Hi Markus, I'm confused by the build IDs in these profiles, it doesn't match what you've described. Could you check my work?
(In reply to Markus Stange [:mstange] from comment #0)
There also seem to have been two recent regressions in terms of GC times on the testcase, so much so that it's now impacting the animation frame rate. GC behavior went from almost no GC to quite frequent GC, with a step in between, over the last two or three weeks.
Almost no GC: https://perfht.ml/2WQzR9p
I agree, I see no GC Major/Slice markers, plenty of GC minor slices but all are OUT_OF_NURSERY with a 1MB nursery. This is pretty much generational GC acting as designed.
There were 5409 nursery collections taking 2% of all the elapsed time.
Mean: 0.07ms ±0.01
90th percentile: 0.09ms
Total: 395ms / 19,916ms (2.0%)
Around one GC per second: https://perfht.ml/2WX2EJI
4040 pauses for Nursery collections:
Mean: 0.09ms ±0.02
90th percentile: 0.11ms
Total: 366ms / 19,636ms (1.9%)
So about the same for nursery behaviour.
204 pauses for Major slices:
Mean: 3.75ms ±2.53
90th percentile: 5.04ms
Total: 765ms / 19,636ms (3.9%)
But now there are major GCs also, still they're fairly quick and maybe only the top 10% may result in a dropped frame, but that probably depends what else is happening (looking at this data only).
These 204 slices belong to several major GCs, each major GC seems to have between 5-10 slices and is started by ALLOC_TRIGGER, each GC seems to free around half the engine's memory. The memory directly used by the engine is fairly stable, cycling between ~50MB and 112MB. The increase in total memory usage over time is either elsewhere or indirect and not freed by these zonal GCs.
Very frequent GC: https://perfht.ml/2WNbjy9
NOTE, this version is OLDER than the previous one.
298 pauses for Nursery collections:
Mean: 7.62ms ±2.92
90th percentile: 10.2ms
Total: 2,270ms / 19,998ms (11%)
116 pauses for Major slices:
Mean: 13.5ms ±16.1
90th percentile: 38.0ms
Total: 1,570ms / 19,998ms (7.9%)
This is spending almost 20% of its time in GC, with a large increase to the time spent collecting the nursery. Looking further this is using a much larger nursery size (16MB) with more data being tenured (>25%). A reasonable guess is that something is being pretenured that is then causing more objects to be tenured, and is creating more work for the GC.
This is why I thought of Bug 1497873, which did land in this time except that this profile is from an earlier build and the previous one is from a later build. So if anything the above bug improved this (which is likely, since one thing it did was avoid any pretenuring when the nursery is small).
Marcus, am I understanding this correctly, that this wasn't a regression but an improvement? Or what am I missing.
(The statistics in this comment are from an experimental patch I have for the profiler.)