1339593 - Long GC pauses in Speedometer

Status: RESOLVED INVALID

(Core :: JavaScript: GC, defect)

Description

[(no longer active)]

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.

Comment 1

[Olli Pettay [:smaug][[e-mail]]]

ProcessExecutableMemory::deallocate taking crazy lots of time.

Comment 2

[Olli Pettay [:smaug][[e-mail]]]

(Don't know what the profile looks before bug 1334933)

Comment 3

[Jan de Mooij [:jandem]]

I doubt it would have been very different before bug 1334933.

Where are we spending time exactly according to your profile?

Comment 4

[Olli Pettay [:smaug][[e-mail]]]

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.

Comment 5

[Jan de Mooij [:jandem]]

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?

Comment 6

[(no longer active)]

(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...

Comment 7

[Jan de Mooij [:jandem]]

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?

Comment 8

[(no longer active)]

(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.

Comment 9

[Naveed Ihsanullah [:naveed]]

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)

Comment 10

[(no longer active)]

FWIW if I see GC pauses that do get measured in speedometer I will file better bugs!