I finally solved a hugely annoying performance bug in one of my Rails apps! To give you an idea of how bad it had gotten, just before the fix an admin page I use 5-10 times every Saturday was averaging 21,114.2 milliseconds per load!!! 😱 Although really, when the times are that large, milliseconds is probably the wrong unit of measurement… That page was taking 0.00024 days to load!!! And the trend was only getting worse!
That same page is now averaging 22.4 milliseconds, about 3 orders of magnitude quicker!
I’d been trying to figure it out for months but I was hampered by a combined lack of:
The tooling problems were particularly frustrating so I owe a massive thank you to Nate Berkopec from Speedshop who not only puts out a ton of great content but was also very patient with my beginner questions about why my flamegraphs weren’t working. I didn’t end up figuring out that problem, but at Nate’s suggestion I switched to rbspy to create a flamegraph and within about an hour I’d figured out the problem that I’d previously spent months off and on trying to solve.
It turns out that every time I fetched a person from the database, my app was generating a random password for them. That process is a bit slow (possibly by design? to avoid timing attacks?? maybe???). Individually, 200 milliseconds to generate a password isn’t a big deal… but on the admin page I load a list of all the people, so every time a new person got added, the page slowed down by another 1/5 of a second 🤦♂️
In the end the fix was super simple, I now only generate the random password (and other default values) if the person isn’t already in the database:
# Before after_initialize :set_default_values # After after_initialize :set_default_values, if: :new_record?
18 more characters to remove a 94,160% slow down! Plus now the user facing pages are down below 30 milliseconds too! 🥳
For future reference, here’s how I tracked down the issue:
sudo --preserve-env rbspy record --pid 86229 --format speedscope --subprocesses
sudo --preserve-env rbspy record --pid `cat tmp/pids/server/pid` --format speedscope --subprocesses]