1708532 - Initializing the log module takes extra time for each and every process creation

Status: RESOLVED FIXED

(Remote Protocol :: Marionette, defect, P3)

Description

[Henrik Skupin [:whimboo][⌚️UTC+2]]

As discovered in the #fission channel there is a bit of noise for performance tests around content process creation time. Especially when the MarionetteEvents child actor is getting created. Here we call logger.trace() to print actor creation information if the log level is Trace:

https://searchfox.org/mozilla-central/rev/71515d047cbdd02687a1b9b7265f2ffb51300bf1/testing/marionette/actors/MarionetteEventsChild.jsm#28-31

This call always takes around 2ms, which isn't much, but as said above adds noise when analyzing a profile. Problem is that even for log levels of Info and Debug we are creating the logger, whereby it's just a no-op and nothing gets logged.

The problem actually is inside the Toolkit logger which doesn't cache the preference name and value, so that manageLevelFromPref takes 50% of the time.

As such any code in Marionette that uses our own logger needs to configure the logger for each and every process, because existing ones aren't shared:

https://searchfox.org/mozilla-central/rev/71515d047cbdd02687a1b9b7265f2ffb51300bf1/testing/marionette/log.js#34-37

Here a profile:
https://share.firefox.dev/2S62b9W

Nika, I'm not sure how much we can actually do on our side. Also it seems like that each and every consumer of the toolkit logger has the same problem. So fixing it there might be a better approach?

Comment 1

[Henrik Skupin [:whimboo][⌚️UTC+2]]

So for the first page load the above mentioned delay gets hit even twice. First when the pagehide event is fired by about:blank because that causes the events actor to be instantiated for the given browsing context. And then again for the next page load event (DOMContentLoaded or pageshow) because these also cause the actor to be created for the new browsing context. There might even be cases when the process gets switched multiple times...

Easiest solution would be to just remove the call to log.trace() in actorCreated, but it would also mean we will miss information for failure investigation. As such I would do that only in case of no other solution.

Over the weekend Mark Banner mentioned that there is also console.createInstance(), and which supports setting a prefix and a maximum level. For Marionette it could look like the following:

    const logger = console.createInstance({
      maxLogLevelPref: "marionette.log.level",
      prefix: "Marionette",
    });

I didn't test that yet but it might need devtools.console.stdout.chrome set to true so that those log entries also appear on stdout. Sadly all the other chrome logging from other Firefox components will also end-up there so that we hit bug 1399441. By default we don't want to see anything else beside Marionette and soon the Remote Agent.

Comment 2

[Nika Layzell [:nika] (ni? for response)]

I don't think I have very much I can easily contribute here, so clearing ni?

Comment 3

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Randell, how important is it to get these extra calls out of the performance profile? There might be workarounds for now that we could check, but won't have the time to fully fix the underlying problem in the short term due to the filtering problems on geckodriver's side. Thanks.

Comment 4

[Randell Jesup [:jesup] (needinfo me)]

we're trying to get rid of ~30ms of delay when loading into new processes (more realistically get it down to 20 or maybe even 10ms), so even 2ms is a significant amount. It occurs at a critical point when there's no way to 'hide' the delay. I'd say it's moderately important.

Comment 5

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Ok, so lets see what we can do here. Given that the trace output is helpful to us in case of failure investigations in Marionette we would like to leave the call for logger.trace() in the actorCreated method. But we could definitely have a preference check before and only execute it if the logger is indeed set to Trace level.

Anything else might not work at this time due to the above mentioned issues with geckodriver, which would take much work work to get it properly done.

Comment 6

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Only log in actorCreated for trace level

Jesup, how does the measurement look like when this patch gets applied to Marionette? Locally I don't see any overhead anymore. If that's the same for you I'm happy to finalize it and get it landed as a workaround for now.

Comment 7

[Randell Jesup [:jesup] (needinfo me)]

When I profile with your patch in browsertime, I still see getLogger() and Log.jsm::set parent and updateAppenders(), etc: https://share.firefox.dev/2SoyXTV

I also later see Log.jsm being used by MarionetteEventsChild::actorCreated (calls trace()->log()....)

Comment 8

[Randell Jesup [:jesup] (needinfo me)]

Command line to capture the profile:
(what the script I use ends up calling)

./mach browsertime --firefox.binaryPath='/home/jesup/bin/firefox/firefox' --pageCompleteWaitTime 10000 --webdriverPageload true --firefox.preference network.http.speculative-parallel-limit:6 --firefox.preference gfx.webrender.enabled:true --firefox.preference gfx.webrender.precache-shaders:true --firefox.geckoProfiler true --firefox.geckoProfilerParams.interval 0.3 --firefox.geckoProfilerParams.features java,js,stackwalk,leaf,ipcmessages --firefox.geckoProfilerParams.threads GeckoMain,Compositor,IPDL,Worker --firefox.geckoProfilerParams.bufferSize 200000000 --visualMetrics true --video true --visualMetricsContentful true --visualMetricsPerceptual true --videoParams.addTimer false --videoParams.createFilmstrip false --videoParams.keepOriginalVideo false --firefox.windowRecorder=true -n 1 --firefox.preference network.dns.forceResolve:192.168.1.19 --firefox.preference network.socket.forcePort:80=8080;443=8080 --firefox.acceptInsecureCerts true /home/jesup/src/mozilla/browsertime_on_android_scripts/preload.js --browsertime.url https://www.google.com/search?hl=en&q=barack+obama&cad=h --resultDir browsertime-results/www.google.com_search_hl=en_q=barack+obama_cad=h/e10s

Comment 9

[Randell Jesup [:jesup] (needinfo me)]

I presume this means that browsertime is telling it to trace, for some reason?

Comment 10

[Randell Jesup [:jesup] (needinfo me)]

Never mind, I was running Nightly in that profile I think

Comment 11

[Randell Jesup [:jesup] (needinfo me)]

With the right build, I don't see any trace() calls anymore, thanks

Comment 12

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Randell Jesup [:jesup] (needinfo me) from comment #11)

With the right build, I don't see any trace() calls anymore, thanks

Good to know and thanks for the testing. I'll upload a patch for review tomorrow. Also I will file a new bug to move to console.createInstance().

Comment 13

[Henrik Skupin [:whimboo][⌚️UTC+2]]

Attachment: Bug 1708532 - [marionette] Only do trace logging in MarionetteEventsChild.actorCreated when trace level is set.

Comment 14

[Henrik Skupin [:whimboo][⌚️UTC+2]]

(In reply to Randell Jesup [:jesup] (needinfo me) from comment #11)

With the right build, I don't see any trace() calls anymore, thanks

The recently attached patch was actually broken. I'm sorry for that. So can you please have a look again and this time make use of the patch as uploaded to Phabricator? Would be good to know that the 2ms delay is fully gone. Thanks!

Comment 15

[Henrik Skupin [:whimboo][⌚️UTC+2]]

I'm going to just land this patch. If it doesn't fully fix the content process startup delay please file a new bug. Thanks.

Comment 16

[Pulsebot]

Pushed by [e-mail]:
https://hg.mozilla.org/integration/autoland/rev/3714aec52e32
[marionette] Only do trace logging in MarionetteEventsChild.actorCreated when trace level is set. r=marionette-reviewers,jdescottes

Comment 17

[Cristian Brindusan [:cbrindusan]]

https://hg.mozilla.org/mozilla-central/rev/3714aec52e32