On Mac nightly, I was getting noticeable rendering pauses every 5-10 seconds that significantly detracted from the whole experience. The audio continued to play, at least, but I suspect GC/CC was at fault here. Haven't done any profiling, though.

The are unconfirmed reports that the demo runs really smoothly in Aurora. I would love for someone to confirm this.

Josh: I am playing this demo in the latest nightly using Mozilla/5.0 (Macintosh; Intel Mac OS X 10.7; rv:10.0a1) Gecko/20111024 Firefox/10.0a1 and I get some pauses too, but it was hard for me to tell if that was expected or not. I tested Aurora as well on the same machine and while I got some pauses, I don't think it was as noticeable on Aurora as on nightly. Using 10.7.2 machine. I tried the demo in Chrome but it doesn't play at all there and I got a message about Safari and WebGL. I will try on my 10.6 laptop as well some of the machines in the lab to compare.

Hmm, using a local opt build with a blank profile, I got a really smooth experience. I might try downloading a shark nightly and profiling on my regular profile.

Mozilla/5.0 (X11; Linux x86_64; rv:10.0a1) Gecko/20111027 Firefox/10.0a1 Seems to be the same for Ubuntu 11.10. On Nightly some slight pauses when moving the mouse, while on Aurora the experience seems to be smoother.

Tested on today nightly and aurora I get some pauses maybe It feels a little more on nightly than aurora but almost the same pauses tested with a new profile. With my normal nightly profile theres other history I have many tabs but none active except for the lights experience and at some point the image is just lost but keeping with the bug I can feel that the pauses are longer. Mozilla/5.0 (X11; Linux x86_64; rv:10.0a1) Gecko/20111028 Firefox/10.0a1

The janks correspond to (global) GCs. I have javascript.options.mem.log set to true and left the Error Console open to test. On my computer, each GCs is reported as taking 100-120ms, but somehow the janks seem worse than that. I tested using Firefox Nightly on a 2011 MacBook Pro running Mac OS X 10.6.

Thanks for looking at this, Jesse. This looks like it could be an instance of the GC scheduling regressions bz noticed, in bug 707162. When I ran this, the pauses corresponded exactly with GCs, as Jesse noted. Furthermore, the GCs were almost precisely every 4 seconds, and were always "Reason: API". NS_GC_DELAY is 4 seconds, so this suggests that a new GC is being scheduled at the end of every GC. This would be consistent with Igor's theory in bug 707162 comment 3.

I downloaded Beta 9, and it feels a lot smoother. The GCs seem maybe slightly more frequent, but they are shorter. There are noticeable pauses, but they are like a slight judder in the background, not like the whole thing comes to a halt. So maybe it isn't a scheduling thing. The GC log looks like this: GC mode: full, timestamp: 1323109086733743, duration: 41 ms. GC mode: full, timestamp: 1323109090351669, duration: 43 ms. CC timestamp: 1323109091749118, collected: 0 (0 waiting for GC), suspected: 194, duration: 7 ms. GC mode: full, timestamp: 1323109093922603, duration: 42 ms. GC mode: full, timestamp: 1323109097652421, duration: 41 ms.

