(no longer active) Reporter
	Description • 7 years ago

In bug 1363384 comment 1, Florian observed some main thread IO when Cu.import()ing some JS module.  Looking at the call stack, I noticed that he isn't getting a working startup cache.  I checked with him and he wasn't on a new profile, which raised some alarms.  We looked into his profile and his startupCache.4.little file was very small (about 45KB.)  He'll attach it to the bug soon.  We looked inside the zip package and there were only a few entries corresponding to a few scripts that should be in the startup cache but almost everything else was missing.

In the mean time there is also bug 1351071 which was backed out recently on the suspicion that the generation of startup cache may somehow be busted and therefore users may not be getting a startup cache after that bug landed.  Florian's Nightly on his machine was the latest build so he already have the backout for bug 1351071 in it.

As we were looking at things on Florian's machine, we noticed his startupCache.4.little file changed again and this time grew to somewhere around 700KB or something like that which sounds more like what I would expect a typical startup cache to be around.

We need to investigate why this is happening (and what is really happening...)

	(no longer active) Reporter
	Comment 3 • 7 years ago

It would be really helpful if we can find someone to dig into this sooner than later.

	Gabor Krizsanits (INACTIVE)
	Comment 4 • 7 years ago

Kris worked on Bug 1361900 and Bug 1359653 so it might be worth to check if those patches fixed/caused this problem. We don't store all the cached scripts in the same file any longer if I recall it correctly. Is the issue reproducible to verify?

	(no longer active) Reporter
	Comment 5 • 7 years ago

