Last active
January 26, 2025 01:12
-
-
Save mperham/605be96e5b13e0a025973920819f5f08 to your computer and use it in GitHub Desktop.
Huge Ruby performance regression on Linux
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| % bin/sidekiqload | |
| ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [arm64-darwin24] | |
| THREADS: nil, LATENCY: nil, AJ: nil, PROFILE: nil | |
| 2025-01-26T00:15:11.215Z pid=36449 tid=rjd WARN: Setup RSS: 39888 | |
| 2025-01-26T00:15:13.774Z pid=36449 tid=rjd WARN: Created 500000 jobs in 2.556306 sec | |
| 2025-01-26T00:15:13.774Z pid=36449 tid=rjd WARN: Starting load | |
| 2025-01-26T00:15:13.774Z pid=36449 tid=rjd WARN: Simulating 0ms of latency between Sidekiq and redis | |
| 2025-01-26T00:15:18.518Z pid=36449 tid=qy9 class=LoadWorker jid=654f5566f8c5ffca71f294d4 WARN: 2025-01-25 16:15:18 -0800 Done 100000 | |
| 2025-01-26T00:15:23.274Z pid=36449 tid=qy9 class=LoadWorker jid=dafb1897a39cce72cdeb8b48 WARN: 2025-01-25 16:15:23 -0800 Done 200000 | |
| 2025-01-26T00:15:28.021Z pid=36449 tid=rll class=LoadWorker jid=bbe57e2aaba80f29c61b6e87 WARN: 2025-01-25 16:15:28 -0800 Done 300000 | |
| 2025-01-26T00:15:32.763Z pid=36449 tid=rkp class=LoadWorker jid=f1a54c0a65d70fd435e78719 WARN: 2025-01-25 16:15:32 -0800 Done 400000 | |
| 2025-01-26T00:15:37.504Z pid=36449 tid=rkp class=LoadWorker jid=ed7348633b423a7da8134529 WARN: 2025-01-25 16:15:37 -0800 Done 500000 | |
| 2025-01-26T00:15:37.545Z pid=36449 tid=qx5 WARN: Done, 500000 jobs in 23.77083 sec, 21034 jobs/sec | |
| 2025-01-26T00:15:37.551Z pid=36449 tid=qx5 WARN: Ending RSS: 50480 | |
| 2025-01-26T00:15:37.551Z pid=36449 tid=qx5 WARN: Now here's the latency for three jobs | |
| 0.0004730224609375 | |
| 0.0002410411834716797 | |
| 0.00014519691467285156 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| $ bin/sidekiqload | |
| ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [x86_64-linux] | |
| THREADS: nil, LATENCY: nil, AJ: nil, PROFILE: nil | |
| 2025-01-26T00:12:21.884Z pid=95261 tid=20wl WARN: Setup RSS: 40624 | |
| 2025-01-26T00:12:23.099Z pid=95261 tid=20wl WARN: Created 500000 jobs in 1.212474893 sec | |
| 2025-01-26T00:12:23.099Z pid=95261 tid=20wl WARN: Starting load | |
| 2025-01-26T00:12:23.099Z pid=95261 tid=20wl WARN: Simulating 0ms of latency between Sidekiq and redis | |
| 2025-01-26T00:12:46.891Z pid=95261 tid=212t class=LoadWorker jid=c4e151f78a1609db1da5dd8b WARN: 2025-01-25 16:12:46 -0800 Done 100000 | |
| 2025-01-26T00:13:10.754Z pid=95261 tid=211p class=LoadWorker jid=30952445f24862cb39df0884 WARN: 2025-01-25 16:13:10 -0800 Done 200000 | |
| 2025-01-26T00:13:34.573Z pid=95261 tid=211h class=LoadWorker jid=4e1e0e6ca79f224aca4980fc WARN: 2025-01-25 16:13:34 -0800 Done 300000 | |
| 2025-01-26T00:14:00.059Z pid=95261 tid=2139 class=LoadWorker jid=ed0327b7b116c664ec31d8bb WARN: 2025-01-25 16:14:00 -0800 Done 400000 | |
| 2025-01-26T00:14:25.557Z pid=95261 tid=213p class=LoadWorker jid=57523e6fa384d50d25af5af5 WARN: 2025-01-25 16:14:25 -0800 Done 500000 | |
| 2025-01-26T00:14:25.598Z pid=95261 tid=214l WARN: Done, 500000 jobs in 122.499041285 sec, 4081 jobs/sec | |
| 2025-01-26T00:14:25.626Z pid=95261 tid=214l WARN: Ending RSS: 49740 | |
| 2025-01-26T00:14:25.626Z pid=95261 tid=214l WARN: Now here's the latency for three jobs | |
| 0.0011949539184570312 | |
| 0.0010800361633300781 | |
| 0.0010154247283935547 |
This file contains bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| $ THREADS=1 bin/sidekiqload | |
| ruby 3.4.1 (2024-12-25 revision 48d4efcb85) +PRISM [x86_64-linux] | |
| THREADS: 1, LATENCY: nil, AJ: nil, PROFILE: nil | |
| 2025-01-26T00:55:25.545Z pid=108962 tid=2coa WARN: Setup RSS: 40288 | |
| 2025-01-26T00:55:26.946Z pid=108962 tid=2coa WARN: Created 500000 jobs in 1.392991428 sec | |
| 2025-01-26T00:55:26.946Z pid=108962 tid=2coa WARN: Starting load | |
| 2025-01-26T00:55:26.946Z pid=108962 tid=2coa WARN: Simulating 0ms of latency between Sidekiq and redis | |
| 2025-01-26T00:55:32.819Z pid=108962 tid=2cpu class=LoadWorker jid=481d9d8c2b8d58882617edb3 WARN: 2025-01-25 16:55:32 -0800 Done 100000 | |
| 2025-01-26T00:55:36.744Z pid=108962 tid=2cpu class=LoadWorker jid=5e94147e1586a3cbbe5eed40 WARN: 2025-01-25 16:55:36 -0800 Done 200000 | |
| 2025-01-26T00:55:40.122Z pid=108962 tid=2cpu class=LoadWorker jid=133f3457ae70b5e5526442c9 WARN: 2025-01-25 16:55:40 -0800 Done 300000 | |
| 2025-01-26T00:55:44.068Z pid=108962 tid=2cpu class=LoadWorker jid=02a9e03fb12f4698ce224d3a WARN: 2025-01-25 16:55:44 -0800 Done 400000 | |
| 2025-01-26T00:55:48.964Z pid=108962 tid=2cpu class=LoadWorker jid=c690a2a27e2e4fae956a1183 WARN: 2025-01-25 16:55:48 -0800 Done 500000 | |
| 2025-01-26T00:55:49.004Z pid=108962 tid=2cq2 WARN: Done, 500000 jobs in 22.057348362 sec, 22668 jobs/sec | |
| 2025-01-26T00:55:49.031Z pid=108962 tid=2cq2 WARN: Ending RSS: 48624 | |
| 2025-01-26T00:55:49.031Z pid=108962 tid=2cq2 WARN: Now here's the latency for three jobs | |
| 0.0013756752014160156 | |
| 0.0017023086547851562 | |
| 0.0017108917236328125 |
And the network latency seems much higher. Something wrong with Valkey?
Both valkey-redis-compat and redis-server packages seem to exhibit the same slow local network latencies greater than 1ms (lines 16-18). A problem with Ruby? Or a bad linux networking config?
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
Ubuntu 24.04 seems to not scale with IO at all. THREADS=1 is much faster than THREADS=10.