Closed
Bug 1339593
Opened 8 years ago
Closed 7 years ago
Long GC pauses in Speedometer
Categories
(Core :: JavaScript: GC, defect)
Core
JavaScript: GC
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.
Comment 1•8 years ago
|
||
ProcessExecutableMemory::deallocate taking crazy lots of time.
Blocks: CVE-2017-5400
Comment 2•8 years ago
|
||
(Don't know what the profile looks before bug 1334933)
Comment 3•8 years ago
|
||
I doubt it would have been very different before bug 1334933.
Where are we spending time exactly according to your profile?
Comment 4•8 years ago
|
||
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•8 years ago
|
||
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?
Reporter | ||
Comment 6•8 years ago
|
||
(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•8 years ago
|
||
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)
Reporter | ||
Comment 8•8 years ago
|
||
(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)
Updated•8 years ago
|
Whiteboard: [qf:p1]
Updated•8 years ago
|
Whiteboard: [qf:p1] → [qf:investigate:p1]
Updated•7 years ago
|
Blocks: TimeToFirstPaint_FB
Updated•7 years ago
|
No longer blocks: TimeToFirstPaint_FB
Updated•7 years ago
|
Status: NEW → RESOLVED
Closed: 7 years ago
Resolution: --- → INVALID
Comment 9•7 years ago
|
||
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)
Reporter | ||
Comment 10•7 years ago
|
||
FWIW if I see GC pauses that do get measured in speedometer I will file better bugs!
Updated•3 years ago
|
Performance Impact: --- → P1
Whiteboard: [qf:investigate:p1]
You need to log in
before you can comment on or make changes to this bug.
Description
•