Closed Bug 702495 Opened 13 years ago Closed 8 months ago

Find web sites with long GC or CC pauses

Categories

(Core :: JavaScript Engine, defect)

x86_64
Linux
defect

Tracking

()

RESOLVED INCOMPLETE

People

(Reporter: billm, Unassigned)

References

(Depends on 1 open bug)

Details

(Whiteboard: [qa+])

Attachments

(2 files, 1 obsolete file)

The goal of this bug is to find web sites where we have really long pauses for garbage collection or cycle collection. Then we can use these sites as tests for incremental garbage collection.

Here's the basic procedure:

1. Set the javascript.options.mem.log option to true in about:config.
2. Visit a web site.
3. Open the error console and hit Clear and then Messages.
4. Messages that start with "CC(T+...)" and "GC(T+...)" should accumulate.
5. The time for a GC is listed under "Total". It is in milliseconds. The time for a CC is given as "duration".

There isn't a clear threshold for what is too long. Mostly, we want to find sites where the user experience is negatively affected by long GCs or CCs. Usually it's easy to determine this. The site will seem to pause for moment, and immediately after there will be a new CC or GC entry appearing in the error console.

Here are some sites that we know we do poorly on:

http://ro.me: A Chrome experiment with lots of video and ~500ms GCs. Also, I sometimes get a 10 second CC when I close the site.

