743687 - huge GC pause times not reflected in max pause or total time

Status: RESOLVED INVALID

(Core :: JavaScript Engine, defect)

Description

[Andrew McCreight [:mccr8]]

2 problems here: 1. why am I getting 12 second slices?  They are causing the browser to hang.  2. Why doesn't it show up in Max Pause or total time? 

GC(T+92569.2) Total Time: 274.4ms, Compartments Collected: 17, Total Compartments: 17, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 51.1ms, Allocated: 104MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Time: 22.1ms (Pause: 22.1, Reason: TOO_MUCH_MALLOC): Mark: 21.4ms, Mark Roots: 11.4ms, Discard Code: 0.5ms
    Slice: 3, Time: 11371.5ms (Pause: 19.9, Reason: INTER_SLICE_GC, Reset: compartment change): Mark: 17.2ms, Mark Roots: 7.1ms, Discard Code: 2.5ms
    Slice: 20, Time: 12808.5ms (Pause: 51.1, Reason: INTER_SLICE_GC): Mark: 5.8ms, Mark Other: 5.7ms, Finalize Start Callback: 0.5ms, Sweep: 44.7ms, Sweep Compartments: 28.2ms, Sweep Object: 2.4ms, Sweep String: 0.3ms, Sweep Script: 0.6ms, Sweep Shape: 4.3ms, Discard Code: 1.5ms, Discard Analysis: 25.0ms, Discard TI: 1.0ms, Sweep Types: 4.8ms, Clear Script Analysis: 1.0ms, Finalize End Callback: 2.5ms, End Callback: 0.5ms
    Totals: Purge: 0.1ms, Mark: 225.3ms, Mark Roots: 18.5ms, Mark Delayed: 0.2ms, Mark Other: 5.7ms, Finalize Start Callback: 0.5ms, Sweep: 44.7ms, Sweep Compartments: 28.2ms, Sweep Object: 2.4ms, Sweep String: 0.3ms, Sweep Script: 0.6ms, Sweep Shape: 4.3ms, Discard Code: 4.5ms, Discard Analysis: 25.0ms, Discard TI: 1.0ms, Sweep Types: 4.8ms, Clear Script Analysis: 1.0ms, Finalize End Callback: 2.5ms, End Callback: 0.5ms

GC(T+92809.2) Total Time: 273.8ms, Compartments Collected: 17, Total Compartments: 17, MMU (20ms): 0%, MMU (50ms): 0%, Max Pause: 51.9ms, Allocated: 108MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Time: 20.3ms (Pause: 20.3, Reason: MAYBEGC): Mark: 19.9ms, Mark Roots: 9.9ms, Discard Code: 0.3ms
    Slice: 3, Time: 11511.7ms (Pause: 19.2, Reason: INTER_SLICE_GC, Reset: compartment change): Mark: 17.0ms, Mark Roots: 6.9ms, Discard Code: 2.0ms
    Slice: 21, Time: 12783.6ms (Pause: 51.9, Reason: INTER_SLICE_GC): Mark: 5.4ms, Mark Other: 5.3ms, Finalize Start Callback: 0.6ms, Sweep: 46.1ms, Sweep Compartments: 29.8ms, Sweep Object: 2.1ms, Sweep String: 0.3ms, Sweep Script: 0.6ms, Sweep Shape: 4.1ms, Discard Code: 1.6ms, Discard Analysis: 26.3ms, Discard TI: 1.1ms, Sweep Types: 5.0ms, Clear Script Analysis: 1.1ms, Finalize End Callback: 2.6ms, End Callback: 0.5ms
    Totals: Mark: 224.1ms, Mark Roots: 16.8ms, Mark Delayed: 0.6ms, Mark Other: 5.3ms, Finalize Start Callback: 0.6ms, Sweep: 46.1ms, Sweep Compartments: 29.8ms, Sweep Object: 2.1ms, Sweep String: 0.3ms, Sweep Script: 0.6ms, Sweep Shape: 4.1ms, Discard Code: 3.9ms, Discard Analysis: 26.3ms, Discard TI: 1.1ms, Sweep Types: 5.0ms, Clear Script Analysis: 1.1ms, Finalize End Callback: 2.6ms, End Callback: 0.5ms