(In reply to Gabor Krizsanits [:krizsa :gabor] from comment #4)
> Kris worked on Bug 1361900 and Bug 1359653 so it might be worth to check if
> those patches fixed/caused this problem. We don't store all the cached
> scripts in the same file any longer if I recall it correctly. Is the issue
> reproducible to verify?

I don't know much more about this besides comment 0, unfortunately.  Someone needs to look into the reproducibility aspect as part of the investigation too...

	(no longer active) Reporter
	Comment 6 • 7 years ago

Hi Ting-yu,

Is there any chance you can please take a look at this bug and investigate it please?  I'd like to get a sense of whether this is a real regression and what causes it.  We don't have a lot of information about this bug yet unfortunately, so I suggest starting by trying to reproduce the bug from a Nightly build around the date of comment 0 or when bug 1363384 got filed and seeing if you can reproduce it...

	Ting-Yu Chou [:ting] (away)
	Comment 7 • 7 years ago

Sure, bug 1351071 was backed out at 2017-05-09 and relanded at 2017-05-19, which seems match to the date that Florian profiled and when the cache went back to normal.

If bug 1351071 really causes that, Florian should see a smaller cache file now, do you? Also are you able to reproduce the profile of bug 1363384 comment 1?

On my Ubuntu, Nightly 20170509222706 (I am not sure whether it includes the backout for bug 1351071, but based on the timestamp it should) has ~/.cache/.mozilla/firefox-trunk/x.default/startupCache/startupCache.8.little ~1770k. After updating to Nightly 20170523165845, the file size is ~1340k which seems still normal with bug 1351071 in it.

I assume the cache grows over time, could it be possible that the profile was captured when the cache was just created?

	Ting-Yu Chou [:ting] (away)
	Comment 8 • 7 years ago

Or maybe StartupCache::Init() was just failed, so it went to the slow path. There are cases that it could fail.

	(no longer active) Reporter
	Comment 9 • 7 years ago

Florian: ping?

	Florian Quèze [:florian]
	Comment 10 • 7 years ago

(In reply to Ting-Yu Chou [:ting] from comment #7)

> If bug 1351071 really causes that, Florian should see a smaller cache file
> now, do you? Also are you able to reproduce the profile of bug 1363384
> comment 1?

Not exactly sure of what you are asking, but nsZipArchive::GetDataOffset is still expensive during cold startup, see https://perfht.ml/2tAdjgA

The scriptCache.* files I'm seeing today in the "startupCache" folder of the profile all weight more than 4MB, and the scriptCache-child.* files weight ~1.5MB.


Here is a startup profile if I remove the "startupCache" folder from the profile folder: https://perfht.ml/2tAN2ij

The interesting thing to notice is that the main thread is idle twice before first paint, while loading the browser.xul window and its dependencies. nsZipArchive::GetDataOffset isn't visible there.



These 2 periods of idleness on the main thread during startup puzzled me a lot since I first saw them, back around the time this bug was filed. I could reproduce consistently with warm startup on the reference hardware during the SF all hands. Last time I reproduced for sure was Thursday last week (July 6th). Today I can't reproduce.

I had noticed in SF that I could get a similar startup profile on my macbook if I packaged a local build and started it with the -purgecaches flag. And now I just realized that I can also force the reference hardware to generate such a profile by deleting the startupCache folder.

So... I don't have any proof, but I think this all gives strong evidence that the startup cache either isn't working correctly, or wasn't until at least Thursday last week.

	lucian
	Comment 11 • 7 years ago

Hey guys,

Since Firefox 56 we are experiencing random weird behaviours of the Cliqz extension and the only thing we knew so far was that it happens mostly after the extension updates.
We finally managed to pin it down and we think it is related with the issue described in this bug.
When a user runs version X of our extension and updates to version X+1 he has a chance (20-30% from our telemetry) to run a version which uses files from both versions.
More precisely the issue seems to be in “Services.scriptloader.loadSubScript” which will load a cached version of some files (even bootstrap.js!) from an older version from "/Users/YYYYY/Library/Caches/Firefox/Profiles/XXXXX/startupCache/scriptCache.bin” or ".../scriptCache-current.bin"

It is not 100% reproducible but after a few tries it happens. Here are the steps:
 - new profile in latest Firefox release (58.0.2) probably happens in more versions, likely after Firefox 56
 - install any version from https://addons.mozilla.org/de/firefox/addon/cliqz/versions/   (Eg 2.23.3)
 - use the search dropdown and the browser in general
 - restart the browser, use more the search, restart again (maybe? :) )
 - install another version (eg 2.24.5)
 - in this moment all the resources loaded with “Services.scriptloader.loadSubScript” are from the old version (2.23.3) including our bootstrap.js file which is the entry to our extension although we upgraded to 2.24.5
 - and all the other files are updated (eg process scripts, or iframes or whatever) 
 - it seems to happen more often on downgrade (from 2.24.5 to 2.23.3) but not exclusively so try to alternate upgrade and downgrade to reproduce

To prove that we prepared a small snippet:
  // this will return the wrong version (2.24.5 in the screenshot)
  var win = { global: {} }; 
  Services.scriptloader.loadSubScript('chrome://cliqz/content/runloop.js', win);
  Services.scriptloader.loadSubScript('chrome://cliqz/content/core/app.bundle.js', win);
  console.log(win.global.config.EXTENSION_VERSION); 

  // and this will return the right version (2.23.3 in the screenshot)
  var win = { global: {} }; 
  Services.scriptloader.loadSubScriptWithOptions('chrome://cliqz/content/runloop.js',  { target: win, ignoreCache: true });
  Services.scriptloader.loadSubScriptWithOptions('chrome://cliqz/content/core/app.bundle.js',  { target: win, ignoreCache: true });
  console.log(win.global.config.EXTENSION_VERSION); 

Also a screenshot: https://screenshots.firefox.com/DtUTAx7fKo585FQp/null 
Behind the Browser Console you can see the right version of the code loaded via the chrome url.

We temporarily moved towards "loadSubScriptWithOptions" where we are able to ignore the Cache but it would be great to find a better solution.  https://github.com/cliqz-oss/browser-core/compare/2.24.5...2.24.7#diff-33f3f1d203440162225e08f676fa1d4eR20

Please let me know if these findings make sense.

Cheers!
Lucian

	lucian
	Comment 12 • 7 years ago

PS: probably important - we are a bootstrapped extension

	Kris Maglione [:kmag]
	Comment 13 • 7 years ago

(In reply to :Ehsan Akhgari from comment #0)
> We looked into his profile and his
> startupCache.4.little file was very small (about 45KB.)  He'll attach it to
> the bug soon.  We looked inside the zip package and there were only a few
> entries corresponding to a few scripts that should be in the startup cache
> but almost everything else was missing.
> 
> As we were looking at things on Florian's machine, we noticed his
> startupCache.4.little file changed again and this time grew to somewhere
> around 700KB or something like that which sounds more like what I would
> expect a typical startup cache to be around.

Interesting. I've actually been thinking about fixing the opposite problem. The startup cache tends to be way too big, because it still duplicates files from the preloader cache. And on Windows, last I checked, we still open that file with aggressive read-ahead enabled, which means lots of wasted IO.

> We need to investigate why this is happening (and what is really
> happening...)

It's worth noting that we still purge the startup caches in a bunch of situations, including after every app or extension update.

	Kris Maglione [:kmag]
	Comment 14 • 7 years ago

(In reply to lucian from comment #11)
> Since Firefox 56 we are experiencing random weird behaviours of the Cliqz
> extension and the only thing we knew so far was that it happens mostly after
> the extension updates.

This is completely unrelated to this bug. In fact, if anything, the behavior you describe is the opposite of the behavior described here. Please file a separate bug for this.

Thanks.

	lucian
	Comment 15 • 7 years ago

(In reply to Kris Maglione [:kmag] (long backlog; ping on IRC if you're blocked) from comment #14)
> This is completely unrelated to this bug. In fact, if anything, the behavior
> you describe is the opposite of the behavior described here. Please file a
> separate bug for this.

Thanks for your feedback Kris!
Submitted a new bug for our issue - https://bugzilla.mozilla.org/show_bug.cgi?id=1444957

	Sylvestre Ledru [:Sylvestre]
	Comment 16 • 6 years ago

Clearly ni on Naveed as he no longer works at Mozilla.

	Pulsebot
	Comment 26 • 6 years ago

Pushed by dothayer@mozilla.com:
https://hg.mozilla.org/integration/autoland/rev/1a681dc60b60
Collect telemetry stats on startup cache hits and misses r=kmag