714770 - GC times > 1 sec

Status: RESOLVED WORKSFORME

(Core :: JavaScript Engine, defect)

Description

[Bob Clary [:bc] (inactive)]

In bug 702813 comment 35 I attached the results of extracting GC and CC times during the load of the top 10,000 sites from Alexa. Smaug suggested I file a JS bug on the long GC times.

The top 10 times were:

Site                       gctype gcduration
http://jsonline.com/       GC     1396.5
http://haaretz.co.il       GC     1258.2
http://crictime.com/       GC      646.6
http://haaretz.com/        GC      303
http://ilemi.me/           GC      289
http://mako.co.il/         CC      288
http://archdaily.com/      CC      233
http://hindustantimes.com/ GC      232.9
http://redmondpie.com/     CC      224
http://deadspin.com/       CC      192

I set javascript.options.mem.log to true then extracted what I think was the total time for the GC from the Total value in the log. e.g.

GC(T+9.4) Type:Glob, Total:1396.5, Wait:1.5, Mark:21.4, Sweep:16.8, FinObj:2.4, FinStr:0.2, FinScr:0.9, FinShp:2.3, DisCod:1.4, DisAnl:5.1, XPCnct:1.7, Destry:0.1, End:1358.3, +Chu:2, -Chu:0, Reason:  API

I used a Nightly nightly build from 2011-12-28 on 32bit Linux (Centos5). The test consisted of starting the browser, loading the page, waiting 15 seconds, shutting down the browser, repeat...

Comment 1

[Igor Bukanov]

