Open Bug 733190 Opened 12 years ago Updated 2 years ago

900ms GC pauses on maps.google.com

Categories

(Core :: JavaScript Engine, defect)

defect

Tracking

()

People

(Reporter: jbalogh, Unassigned)

References

Details

This is on Nightly (Mozilla/5.0 (Macintosh; Intel Mac OS X 10.6; rv:13.0) Gecko/20120305 Firefox/13.0a1)

1. Search for "ups loc: Sausalito, CA" on maps.google.com
2. Scroll in and out, enjoy the beachballing

Here's some GC logs:

GC(T+22.1) TotalTime: 669.7ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: CC_WAITING, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 440.9, mark-roots: 108.3, mark-other: 153.0, sweep: 210.8, sweep-obj: 33.6, sweep-string: 4.5, sweep-script: 0.6, sweep-shape: 17.6, discard-code: 9.7, discard-analysis: 71.0, xpconnect: 30.9, deallocate: 0.1

GC(T+35.8) TotalTime: 628.5ms, Type: compartment, MMU(20ms): 0%, MMU(50ms): 0%, Reason: TOO_MUCH_MALLOC, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 246.7, mark-roots: 112.0, mark-other: 101.8, sweep: 269.0, sweep-obj: 76.3, sweep-string: 14.0, sweep-script: 0.1, sweep-shape: 11.0, discard-code: 1.2, discard-analysis: 1.1, xpconnect: 67.9, deallocate: 0.0

GC(T+42.9) TotalTime: 1017.9ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: POST_COMPARTMENT, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 549.5, mark-roots: 135.5, mark-other: 200.6, sweep: 364.4, sweep-obj: 115.1, sweep-string: 40.5, sweep-script: 0.8, sweep-shape: 28.7, discard-code: 20.6, discard-analysis: 41.4, xpconnect: 57.9, deallocate: 0.1

GC(T+47.8) TotalTime: 893.7ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: PAGE_HIDE, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 561.0, mark-roots: 138.8, mark-other: 206.4, sweep: 185.2, sweep-obj: 39.2, sweep-string: 2.7, sweep-script: 0.7, sweep-shape: 16.9, discard-code: 8.1, discard-analysis: 34.2, xpconnect: 37.3, deallocate: 0.1

GC(T+60.4) TotalTime: 1134.1ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: PAGE_HIDE, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 630.4, mark-roots: 158.0, mark-other: 239.9, sweep: 366.3, sweep-obj: 132.4, sweep-string: 34.5, sweep-script: 0.8, sweep-shape: 26.3, discard-code: 3.2, discard-analysis: 14.2, xpconnect: 77.7, deallocate: 0.1

GC(T+65.6) TotalTime: 986.8ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: PAGE_HIDE, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 643.7, mark-roots: 171.8, mark-other: 234.4, sweep: 236.8, sweep-obj: 30.0, sweep-string: 3.2, sweep-script: 0.7, sweep-shape: 19.3, discard-code: 5.1, discard-analysis: 69.8, xpconnect: 43.2, deallocate: 0.1

CC(T+67.1) duration: 1132ms, suspected: 15884, visited: 164024 RCed and 30115 GCed, collected: 41327 RCed and 26488 GCed (67815 waiting for GC)
ForgetSkippable 21 times before CC, min: 0 ms, max: 531 ms, avg: 94 ms, total: 1991 ms, removed: 373069

GC(T+72.0) TotalTime: 932.9ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: CC_WAITING, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 617.6, mark-roots: 150.8, mark-other: 225.8, sweep: 241.0, sweep-obj: 43.0, sweep-string: 5.9, sweep-script: 0.7, sweep-shape: 19.2, discard-code: 4.7, discard-analysis: 38.7, xpconnect: 43.5, deallocate: 0.1

CC(T+75.0) duration: 903ms, suspected: 10057, visited: 143520 RCed and 18107 GCed, collected: 24287 RCed and 14482 GCed (38769 waiting for GC)
ForgetSkippable 9 times before CC, min: 3 ms, max: 5 ms, avg: 4 ms, total: 37 ms, removed: 5674