Flight of the Navigator (http://videos.mozilla.org/serv/mozhacks/flight-of-the-navigator/): GCs are shorter, but they cause noticeable pauses

Mozilla Graph Server (graphs.mozilla.org): This site takes a lot of memory, so GCs take a long time. The site is not very interactive, so you usually don't notice unless you're doing something in another tab.

JS realtime raytracer (http://29a.ch/2010/6/2/realtime-raytracing-in-javascript): This site has long GCs that really mess up the animation.

A good start would be to look at more Chrome experiments, and also look for sites with lots of animation. It might also be good to search bugzilla for reproducible cases.
In emails from dmandelin, here are two more:

Google Reader: Blizzard says he confirmed that long pauses on his Mac are causes by CC or GC. This seems to be workload-dependent since I can't reproduce it easily.

This demo from Damon:
http://alteredqualia.com/three/examples/webgl_terrain_dynamic.html

The latter runs at ~1fps on my laptop, so I wasn't able to check whether GC or CC are at fault.
(In reply to Bill McCloskey (:billm) from comment #1)
> This demo from Damon:
> http://alteredqualia.com/three/examples/webgl_terrain_dynamic.html

I tested this site from work, and there are noticeable pauses caused by garbage collection. In a fresh browser, the GC pauses are ~80ms and the CC pauses are about 10ms.

I should emphasize that GC and CC times will get worse the more tabs you have open. I think this bug should focus on single pages that lead to bad pauses (i.e., with no other tabs loaded). Otherwise it's much harder to reproduce the problems.
Summary: Find web sites with long GC or CC times → Find web sites with long GC or CC pauses
See also bug 702813, which has a synthetic testcase which causes long CC pauses.
http://lights.elliegoulding.com/

I get around 40ms with FF 8 but 75ms with todays nightly.
http://sørver.no/Projects/Origami3D/examples/mode7.html

The GC duration is something like 236ms in FF8. This causes noticable delays in the animation.
WebGL seems to have large enough memory throughput to cause frequent GC pauses. On MacBook Pro / Sandybridge GPU / Aurora FF 10:

WebGLASS http://possan.se/junk/webglass/index.html frequent 28ms or so pauses a couple of times a second.

Rome interactive music video: http://ro.me 300-2000ms pauses while loading, lots of pauses while running of 0.5-4s, including one GC Timestamp which lists a duration of 78019ms!
The WebGL video: http://lights.elliegoulding.com/ causes GC pauses of 40-60ms every couple of seconds.
Adding [qa+] and in-litmus? to this bug. QA should really keep track of the test sites found in this bug and put them into a regression test suite.
Flags: in-litmus?
Whiteboard: [qa+]
Depends on: 689940
I get several ~80ms pauses on Google Maps.
Let's focus on repeatable test cases here. That is, ones where it's possible to visit the same site with a clean profile and no other tabs open and get a long GC pause, every time.
An email reply to my blog post:

>The games I made at http://gamesalad.com/arcade tended to have garbage collection >pauses. Try air supply for example.
ammo.js is a good one:

http://syntensity.com/static/ammo.html

I just tried it in Larch and it's much better than Nightly, but there is still a bit of pausing. Not sure if it's the 20ms min vs. 60fps, or some CC getting thrown in there.
Running the PDF.JS[1] test suite results in quite some GC pauses, that sometimes take longer then 200ms.

[1]: https://github.com/mozilla/pdf.js
From blog comment:

>I don’t know if it’s GC related but http://www.pirateslovedaisies.com seems to 
>perform worse in Firefox 8 and 9 as compared to Firefox 7. It has lots of small 
>pauses in 8 and 9.
(In reply to gundersen@gmail.com from comment #5)
> http://sørver.no/Projects/Origami3D/examples/mode7.html
> 
> The GC duration is something like 236ms in FF8. This causes noticable delays
> in the animation.

We only perform global GCs here because of bug 679026
When you load IRCcloud, the whole browser hangs for 4-10 seconds.  When I measured GC times, I saw there was a 1.6 second compartmental GC, and a few other 600ms GCs in there, so it might be something to look at.
Depends on: 703455
Depends on: 706975
Depends on: 694883
leave this running for a minute or so and the gc times rises to 30ms every few seconds:

http://airtightinteractive.com/demos/js/snowbox/

(Aurora / FF10 / OSX)
(In reply to Julian Adams from comment #17)
> leave this running for a minute or so and the gc times rises to 30ms every
> few seconds:
> 
> http://airtightinteractive.com/demos/js/snowbox/
> 
> (Aurora / FF10 / OSX)

On Nightly, with my patch from bug 694883 applied, the GC pause time is only degrading slightly, from about 14.5ms to 16.5ms, after running it for 5 or so minutes.  The GC's are all global GCs, triggered by "many waiting for GC", which I think means that it is triggered because the CC freed about 1200 things each time.

CC(T+609.9) collected: 1294 (1294 waiting for GC), suspected: 1361, duration: 8 ms.
GC(T+613.9) Type:Glob, Total:16.9, Wait:0.1, Mark:12.7, Sweep:4.0, FinObj:0.3, FinStr:0.0, FinScr:0.1, FinShp:0.2, DisCod:0.9, DisAnl:1.7, XPCnct:0.5, Destry:0.0, End:0.5, +Chu:0, -Chu:0, Reason:many waiting for GC

I don't know if difference is because I'm on nightly or because of my patch.
Depends on: 701657
Attached file Peptest for ammo.js (obsolete) —
I wrote a couple peptests (https://wiki.mozilla.org/Auto-tools/Projects/peptest) to get some numbers on unresponsiveness for some of these sites.  They're just very simple tests that open a page and wait for a short while; I attached one (for ammo.js).

Here are the results with today's nightly on Ubuntu 11.10 on a MacBook Pro.  Note that peptest only records instances in which the event loop is stuck for more than 50 ms.

ammo.js

Long unresponsive period (> 1 s) and a few shorter ones when loading page.  A few short unresponsive periods during the 20 seconds that the test waits after the page loads.

PEP TEST-START | test_ammo.js
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 135 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 82 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 1138 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 446 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 87 ms
PEP WARNING    | test_ammo.js | wait | unresponsive time: 100 ms
PEP WARNING    | test_ammo.js | wait | unresponsive time: 219 ms
PEP WARNING    | test_ammo.js | wait | unresponsive time: 116 ms
PEP TEST-UNEXPECTED-FAIL | test_ammo.js | fail threshold: 0.0 < metric: 1597.895
PEP TEST-END   | test_ammo.js | finished in: 26517 ms

webgl_terrain_dynamic.html

Much like ammo.js, there's a big delay, and a few short/medium-sized ones, when loading the page.  Then there are regular short delays while the demo is displaying.

PEP TEST-START | test_webgl_terrain.js
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 60 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 1054 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 135 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 307 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 130 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 658 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 118 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 278 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 70 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 54 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 56 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 56 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 58 ms
PEP TEST-UNEXPECTED-FAIL | test_webgl_terrain.js | fail threshold: 0.0 < metric: 1785.514
PEP TEST-END   | test_webgl_terrain.js | finished in: 29473 ms
I modified the peptest to enable JS memory logging and output the error console messages.

Here's the new output from ammo.js (page loaded + 20 seconds of run time):

PEP TEST-START | test_ammo.js
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 57 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 1123 ms
PEP INFO       | GC(T+0.0) Type:Glob, Total:42.2, Wait:6.9, Mark:22.1, Sweep:11.2, FinObj:3.3, FinStr:0.2, FinScr:0.4, FinShp:2.0, DisCod:1.1, DisAnl:1.6, XPCnct:1.0, Destry:0.0, End:2.9, +Chu:15, -Chu:0, Reason:Mallc
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 405 ms
PEP WARNING    | test_ammo.js | open_page | unresponsive time: 73 ms
PEP INFO       | GC(T+4.0) Type:Glob, Total:44.5, Wait:0.1, Mark:28.8, Sweep:12.5, FinObj:3.4, FinStr:0.0, FinScr:0.4, FinShp:1.0, DisCod:1.6, DisAnl:4.8, XPCnct:0.6, Destry:0.1, End:3.6, +Chu:19, -Chu:0, Reason:  API
PEP WARNING    | test_ammo.js | wait | unresponsive time: 89 ms
PEP WARNING    | test_ammo.js | wait | unresponsive time: 187 ms
PEP INFO       | GC(T+8.1) Type:Glob, Total:38.6, Wait:0.1, Mark:29.3, Sweep:9.2, FinObj:3.4, FinStr:0.0, FinScr:0.2, FinShp:0.7, DisCod:1.4, DisAnl:2.3, XPCnct:0.4, Destry:0.0, End:0.5, +Chu:4, -Chu:0, Reason:  API
PEP INFO       | CC(T+9.1) collected: 1057 (1057 waiting for GC), suspected: 4506, duration: 5 ms.
PEP INFO       | GC(T+12.1) Type:Glob, Total:39.0, Wait:0.1, Mark:29.0, Sweep:9.8, FinObj:4.0, FinStr:0.0, FinScr:0.2, FinShp:0.7, DisCod:1.4, DisAnl:2.4, XPCnct:0.4, Destry:0.0, End:0.5, +Chu:1, -Chu:0, Reason:  API
PEP INFO       | GC(T+16.2) Type:Glob, Total:38.8, Wait:0.1, Mark:28.7, Sweep:10.0, FinObj:4.1, FinStr:0.0, FinScr:0.2, FinShp:0.7, DisCod:1.4, DisAnl:2.4, XPCnct:0.5, Destry:0.0, End:0.5, +Chu:1, -Chu:0, Reason:  API
PEP INFO       | CC(T+17.1) collected: 48 (48 waiting for GC), suspected: 75, duration: 2 ms.
PEP INFO       | GC(T+20.2) Type:Glob, Total:39.2, Wait:0.1, Mark:28.9, Sweep:10.2, FinObj:4.2, FinStr:0.0, FinScr:0.2, FinShp:0.7, DisCod:1.4, DisAnl:2.4, XPCnct:0.4, Destry:0.0, End:0.4, +Chu:0, -Chu:0, Reason:  API
PEP TEST-UNEXPECTED-FAIL | test_ammo.js | fail threshold: 0.0 < metric: 1476.622
PEP TEST-END   | test_ammo.js | finished in: 22896 ms
PEP INFO       | Test Suite Finished
PEP INFO       | GC(T+22.3) Type:Glob, Total:24.1, Wait:0.1, Mark:9.5, Sweep:13.1, FinObj:2.9, FinStr:0.0, FinScr:3.0, FinShp:1.5, DisCod:1.3, DisAnl:2.5, XPCnct:1.0, Destry:0.0, End:2.4, +Chu:0, -Chu:0, Reason:  API
Attachment #583268 - Attachment is obsolete: true
And for webgl_terrain_dynamic.html:

PEP TEST-START | test_webgl_terrain.js
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 57 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 1073 ms
PEP INFO       | GC(T+0.0) Type:Glob, Total:51.2, Wait:1.1, Mark:39.5, Sweep:9.3, FinObj:3.1, FinStr:0.2, FinScr:0.4, FinShp:1.9, DisCod:0.4, DisAnl:1.2, XPCnct:0.8, Destry:0.0, End:2.2, +Chu:102, -Chu:0, Reason:Alloc
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 116 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 69 ms
PEP INFO       | GC(T+4.1) Type:Glob, Total:73.5, Wait:0.1, Mark:68.2, Sweep:5.1, FinObj:0.5, FinStr:0.0, FinScr:0.1, FinShp:0.7, DisCod:0.4, DisAnl:2.1, XPCnct:0.5, Destry:0.1, End:0.6, +Chu:50, -Chu:0, Reason:  API
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 313 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 123 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 524 ms
PEP WARNING    | test_webgl_terrain.js | open_page | unresponsive time: 79 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 176 ms
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 74 ms
PEP INFO       | GC(T+8.1) Type:Glob, Total:58.9, Wait:0.1, Mark:54.8, Sweep:3.9, FinObj:0.5, FinStr:0.0, FinScr:0.1, FinShp:0.7, DisCod:0.6, DisAnl:1.1, XPCnct:0.5, Destry:0.0, End:0.6, +Chu:0, -Chu:0, Reason:  API
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 68 ms
PEP INFO       | CC(T+9.1) collected: 1989 (1989 waiting for GC), suspected: 5453, duration: 15 ms.
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 57 ms
PEP INFO       | GC(T+12.2) Type:Glob, Total:59.0, Wait:0.1, Mark:54.7, Sweep:3.9, FinObj:0.7, FinStr:0.0, FinScr:0.1, FinShp:0.6, DisCod:0.6, DisAnl:1.0, XPCnct:0.5, Destry:0.0, End:0.8, +Chu:0, -Chu:0, Reason:  API
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 51 ms
PEP INFO       | GC(T+16.3) Type:Glob, Total:56.7, Wait:0.1, Mark:52.6, Sweep:4.0, FinObj:0.7, FinStr:0.0, FinScr:0.1, FinShp:0.7, DisCod:0.6, DisAnl:1.0, XPCnct:0.4, Destry:0.0, End:0.5, +Chu:0, -Chu:0, Reason:  API
PEP INFO       | CC(T+17.2) collected: 826 (826 waiting for GC), suspected: 878, duration: 3 ms.
PEP INFO       | GC(T+20.3) Type:Glob, Total:56.9, Wait:0.1, Mark:52.6, Sweep:4.2, FinObj:0.9, FinStr:0.0, FinScr:0.1, FinShp:0.6, DisCod:0.6, DisAnl:1.0, XPCnct:0.4, Destry:0.0, End:0.5, +Chu:0, -Chu:0, Reason:  API
PEP WARNING    | test_webgl_terrain.js | wait | unresponsive time: 55 ms
PEP INFO       | GC(T+24.4) Type:Glob, Total:60.3, Wait:0.1, Mark:56.0, Sweep:4.2, FinObj:0.9, FinStr:0.0, FinScr:0.1, FinShp:0.6, DisCod:0.6, DisAnl:1.0, XPCnct:0.4, Destry:0.0, End:0.5, +Chu:0, -Chu:13, Reason:  API
PEP INFO       | CC(T+25.4) collected: 818 (818 waiting for GC), suspected: 851, duration: 4 ms.
PEP TEST-UNEXPECTED-FAIL | test_webgl_terrain.js | fail threshold: 0.0 < metric: 1616.661
PEP TEST-END   | test_webgl_terrain.js | finished in: 28869 ms
PEP INFO       | Test Suite Finished
PEP INFO       | GC(T+28.7) Type:Glob, Total:80.6, Wait:0.1, Mark:71.3, Sweep:6.3, FinObj:1.8, FinStr:0.0, FinScr:0.1, FinShp:1.1, DisCod:0.6, DisAnl:1.1, XPCnct:0.6, Destry:0.0, End:3.6, +Chu:0, -Chu:0, Reason:  API

We can clearly see the GC/CC running at every > 50 ms pause.

Let me know if anyone wants similar output from other sites.
I ran across this test site yesterday: http://gregor-wagner.com/tmp/mem
It may be useful in tracking down this bug.  Sure stresses the browser nicely.

I'll try playing with this if I get a chance over the holidays.  But if anyone else wants to see if it illuminates something, please feel free.  :)
Depends on: 714770
Depends on: 733190
Depends on: 751557
Depends on: 504640
Depends on: 624867
Starting sync can causes 400ms stops.
Assignee: general → nobody
Severity: normal → S3
Status: NEW → RESOLVED
Closed: 8 months ago
Resolution: --- → INCOMPLETE
You need to log in before you can comment on or make changes to this bug.