On nightly this is what it looks like: GC(T+62.1) Type:Glob, Total:121.3, Wait:0.2, Mark:92.5, Sweep:28.1, FinObj:5.9, FinStr:0.1, FinScr:0.5, FinShp:3.2, DisCod:4.4, DisAnl:9.7, XPCnct:1.6, Destry:0.0, End:1.9, +Chu:0, -Chu:0, Reason: API GC(T+66.3) Type:Glob, Total:151.9, Wait:0.1, Mark:119.8, Sweep:31.6, FinObj:7.8, FinStr:0.1, FinScr:0.6, FinShp:3.6, DisCod:4.3, DisAnl:10.3, XPCnct:2.0, Destry:0.0, End:2.2, +Chu:0, -Chu:1, Reason: API CC(T+67.2) collected: 24 (24 waiting for GC), suspected: 849, duration: 17 ms. GC(T+70.4) Type:Glob, Total:134.3, Wait:0.8, Mark:101.7, Sweep:31.5, FinObj:6.2, FinStr:0.1, FinScr:0.5, FinShp:2.9, DisCod:4.5, DisAnl:13.6, XPCnct:1.2, Destry:0.0, End:1.4, +Chu:1, -Chu:8, Reason: API GC(T+74.6) Type:Glob, Total:118.4, Wait:0.1, Mark:92.8, Sweep:25.3, FinObj:6.4, FinStr:0.1, FinScr:0.5, FinShp:2.6, DisCod:3.5, DisAnl:8.4, XPCnct:1.2, Destry:0.0, End:1.3, +Chu:0, -Chu:0, Reason: API CC(T+75.5) collected: 87 (87 waiting for GC), suspected: 314, duration: 11 ms. GC(T+78.7) Type:Glob, Total:117.0, Wait:0.1, Mark:91.7, Sweep:25.0, FinObj:6.3, FinStr:0.1, FinScr:0.5, FinShp:2.6, DisCod:3.6, DisAnl:8.2, XPCnct:1.1, Destry:0.0, End:1.2, +Chu:1, -Chu:0, Reason: API GC(T+82.8) Type:Glob, Total:117.3, Wait:0.1, Mark:91.3, Sweep:25.7, FinObj:6.5, FinStr:0.1, FinScr:0.5, FinShp:2.7, DisCod:3.5, DisAnl:8.5, XPCnct:1.5, Destry:0.0, End:1.6, +Chu:0, -Chu:0, Reason: API As you can see, in addition to firing off every 4 seconds like clockwork, the GCs are almost about 3 times as long. That seems like a more likely cause of increased jank than scheduling. Also of note, when I run with smaug's patch from bug 705582, the CC basically never runs.

Aurora 10: GC mode: full, timestamp: 1323113263141907, duration: 230 ms. GC mode: full, timestamp: 1323113267357536, duration: 200 ms. CC timestamp: 1323113268189188, collected: 16 (16 waiting for GC), suspected: 232, duration: 13 ms. GC mode: full, timestamp: 1323113271581462, duration: 203 ms. GC mode: full, timestamp: 1323113275820859, duration: 220 ms. CC timestamp: 1323113276603366, collected: 0 (0 waiting for GC), suspected: 254, duration: 13 ms. No idea why it is longer here. I was unplugged so maybe the CPU was running at a lower rate.

Using my patch in bug 706227, I determined that all of the GCs that fire off during this demo in nightly are triggered by the presence of unused chunks. In this particular build, they were taking 98ms. When I changed the threshold of unused chunks to 6 from 0, the global unused-chunk GCs became compartmental Maybe GCs that were only around 82ms, and were happening slightly less often: GC(T+42.4) Type:Comp, Total:81.4, Wait:0.4, Mark:64.1, Sweep:16.4, FinObj:6.4, FinStr:0.0, FinScr:0.1, FinShp:0.4, DisCod:2.5, DisAnl:5.7, XPCnct:0.8, Destry:0.0, End:0.8, +Chu:24, -Chu:0, Reason:Maybe GC(T+48.8) Type:Comp, Total:80.5, Wait:0.1, Mark:63.7, Sweep:16.4, FinObj:6.2, FinStr:0.0, FinScr:0.1, FinShp:0.4, DisCod:2.9, DisAnl:5.5, XPCnct:0.7, Destry:0.0, End:0.7, +Chu:0, -Chu:0, Reason:Maybe GC(T+55.6) Type:Comp, Total:82.3, Wait:0.1, Mark:64.2, Sweep:17.7, FinObj:6.2, FinStr:0.0, FinScr:0.1, FinShp:0.4, DisCod:3.1, DisAnl:6.5, XPCnct:0.8, Destry:0.0, End:0.8, +Chu:0, -Chu:0, Reason:Maybe There were still a number of unused-chunk GCs at the start, but after 3 or 4 of those it settled into compartmental GCs. This is an improvement of about 25% over the base performance in Nightly, but is still twice as slow as in release. Though I'm using a debug build, which is probably also a factor.

I pushed the combination of my improved GC explanation patch and my single line expired-chunks tweak to try: https://tbpl.mozilla.org/?tree=Try&rev=155baf7c369b It may be crashy. The GC explanation patch is pretty flaky. But I was able to at least run this demo.

In an opt build with the patch applied, from comment 12, the GC times with this demo are 42ms, eg the same as beta.

