I recently looked into a slight performance regression after landing a string-related patch. I’ve never been sure what the best process is to look into these things, so I thought I’d at least write down what I came up this time in case it’s useful to future-me or some helpful reader can tell me I’m being an idiot and there’s a Much Better Way. (Other than padenot, who has already implemented a Much Better Way for part of this. I’ve only just begun to try using it, and will perhaps do more in a later post.)
Note that the formatting in the post is really awful, and is motivating me to get around to migrating my blog to someplace I can control even though it probably means I’ll lose my Planet Mozilla syndication in the process (because I’m not sure anyone maintains it anymore?) Bye bye in advance! I plan to cross-post for a while, but given that I had 0 posts for 3 years, that has little meaning. If you can, you’re probably better off reading this post via a feed reader or something rather than going to the blog.m.o site.
The basic issue: I landed a patch, I got an alert saying I had improved 3 subtests and regressed another 3. I was curious, so I dug into the first (and largest) regression.
I first opened the “before” and “after” links in separate tabs, and added “after – ” and “before – ” prefixes to their names so I could tell them apart. (Note: my actual process was way clumsier than I’ll be describing, involving me repeatedly confusing myself over which profile was which, until I finally did what I say here.)
That done, I went to the marker chart and flipped back and forth between them to sort of eyeball-animate the change from before to after. That was confusing because the “after” seemed slightly faster. The marker chart is clogged with lots of “CSS transition” markers, so I filtered those out with -name:CSS
in the filter field. (Actually, I flailed around for a while to figure out what the syntax of that field was first, and ended up creating a PR to add my findings to the documentation.)
That showed me that the profile contains 10 iterations of sp3. I tried looking at just one in each profile, but that was pointless, since each iteration goes through all of the sp3 tests and my regressing test gets lost in the noise. Instead, I used the devtools console and grabbed out the markers I wanted by name:
filteredMarkers.filter(m => m.data.name === "Charts-chartjs.Draw scatter-async")
Later on, I instead filtered by name in the UI:
-name:CSS,Draw scatter-async
which later turned into Draw scatter-async,-name:-end,-name:-start
to only look at the interval markers rather than the older `-start` and `-end` markers that now just serve as noise.
But anyway, back to the console, I looked at the total duration of just that subtest:
filteredMarkers.filter(m => m.data.name === "Charts-chartjs.Draw scatter-async").map(m => m.end - m.start).reduce((acc, v) => acc + v, 0) / 10
That showed the “after” being 8.5% slower, which is close enough to 5% that I felt like I was looking at the right thing.
Staring at the data (by running the above without the reduce
), I noticed that all of the “after” runs were about 350µs except for one that took 657µs, and did the math to see that the single long run was responsible for all of the difference (plus a tiny bit more). I did some further investigation (which you can see in the bug) to diagnose this further, but that’s not relevant to this post which is really about profiler gymnastics.
I guess for sake of completeness, “doing the math” was something like:
- Run the expression to extract my durations from
filteredMarkers
- Left-click the result to select it, right-click and choose “Store as Global Variable”.
- Drop out the outlier (element 9) and recompute the mean:
tmp = [...temp0]; tmp.splice(9); tmp.reduce((s,v) => s + v, 0) / tmp.length
And just because it seems I can’t bear to submit this post, here’s my first experience with Fouineur:
- Install the add-on
- With the profile open, click on the add-on puzzle piece to dropdown the menu that is there to hide useful stuff from me
- Click on Fouineur to open up its edit window
- Minimize the edit window because it prevents me from interacting with the profile
- Filter down to just the markers I want (I did this in the UI because it seemed like it might be harder to exclude the “-start” and “-end” nuisance markers with Fouineur, now that I had learned how the profiler’s filter syntax works
- Struggle with the Fouineur editor because it prevents adding a blank line, which is problematic when the syntax requires a blank line between match expressions and actions. Eventually discovered that shift-Enter forces the issue.
- Used the match
UserTiming
and the actionplot(UserTiming)
to get a cool little graph! Yay!
But I was already done with the analysis, I just felt guilty about not trying out Fouineur when I knew it was meant for pretty much what I was doing. Now I know enough to try it for real next time. It looks pretty awesome so far.