GC(T+79.9) TotalTime: 841.4ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: CC_WAITING, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 611.0, mark-roots: 146.0, mark-other: 228.2, sweep: 198.3, sweep-obj: 38.9, sweep-string: 6.4, sweep-script: 0.7, sweep-shape: 19.3, discard-code: 2.6, discard-analysis: 27.3, xpconnect: 48.6, deallocate: 0.1

CC(T+82.8) duration: 906ms, suspected: 5837, visited: 146492 RCed and 25655 GCed, collected: 29985 RCed and 22003 GCed (51988 waiting for GC)
ForgetSkippable 9 times before CC, min: 1 ms, max: 3 ms, avg: 2 ms, total: 21 ms, removed: 5974

GC(T+87.7) TotalTime: 841.8ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: CC_WAITING, NonIncrementalReason: incremental permanently disabled, +chunks: 0, -chunks: 0
mark: 600.5, mark-roots: 143.8, mark-other: 227.0, sweep: 197.8, sweep-obj: 40.0, sweep-string: 6.3, sweep-script: 0.7, sweep-shape: 19.2, discard-code: 2.3, discard-analysis: 33.7, xpconnect: 42.4, deallocate: 0.1
I'm not entirely sure this is our problem, but it's worth investigating. I used the regular version of Google maps, and I scrolled in and out with the scroll wheel a lot. My GCs started to get a little slower. After a little while, I got a slow script dialog. I let it run for a few more times and then stopped it.

At the end, the JS heap for the Google maps compartment was ~500MB. A typical GC looked like this:

GC(T+365137.3) TotalTime: 1072.6ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: CC_WAITING, +chunks: 0, -chunks: 0
mark: 921.9, mark-roots: 7.5, mark-other: 38.6, sweep: 147.3, sweep-obj: 35.3, sweep-string: 2.6, sweep-script: 1.0, sweep-shape: 53.2, discard-code: 4.4, discard-analysis: 17.3, xpconnect: 3.1, deallocate: 0.0

I don't know if this is a reasonable GC time for such a large heap. It seems high, but the heap is pretty big.

The really bad part was that when I closed the page I got this:

GC(T+365156.6) TotalTime: 1084.2ms, Type: global, MMU(20ms): 0%, MMU(50ms): 0%, Reason: PAGE_HIDE, +chunks: 0, -chunks: 0
mark: 941.9, mark-roots: 7.3, mark-other: 863.4, sweep: 140.7, sweep-obj: 31.9, sweep-string: 2.3, sweep-script: 0.9, sweep-shape: 53.0, discard-code: 3.2, discard-analysis: 16.9, xpconnect: 2.4, deallocate: 0.0

CC(T+365161.5) duration: 4416ms, suspected: 1420, visited: 64105 RCed and 3051461 GCed, collected: 9131 RCed and 3003151 GCed (3012282 waiting for GC)
ForgetSkippable 7 times before CC, min: 0 ms, max: 31 ms, avg: 8 ms, total: 60 ms, removed: 3937
Wow, 3 million JS nodes in the CC graph!  I'm not sure how the CC can possibly deal with that many nodes.
The same here. Closing the browser after a few minutes of google maps didn't work. I killed it after about 30 sec.
I tried doing the same thing in Chrome. Performance and memory usage are terrible there as well. However, their UI of course doesn't lock up as ours does.

I also tried this out with incremental GC enabled. It actually works reasonably well, although the last slice is ~200ms because of sweeping. However, this should be fixed by bug 729760.

It seems like the main thing to focus on here is the massive CC when the tab is closed. Is that something that happens on every page with a big GC heap, or only on some?
It is only going to happen because the JS is apparently being held alive only by DOM.
Is there anything more to do with this bug right now?
(In reply to David Mandelin from comment #7)
> Is there anything more to do with this bug right now?

No.
Assignee: general → nobody
Severity: normal → S3
You need to log in before you can comment on or make changes to this bug.