(In reply to Andrew McCreight [:mccr8] from comment #14) > In an opt build with the patch applied, from comment 12, the GC times with > this demo are 42ms, eg the same as beta. Interesting. Even if we trigger GCs in MaybeGC and we perform more GCs, individual pause times increase by 100%?

(In reply to Gregor Wagner [:gwagner] from comment #15) > Interesting. Even if we trigger GCs in MaybeGC and we perform more GCs, > individual pause times increase by 100%? On Nightly, a full GC is triggered every 4 seconds. With my patch, a compartmental GC is triggered every 5-7 seconds. So there are less GCs with my patch.

We should confirm that this has actually been fixed by bug 713916.

It's still janky for me, both in my main profile (where its GCs are ~70ms) and in a fresh profile (~30ms). Actually, I'm surprised by how much jank the 30ms GCs cause.

Well, 30ms sounds okay to me. That at least means there's no regression from 9, which is my immediate concern. Improvements beyond that will have to wait for incremental GC. Those are compartmental GCs I assume?

Mostly global GCs, in both profiles.

Cameron Dawson looked into the current state of this demo across all versions: https://bugzilla.mozilla.org/show_bug.cgi?id=711900#c21 Looks like GC times might be slightly worse after 9, but only slightly. In some sense this is fixed, as the initial report was mostly about a regression, but on the other hand it is still janky so I guess I'll leave it open for now, and have it depend on incremental GC.

I tried this again, now that bug 706227 has landed. With a few tabs open, GCs seem to be every 4-8 seconds. The GCs pretty much all look like this: GC(T+126.5) Type:Glob, Total:115.9, Wait:0.1, Mark:81.8, Sweep:33.5, FinObj:5.5, FinStr:0.1, FinScr:0.5, FinShp:2.8, DisCod:4.0, DisAnl:12.4, XPCnct:1.3, Destry:0.1, End:1.6, +Chu:0, -Chu:0, Reason:TOO_MUCH_MALLOC Note they aren't compartmental. With nothing else open, the GCs look like this: GC(T+96.0) Type:Glob, Total:50.0, Wait:0.1, Mark:37.0, Sweep:12.8, FinObj:3.9, FinStr:0.0, FinScr:0.1, FinShp:1.0, DisCod:2.0, DisAnl:3.9, XPCnct:0.7, Destry:0.0, End:0.8, +Chu:2, -Chu:2, Reason:TOO_MUCH_MALLOC They are still global, but shorter because nothing else is there. It still felt pretty janky, though. On Larch (incremental GC) it looks like this: GC(T+141.9) TotalTime: 61.1ms, Type: global, MMU(20ms): 13%, MMU(50ms): 51%, MaxPause: 17.2, +chunks: 2, -chunks: 0 Slice 0 @ 10.6ms (Pause: 10.6, Reason: MAYBEGC): mark: 8.6, mark-roots: 1.6 Slice 6 @ 217.9ms (Pause: 17.2, Reason: REFRESH_FRAME): mark: 1.5, mark-delayed: 0.0, mark-other: 1.1, sweep: 15.1, sweep-obj: 3.9, sweep-string: 0.0, sweep-script: 0.1, sweep-shape: 0.8, discard-code: 1.2, discard-analysis: 6.9, xpconnect: 0.8, deallocate: 0.0 Totals: mark: 43.3, mark-roots: 1.6, mark-delayed: 0.1, mark-other: 1.1, sweep: 15.1, sweep-obj: 3.9, sweep-string: 0.0, sweep-script: 0.1, sweep-shape: 0.8, discard-code: 1.2, discard-analysis: 6.9, xpconnect: 0.8, deallocate: 0.0 There may have been some slight pauses, but they were barely noticeable.

The last time I tried this site with larch, there were still a lot of problems with compilation. That is, GCs are fast, but they force methodjit recompilation, which is slow. I'll try it again after I rebase over bug 706914, which may help with the compilation pauses.

Bug 679026 might help with this as it should turn most if not all of those GCs into compartmental ones. At least it does so with all GCs in V8, leaving not a single global one. IIUC, compartmental GCs don't force recompilations, right? I'll post a refreshed patch to 679026 in a bit and request a new try run for it (don't yet have access to that myself).

(In reply to Till Schneidereit from comment #24) > IIUC, compartmental GCs don't force recompilations, right? That's incorrect, compartmental GCs do force recompilation.

(In reply to Bill McCloskey (:billm) from comment #25) > That's incorrect, compartmental GCs do force recompilation. Oh, that's too bad. Then it will become much less interesting once incremental GC lands, I guess.

Page isn't reachable any more.

I went through that demo over and over again when looking into the performance, and the song is now drilled into my brain.

Found it again. http://lights.helloenjoy.com/. Andrew enjoy! :) Nice song.

Thanks for looking, but at this point, there's not much use it keeping this bug open.