Open Bug 1620079 Opened 5 years ago Updated 2 years ago

Large amounts of time are spent in module import when starting Fenix (applink)

Categories

(GeckoView :: General, defect, P2)

Unspecified
All

Tracking

(Performance Impact:low)

Performance Impact low

People

(Reporter: jesup, Unassigned, NeedInfo)

References

(Depends on 1 open bug, Blocks 1 open bug)

Details

(Keywords: perf:responsiveness, Whiteboard: [geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m93?])

See this applink profile from acreskey:
https://perfht.ml/2IhGYBF

A rough count is that ~470ms of 1.5s (really of 1.2s of the 1.5) was spent in module imports, presuming they don't overlap. (manual adding up of the import times). Largest is about 45ms; with a bunch over 25 (and many in the 1-10ms range)

This appears to be significantly slowing every startup of geckoview; some way to minimize this overhead would help a ton - deferring until needed? precompiling the JS in some way? Etc.

Looks rather bad. p1

Whiteboard: [qf] → [qf:p1:responsiveness]
Priority: -- → P1
Whiteboard: [qf:p1:responsiveness] → [qf:p1:responsiveness][geckoview:m76]

See also the imports in the content process (~200ms of ~550 to load the page, modulo overlap): https://perfht.ml/2Tos8zH

Applying a filter for "import,JS XPCOM,ScriptEval,Subscript" in the marker chart seems to be a good way to focus on the relevant markers.
New Fenix app link startup profile, Moto G5: https://perfht.ml/2VMKVGx

Assignee: nobody → agi
Blocks: GeckoView_Startup
No longer blocks: 1608826

Taking 1623758 instead.

Assignee: agi → nobody

Needs reverification

Assignee: nobody → bdahl
Whiteboard: [qf:p1:responsiveness][geckoview:m76] → [qf:p1:responsiveness][geckoview:m76][geckoview:m77]
Priority: P1 → P2
Assignee: bdahl → nobody
Whiteboard: [qf:p1:responsiveness][geckoview:m76][geckoview:m77] → [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88]

Investigation in 88 to see if this is still an issue

Priority: P2 → P1
Rank: 8

mstange can you tell us if this is still an issue?

Flags: needinfo?(mstange.moz)
Whiteboard: [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88] → [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][geckoview:m89]
Priority: P1 → P2
Whiteboard: [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][geckoview:m89] → [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m90]

Yes, this is still an issue. I just collected a new startup profile in bug 1550073 comment 13 and module imports are still a significant source of startup delay: https://share.firefox.dev/3eTWHII

Flags: needinfo?(mstange.moz)
Whiteboard: [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m90] → [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m91?]

We can verify that the bytecode cache is working on android.

The 100ms of parsing at the beginning should improve with the work to JSRuntime::initSelfHosting from bug 1662149.

Depends on: 1662149

We spent some time digging into this as part of the perf bug bash. We don't think this qualifies as p1 because it should only present on cold startups. mcomella is going to be digging into telemetry to understand how frequent cold startups are in the wild on Android, so I'm leaving a needinfo for him.

I will note here for posterity that we were seeing some weird behavior in the content process around jsm imports. We were seeing significant time spent parsing ExtensionContent.jsm, even though that should have been preloaded by the ScriptPreloader. We timeboxed investigating why but weren't able to come to a conclusion in the time we alotted.

Flags: needinfo?(michael.l.comella)
Whiteboard: [qf:p1:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m91?] → [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m91?]

I will note here for posterity that we were seeing some weird behavior in the content process around jsm imports. We were seeing significant time spent parsing ExtensionContent.jsm, even though that should have been preloaded by the ScriptPreloader.

Here's a profile of the behavior: https://share.firefox.dev/3u39eP2 and steps to reproduce:

  1. fresh install nightly
  2. Launch the app via applink (I used adb)
  3. Go to settings, enable remote debugging
  4. force stop the app (I used adb)
  5. Launch the app via applink (adb)
  6. Press the home button to background the app
  7. Start the profiler
  8. Launch the app via applink (adb)
  9. End profile

If instead of force stopping, you wait maybe two minutes, you can no longer reproduce the behavior. There may be some deferred start up action that will warm this up after a short while such that it can't be reproduced.

Whiteboard: [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m91?] → [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m92?]

(In reply to Doug Thayer [:dthayer] (he/him) from comment #12)

We spent some time digging into this as part of the perf bug bash. We don't think this qualifies as p1 because it should only present on cold startups. mcomella is going to be digging into telemetry to understand how frequent cold startups are in the wild on Android, so I'm leaving a needinfo for him.

I completed my fenix start up type telemetry analysis: see the "Aggregate on start up STATE" heading for COLD/WARM/HOT specifically. COLD start ups are 39.3% of start ups (note: this is not a total count of start ups – this is based on the GLAM-like aggregation that sees each user contribute equally), HOT is 36.1% of start ups, with UNKNOWN & WARM tailing the rest. Note that UNKNOWN may include COLD starts for PWAs and custom tabs.

fwiw, the front-end team has decided to focus on COLD MAIN, COLD VIEW, and UNKNOWN VIEW because WARM is less common and HOT – the other most common event – is supposed to be a trivial amount of computation work.

Doug, does the info that 39.3% of start ups are COLD & that it's the front-end focus change the priority of this issue?

Flags: needinfo?(michael.l.comella) → needinfo?(dothayer)
Whiteboard: [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m92?] → [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m93?]

I will note here for posterity that we were seeing some weird behavior in the content process around jsm imports. We were seeing significant time spent parsing ExtensionContent.jsm, even though that should have been preloaded by the ScriptPreloader.

This might be bug 1623518, the root cause being comment 8 and earlier.

Performance Impact: --- → P3
Whiteboard: [qf:p3:responsiveness][geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m93?] → [geckoview:m76][geckoview:m77][geckoview:m88][[geckoview:m93?]
Severity: normal → S3
Rank: 8 → 222
You need to log in before you can comment on or make changes to this bug.