(In reply to Bob Clary [:bc:] from comment #0)
> GC(T+9.4) Type:Glob, Total:1396.5, Wait:1.5, Mark:21.4, Sweep:16.8,
> FinObj:2.4, FinStr:0.2, FinScr:0.9, FinShp:2.3, DisCod:1.4, DisAnl:5.1,
> XPCnct:1.7, Destry:0.1, End:1358.3, +Chu:2, -Chu:0, Reason:  API

Interesting, the total mark/sweep time is 38.2 ms, so something outside the mark/sweep contributes a lot. So the problems is either in begin/end GC callbacks or with purge. I suppose we need more detailed GC time split to find the reason.

Comment 2

[Igor Bukanov]

(In reply to Bob Clary [:bc:] from comment #0)
> In bug 702813 comment 35 I attached the results of extracting GC and CC
> times during the load of the top 10,000 sites from Alexa. Smaug suggested I
> file a JS bug on the long GC times.

Just to be sure - the test is just running a particular site in a browser for 15 seconds and observing the max total GC time during the test, right?

Comment 3

[Igor Bukanov]

I cannot reproduce the results. With a build from http://ftp.mozilla.org/pub/mozilla.org/firefox/nightly/2011-12-28-03-10-49-mozilla-central/firefox-12.0a1.en-US.linux-i686.tar.bz2 the worst GC time I got was 35 ms after loading the first 3 cites from the list.

Comment 4

[Bob Clary [:bc] (inactive)]

The browser is started and the page loaded with the pref set and the messages sent to the console are captured and dumped to stdout. After the page loads the browser sits idle for 15 seconds then shuts down. This is repeated for each of the urls in the list using the same profile. 

In the jsonline case, the log says:

Spider: Start: -url "http://jsonline.com/" -hook "http://test.mozilla.com/tests/mozilla.org/top-sites/userhooks/userhook-base.js" -depth 0 -timeout 120 -wait 0 -start -quit -jserrors 
Spider: Begin loading http://jsonline.com/
DOM Events Warning: ["An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http
://www.jsonline.com/" line: 584}]. Source File: http://www.jsonline.com/, Line: 584.
DOM Events Warning: ["An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http
://c5.zedo.com//ads2/f/1085579/3840/27/0/305006688/305006688/0/305/1578/zz-V1-LMB_Canada_1x1.html?a=s%3D1578%3Bg%3D27%3Bm%3D57%3Bw%3D8%3Bu%3D3wv8TsyOk4wOndMAZsLFPAJv~122911%3Bi%3D0%3B;l=;p=;t=1325421364" line: 43}]. Source File: http:/
/c5.zedo.com//ads2/f/1085579/3840/27/0/305006688/305006688/0/305/1578/zz-V1-LMB_Canada_1x1.html?a=s%3D1578%3Bg%3D27%3Bm%3D57%3Bw%3D8%3Bu%3D3wv8TsyOk4wOndMAZsLFPAJv~122911%3Bi%3D0%3B;l=;p=;t=1325421364, Line: 43.
malformed-xml Error: ["junk after document element" {file: "http://www.jsonline.com/templates/JSO_Get_Newswatch_Items?m=46&h=20&day=31&c=y" line: 9 column: 2 source: " <p class="contentblock">"}]. Source File: http://www.jsonline.com/t
emplates/JSO_Get_Newswatch_Items?m=46&h=20&day=31&c=y, Line: 9, Column: 2, Source Code:      <p class="contentblock">
GC(T+0.0) Type:Glob, Total:77.5, Wait:2.5, Mark:17.6, Sweep:40.2, FinObj:13.0, FinStr:0.9, FinScr:1.6, FinShp:6.7, DisCod:3.4, DisAnl:5.3, XPCnct:2.9, Destry:0.1, End:19.8, +Chu:11, -Chu:0, Reason:  API
DOM Warning: ["Empty string passed to getElementById()." {file: "http://www.jsonline.com/" line: 0}]. Source File: http://www.jsonline.com/, Line: 0.
DOM Warning: ["Empty string passed to getElementById()." {file: "http://www.jsonline.com/" line: 0}]. Source File: http://www.jsonline.com/, Line: 0.
DOM Warning: ["Empty string passed to getElementById()." {file: "http://www.jsonline.com/" line: 0}]. Source File: http://www.jsonline.com/, Line: 0.
DOM Warning: ["Empty string passed to getElementById()." {file: "http://www.jsonline.com/" line: 0}]. Source File: http://www.jsonline.com/, Line: 0.
malformed-xml Error: ["mismatched tag. Expected: </br>." {file: "http://www.jsonline.com/templates/JSO.PagePart.FeaturedBlogs" line: 30 column: 5 source: "             </p>    "}]. Source File: http://www.jsonline.com/templates/JSO.Pag
ePart.FeaturedBlogs, Line: 30, Column: 5, Source Code:               </p>    
DOM Events Warning: ["An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http
://www.jsonline.com/" line: 7211}]. Source File: http://www.jsonline.com/, Line: 7211.
DOM Events Warning: ["An unbalanced tree was written using document.write() causing data from the network to be reparsed. For more information https://developer.mozilla.org/en/Optimizing_Your_Pages_for_Speculative_Parsing" {file: "http
://www.jsonline.com/" line: 8770}]. Source File: http://www.jsonline.com/, Line: 8770.
affiliates.upickem.net : server does not support RFC 5746, see CVE-2009-3555
eblastengine.upickem.net : server does not support RFC 5746, see CVE-2009-3555
DOM Core Warning: ["Use of getAttributeNode() is deprecated. Use getAttribute() instead." {file: "http://www.jsonline.com/" line: 0}]. Source File: http://www.jsonline.com/, Line: 0.
affiliates.upickem.net : server does not support RFC 5746, see CVE-2009-3555
*** Failed to get string typeException in bundle: chrome://global/locale/console.properties
JavaScript[JavaScript Error: "function statement requires a name" {file: "http://tag.admeld.com/ad/iframe/344/journalinteractive/300x250/btf?t=1325393181535&tz=480&hu=&ht=js&hp=0&url=http%3A%2F%2Fwww.jsonline.com%2F&refer=" line: 23 co
lumn: 8 source: "function() { var src="http://b.ermisvc.com"; }"}]
GC(T+4.0) Type:Glob, Total:39.7, Wait:1.2, Mark:17.6, Sweep:16.2, FinObj:3.6, FinStr:1.1, FinScr:0.8, FinShp:2.0, DisCod:1.4, DisAnl:3.6, XPCnct:1.2, Destry:0.2, End:5.9, +Chu:0, -Chu:0, Reason:  API
CC(T+5.0) collected: 4763 (4763 waiting for GC), suspected: 14212, duration: 36 ms.
Spider: Finish loading http://jsonline.com/
Spider: Current Url: http://jsonline.com/, Referer: null, Depth: 0
GC(T+9.4) Type:Glob, Total:1396.5, Wait:1.5, Mark:21.4, Sweep:16.8, FinObj:2.4, FinStr:0.2, FinScr:0.9, FinShp:2.3, DisCod:1.4, DisAnl:5.1, XPCnct:1.7, Destry:0.1, End:1358.3, +Chu:2, -Chu:0, Reason:  API
CC(T+12.7) collected: 167 (167 waiting for GC), suspected: 2292, duration: 15 ms.
GC(T+13.5) Type:Glob, Total:33.5, Wait:0.1, Mark:21.3, Sweep:11.7, FinObj:0.8, FinStr:0.1, FinScr:0.3, FinShp:1.5, DisCod:1.0, DisAnl:4.3, XPCnct:1.1, Destry:0.1, End:1.2, +Chu:0, -Chu:0, Reason:  API
GC(T+17.5) Type:Glob, Total:33.0, Wait:0.1, Mark:21.2, Sweep:11.5, FinObj:0.6, FinStr:0.1, FinScr:0.4, FinShp:1.5, DisCod:1.0, DisAnl:4.3, XPCnct:1.0, Destry:0.1, End:1.2, +Chu:0, -Chu:0, Reason:  API
CC(T+18.5) collected: 56 (56 waiting for GC), suspected: 190, duration: 13 ms.
GC(T+21.5) Type:Glob, Total:32.5, Wait:0.1, Mark:21.3, Sweep:10.8, FinObj:0.7, FinStr:0.1, FinScr:0.3, FinShp:1.5, DisCod:1.0, DisAnl:3.8, XPCnct:1.1, Destry:0.1, End:1.2, +Chu:0, -Chu:0, Reason:  API
Spider: stopped... loaded 1 pages
NOTE: child process received `Goodbye', closing down

http://jsonline.com/: EXIT STATUS: NORMAL (35.100040 seconds)

Perhaps the long time was due to transitory content or due to the profile being used. If you want to refine the collection times to collect more data I can rerun the test.

Comment 5

[Igor Bukanov]

When I tried to run using Spider I got:

Compile Failed  [Exception... "Component returned failure code: 0x80004005 (NS_ERROR_FAILURE)"  nsresult: "0x80004005 (NS_ERROR_FAILURE)"  location: "JS frame :: chrome://spider/content/script-loader.js :: loadScriptXHR :: line 74"  data: no] undefined

What I am doing wrong?

Comment 6

[Bob Clary [:bc] (inactive)]

Attachment: userhook-base.js

You did nothing wrong. You were just missing the user hook I used to delay the page before transitioning.

There are a couple of approaches:

1. place the attached hook script on a locally available web server and change the -hook "http://test.mozilla.com/tests/mozilla.org/top-sites/userhooks/userhook-base.js" to point to it.

2. remove the -hook "http://test.mozilla.com/tests/mozilla.org/top-sites/userhooks/userhook-base.js" stuff from the command line altogether and then:

change -wait 0 to -wait 15 which will terminate the browser after the 15 seconds or

remove the -quit which will leave the browser running until you terminate it manually.

Comment 7

[Bob Clary [:bc] (inactive)]

Igor, I am in the process of testing out a try build from Smaug and have been running it in parallel with a Nightly build as well. I've again seems some outliers (though different from before) but when attempting to reproduce locally I can not. I'm not sure whether this is a real issue that is not reproducible or if it is an artifact of how I am testing. I'm ok with marking this WFM if you want.