Closed Bug 1339593 Opened 8 years ago Closed 7 years ago

Long GC pauses in Speedometer

Categories

(Core :: JavaScript: GC, defect)

defect
Not set
normal

Tracking

()

RESOLVED INVALID
Performance Impact high

People

(Reporter: ehsan.akhgari, Unassigned)

References

(Blocks 2 open bugs)

Details

See this profile for example where we have a 1.3 second GC pause: <https://perfht.ml/2lgUk77> It seems that we should have a mechanism that would prevent us from spending this much time in GC.
ProcessExecutableMemory::deallocate taking crazy lots of time.
(Don't know what the profile looks before bug 1334933)
I doubt it would have been very different before bug 1334933. Where are we spending time exactly according to your profile?
Under sweepPhase. I can't seem to give a proper link to the interesting place, but if you alt+click (at least on linux), it should open the tree. Also other parts of GC is taking time, but that ProcessExecutableMemory::deallocate is surprisingly slow.
Inverting the call stack shows it's 668 ms under mmap. Pretty weird. Ehsan, this is on OS X right? Can you reproduce this reliably?
(In reply to Jan de Mooij [:jandem] from comment #5) > Ehsan, this is on OS X right? Yes. >Can you reproduce this reliably? Reproducing is super easy, just give it a shot! Here is another profile I just captured <https://perfht.ml/2lhtYSx>. The tricky part is to capture a profile at the right time. What I do is I start Speedometer and then use Ctrl+Shift+1 to restart the profiler, wait a bit, Ctrl+Shift+2 to capture a profile, and repeat a bunch of times. For example right now I repeated this 3 times and found ProcessExecutableMemory::deallocate() in one of the profiles. BTW I've seen similar mmap calls take a long time in other profiles quite a bit. Not sure why you find that surprising...
I haven't been able to reproduce this yet. I see mprotect show up quite a bit in Instruments, but mmap is at 0.1% or so. Around which test (it's in the bottom) do you start/stop the profiler? Are you on OS X 10.12?
Flags: needinfo?(ehsan)
(In reply to Jan de Mooij [:jandem] from comment #7) > I haven't been able to reproduce this yet. I see mprotect show up quite a > bit in Instruments, but mmap is at 0.1% or so. Hmm, did you try the approach I use to profile? I guess with Instruments you can also grab a full profile of the entire test run. Does it show up in that view? > Around which test (it's in the bottom) do you start/stop the profiler? As far as I can tell it doesn't happen at a specific point, I get this pretty much randomly. It may even happen several times during the test, but the profiler buffer size I use doesn't capture a super long run so I can't be 100% sure. > Are you on OS X 10.12? Yes.
Flags: needinfo?(ehsan)
Whiteboard: [qf:p1]
Whiteboard: [qf:p1] → [qf:investigate:p1]
No longer blocks: TimeToFirstPaint_FB
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INVALID
Speedometer does not measure all the time. It starts and stops timers each iterations. GCs between iterations would not be impacting speedometer so this bug as written is inaccurate and not applicable. (as per ehsan)
FWIW if I see GC pauses that do get measured in speedometer I will file better bugs!
Performance Impact: --- → P1
Whiteboard: [qf:investigate:p1]
You need to log in before you can comment on or make changes to this bug.