Comment 1

[Andrew McCreight [:mccr8]]

I have incremental GC turned on via pref.  Build from a day or two ago.

Comment 2

[Andrew McCreight [:mccr8]]

Closing Facebook seems to have fixed it.  (I closed some other tabs earlier but they didn't seem to improve the situation.)

Comment 3

[Andrew McCreight [:mccr8]]

Well, it improved it.  I'm still getting a long slice that doesn't show up in total time:

GC(T+93848.2) Total Time: 137.1ms, Compartments Collected: 15, Total Compartments: 15, MMU (20ms): 0%, MMU (50ms): 46%, Max Pause: 26.6ms, Allocated: 70MB, +Chunks: 0, -Chunks: 0
    Slice: 0, Time: 17.6ms (Pause: 17.6, Reason: CC_WAITING): Mark: 15.8ms, Mark Roots: 5.8ms, Discard Code: 1.6ms
    Slice: 11, Time: 1235.3ms (Pause: 26.6, Reason: INTER_SLICE_GC): Mark: 4.9ms, Mark Other: 4.9ms, Finalize Start Callback: 0.3ms, Sweep: 21.2ms, Sweep Compartments: 8.9ms, Sweep Object: 1.0ms, Sweep String: 0.2ms, Sweep Script: 0.6ms, Sweep Shape: 3.3ms, Discard Code: 1.4ms, Discard Analysis: 6.0ms, Discard TI: 1.2ms, Sweep Types: 3.8ms, Clear Script Analysis: 1.0ms, Finalize End Callback: 1.8ms, End Callback: 0.5ms
    Totals: Mark: 113.5ms, Mark Roots: 5.8ms, Mark Delayed: 0.1ms, Mark Other: 4.9ms, Finalize Start Callback: 0.3ms, Sweep: 21.2ms, Sweep Compartments: 8.9ms, Sweep Object: 1.0ms, Sweep String: 0.2ms, Sweep Script: 0.6ms, Sweep Shape: 3.3ms, Discard Code: 3.0ms, Discard Analysis: 6.0ms, Discard TI: 1.2ms, Sweep Types: 3.8ms, Clear Script Analysis: 1.0ms, Finalize End Callback: 1.8ms, End Callback: 0.5ms

Comment 4

[Gregor Wagner [:gwagner]]

I also see 1-2 sec slices with facebook that don't show up in the total time. But the browser doesn't seem to freeze. The stats collection might be buggy. Andrew does the browser actually freeze for 12 sec for you?

Comment 5

[Andrew McCreight [:mccr8]]

When I'm getting the messages as seen in Comment 3, I can't detect any pauses.  But for the behavior in Comment 0, I was actually seeing the browser hang for ten seconds, on almost every GC.

Comment 6

[Bill McCloskey [inactive unless it's an emergency] (:billm)]

I think the main problem here is that the names here are confusing. When it says this:
  Slice: 11, Time: 1235.3ms (Pause: 26.6, Reason: INTER_SLICE_GC):
That means that it's the 11th slice, that it started 1235.3ms after the first slice, and that it took 26.6ms. Instead of "Time", we used to call it "@", but that caused problems for JSON output. Maybe instead we should call it "Started" or something like that. And probably "Pause" should come first, since it's what you really care about.

It's also a bit concerning that a GC is spanning over 12 seconds. We're supposed to get INTER_SLICE_GC slices at least once per 100ms. The entire GC was only 137ms, or about 14 slices. So it should have taken no more than 1.4 seconds.

Andrew, do you have logging enabled in MemChaser? If not, could you enable it? And when you see one of these long ones, could you send it to me? The log includes the start time, reason, and duration of every slice. It might help in understanding the problem.

Comment 7

[Andrew McCreight [:mccr8]]

Ah, yes, I just noticed that.  This may not be a GC problem.  I was getting 12 second hangs.  If there's a non-GC related 12 second hang during a slice, then the slice will take at least 12 seconds.

Comment 8

[Andrew McCreight [:mccr8]]

Whatever the real bug is here, it probably isn't GC related.