AsyncInitializationActivity.onCreate() taking 1.1 seconds sometimes on N5 bots |
||||||||||
Issue descriptionAsyncInitializationActivity.onCreate() is taking 600ms on bots sometimes. It is not happening very often, but enough to spike noise artificially once in a while. It would be nice to understand where it is coming from. Example: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/intent_coldish_bbc_2018-10-02_07-27-54_20880.html On this trace the slow "AsyncInitializationActivity.onCreate()" starts at "24,018.664 ms" and has 600+ ms of idle time. The trace is from this run (hammerhead: Nexus 5): https://uberchromegw.corp.google.com/i/internal.client.clank/builders/health-plan-clankium-phone/builds/8117 Looking at the code my biggest suspect would be the 1% of the unlucky ones that go through the slow path in configureStrictMode(). I'd like to add a trace event there to confirm, and a few trace events nearby.
,
Oct 4
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/3d97a472fe829ed31c020f1ff061b3e9662846df commit 3d97a472fe829ed31c020f1ff061b3e9662846df Author: Egor Pasko <pasko@chromium.org> Date: Thu Oct 04 11:16:03 2018 Android startup: add a few lowly trace events Sometimes AsyncInitializationActivity.onCreate() sits idle for 600+ ms with CPU being idle. Add a few more startup trace events to get a more detailed breakdown where the time is spent. These days finding an example trace where the event spikes (on perf bots) is a matter of a couple of clicks from chromeperf dashboard (win). The plan is to look at the details when it spikes next. Bug: 891797 Change-Id: I41a77a660b166f5013f61ae339596a6745af4686 Reviewed-on: https://chromium-review.googlesource.com/c/1258988 Reviewed-by: Yaron Friedman <yfriedman@chromium.org> Reviewed-by: Boris Sazonov <bsazonov@chromium.org> Commit-Queue: Egor Pasko <pasko@chromium.org> Cr-Commit-Position: refs/heads/master@{#596588} [modify] https://crrev.com/3d97a472fe829ed31c020f1ff061b3e9662846df/chrome/android/java/src/org/chromium/chrome/browser/ChromeStrictMode.java [modify] https://crrev.com/3d97a472fe829ed31c020f1ff061b3e9662846df/chrome/android/java/src/org/chromium/chrome/browser/init/ChromeBrowserInitializer.java [modify] https://crrev.com/3d97a472fe829ed31c020f1ff061b3e9662846df/chrome/android/java/src/org/chromium/chrome/browser/init/ProcessInitializationHandler.java [modify] https://crrev.com/3d97a472fe829ed31c020f1ff061b3e9662846df/components/signin/core/browser/android/java/src/org/chromium/components/signin/AccountManagerFacade.java
,
Oct 5
Here is a trace with the problem illustrated, and new trace events in: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/intent_coldish_bbc_2018-10-04_18-01-48_75468.html AsyncInitializationActivity.onCreate() (starting at "24,613.022 ms") takes 1.3 seconds, but nothing happens for 600ms until handlePreNativeStartup starts. Also no CPU activity during that time. The code for the task is here: https://codesearch.chromium.org/chromium/src/chrome/android/java/src/org/chromium/chrome/browser/init/AsyncInitializationActivity.java?type=cs&q=onCreateInternal&sq=package:chromium&g=0&l=259 What we do before handlePreNativeStartup(): * one shared pref to read for "Document mode migration" - should be quick * a few dummy constructors to run - quick too * super.onCreate() - may read fonts/themes from disk - well, sill way below 500ms This device is running Android M (hammerhead-userdebug 6.0 MRA59G 2457013 dev-keys), so almost everything is AOT-compiled. Maybe OAT is getting fetched to RAM? The LibraryLoader task (a little later on another thread) takes 900ms during this start, but normally it takes <400ms, which suggests that the disk may be busy. We seem to consistently evict the .odex in the log with: /data/local/tmp/clear_system_cache --recurse /data/app/com.google.android.apps.chrome-1 So if it's .odex loading taking 500ms, then it should be affected by some concurrent disk activity (that is not present during other runs) I am puzzled. Will throw in some systrace. If it does not help, will ignore the 2nd run in the metrics as "something weird and unknown".
,
Oct 5
,
Oct 5
unfortunately, the straightforward way to enable systrace on the benchmark breaks messageloop_start_time - no 'CrBrowserMain' thread on the combined systrace. I'll update the metric to allow this, and if it is not too slow to run (hello JS), we'll have some data.
,
Oct 5
Is that the right trace? I see Title AsyncInitializationActivity.onCreate() š Category EarlyJava User Friendly Category other Start 7,151.464 ms Wall Duration 386.032 ms CPU Duration 263.008 ms Self Time 53.859 ms CPU Self Time 26.000 ms
,
Oct 8
yfriedman: this trace has 10 startups. You are pointing at the first event in the trace, and the slowest here is the 2nd, which is at "24,613.022 ms", and these other figures: Wall Duration 1,259.369 ms CPU Duration 257.007 ms Self Time 508.685 ms CPU Self Time 28.998 ms
,
Oct 10
The following revision refers to this bug: https://chromium.googlesource.com/catapult/+/86bdcbf37ffcfaa2c9064a14e24f6195a56baefe commit 86bdcbf37ffcfaa2c9064a14e24f6195a56baefe Author: Egor Pasko <pasko@chromium.org> Date: Wed Oct 10 02:45:50 2018 androidStartupMetric: slow fallback for incorrect process names Scan all processes for event "Startup.BrowserMessageLoopStartTimeFromMainEntry3" in case no event is found ChromeModelHelper..browserHelpers. This happens often when the trace is combined with a systace. The way to reproduce this issue with merging the trace+atrace is demonstrated in: https://chromium-review.googlesource.com/c/chromium/src/+/1264543 Bug: chromium:886621 Bug: chromium:891797 Change-Id: Ibdc3d4a30dd25153a7d4b0d824101ab1ba737168 Reviewed-on: https://chromium-review.googlesource.com/c/1270856 Reviewed-by: Ben Hayden <benjhayden@chromium.org> Commit-Queue: Egor Pasko <pasko@chromium.org> [modify] https://crrev.com/86bdcbf37ffcfaa2c9064a14e24f6195a56baefe/tracing/tracing/metrics/android_startup_metric.html
,
Oct 10
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/ba688e0187826d1ba43799dea76bb0eea45e8008 commit ba688e0187826d1ba43799dea76bb0eea45e8008 Author: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Date: Wed Oct 10 13:08:08 2018 Roll src/third_party/catapult 357c5c287bba..86bdcbf37ffc (3 commits) https://chromium.googlesource.com/catapult.git/+log/357c5c287bba..86bdcbf37ffc git log 357c5c287bba..86bdcbf37ffc --date=short --no-merges --format='%ad %ae %s' 2018-10-10 pasko@chromium.org androidStartupMetric: slow fallback for incorrect process names 2018-10-09 benjhayden@chromium.org Add Request classes for v2spa 2018-10-09 mlippautz@chromium.org Ignore forced Blink GCs in metrics Created with: gclient setdep -r src/third_party/catapult@86bdcbf37ffc The AutoRoll server is located here: https://autoroll.skia.org/r/catapult-autoroll Documentation for the AutoRoller is here: https://skia.googlesource.com/buildbot/+/master/autoroll/README.md If the roll is causing failures, please contact the current sheriff, who should be CC'd on the roll, and stop the roller if necessary. CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel BUG= chromium:886621 ,chromium:891797,chromium:843903 TBR=sullivan@chromium.org Change-Id: I9aedff776241a9f68f0d9efa700c0e769eb29d2c Reviewed-on: https://chromium-review.googlesource.com/c/1273339 Reviewed-by: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Commit-Queue: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Cr-Commit-Position: refs/heads/master@{#598298} [modify] https://crrev.com/ba688e0187826d1ba43799dea76bb0eea45e8008/DEPS
,
Oct 10
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/973cf57b1f0da5d6833b680b0b8efe8c6337eed6 commit 973cf57b1f0da5d6833b680b0b8efe8c6337eed6 Author: Egor Pasko <pasko@chromium.org> Date: Wed Oct 10 15:25:24 2018 startup.mobile benchmark: enable atrace temporarily I am investigating occasional startup delays in 2nd runs (see the bug). The extra systrace information may help. Currently traces merged like this cannot compute messageloop_start_time. This problem is addressed in the catapult-side change: https://chromium-review.googlesource.com/c/catapult/+/1270856 Bug: 891797 Change-Id: I70434fdd627101b29a720c3deca988e3c2318049 Reviewed-on: https://chromium-review.googlesource.com/c/1264543 Reviewed-by: Egor Pasko <pasko@chromium.org> Reviewed-by: Ned Nguyen <nednguyen@google.com> Commit-Queue: Egor Pasko <pasko@chromium.org> Cr-Commit-Position: refs/heads/master@{#598334} [modify] https://crrev.com/973cf57b1f0da5d6833b680b0b8efe8c6337eed6/tools/perf/benchmarks/startup_mobile.py
,
Oct 11
The first combined trace with a slow start arrived: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/intent_coldish_bbc_2018-10-11_00-20-15_3506.html Unfortunately, it displays the systrace information only on the 9th and 10th runs, while we need it on the 2nd run. The traceviewer also complains: "Import Warning: UserModelBuilder: TypeError: Cannot read property 'sliceGroup' of undefined" perezju, nednguyen: I guess this is not a known problem, your ideas on how to debug this would be useful :) Enabling systrace significantly regresses the metrics on Go devices (100ms on go-phone-1024 and 600ms on go-phone-512, both cold and warm), so I'll need to revert systrace soon.
,
Oct 11
Sounds like an issue with tracing? +benjhayden, any idea who would be able to help debug this?
,
Oct 11
,
Oct 11
One more trace with slow 2nd start, same problem: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/intent_coldish_bbc_2018-10-11_07-06-32_24900.html If we cannot fix it early next week, I'll just exclude the 2nd run from results, that's an easy workaround. But wait, on this trace (Start: "23,800.489 ms") the breakdown is: ChromeBrowserInitializer.preInflationStartup: 54ms setContentView(R.layout.main): 295ms (normally 80-90) toolbarContainerStub.inflate: 137ms (normally ~18) ToolbarControlContainer.initWithToolbar: 404ms (normally ~130) ChromeActivity.postInflationStartup: 152ms (normally ~35) total: 1042ms The CPUs are *not* totally idle, but it could be because they are busy collecting the systrace :) An alternative hypothesis is that it is some sort of bad interaction between loading native library and setContentView. But why always on the 2nd run?? We can check this by un-parallelizing the two, as we used to do before.
,
Oct 11
I opened the trace in #11 and ran this in dev console: $0.model_.importWarnings.filter(w=>w.showToUser)[0].message.stack
"TypeError: Cannot read property 'sliceGroup' of undefined
at Function.getMainThreadEvents
at getMainThreadEvents.next (<anonymous>)
at Function.getSortedMainThreadEventsByFrame
at collectLoadExpectationsForRenderer
at Object.findLoadExpectations
I suspect this recent CL:
https://chromium-review.googlesource.com/c/catapult/+/1257270
Maybe getMainThreadEvents should return early if !rendererHelper.mainThread.
,
Oct 12
,
Oct 12
> I opened the trace in #11 and ran this in dev console: > $0.model_.importWarnings.filter(w=>w.showToUser)[0].message.stack wow! lovely magic, thanks! though $0 is undefined for me, am I doing something wrong?
,
Oct 12
Following Ben's suggestion in the most straightforward possible way: https://chromium-review.googlesource.com/c/catapult/+/1278275 It does not eliminate the incorrect trace merge, however. Still no clue here.
,
Oct 12
#17: devtools defines $0 to be the current selected element in the Elements panel. In that example, I think I selected the timeline-track-view by right-clicking anywhere on the trace viewer and selecting Inspect, then hitting the left arrow a few times. $1 is the previously selected element, etc.
,
Oct 15
The following revision refers to this bug: https://chromium.googlesource.com/catapult/+/e302dcb5ab8ab13b0b4f5d5323641d08ff4fff6f commit e302dcb5ab8ab13b0b4f5d5323641d08ff4fff6f Author: Egor Pasko <pasko@chromium.org> Date: Mon Oct 15 22:14:16 2018 event_finder_util: skip renderer events when no mainThread In http://crbug.com/891797#11 there is a link to an example trace that complains with: "Import Warning: UserModelBuilder: TypeError: Cannot read property 'sliceGroup' of undefined". With this change the error goes away. Not sure how to test it properly though, but I'm OK landing this oneliner as is without tests. Bug: chromium:891797 Change-Id: I7046c48a8251b1378e8bb419deb41362c932a52a Reviewed-on: https://chromium-review.googlesource.com/c/1278275 Reviewed-by: Ben Hayden <benjhayden@chromium.org> Reviewed-by: Emily Hanley <eyaich@chromium.org> Commit-Queue: Egor Pasko <pasko@chromium.org> [modify] https://crrev.com/e302dcb5ab8ab13b0b4f5d5323641d08ff4fff6f/tracing/tracing/extras/chrome/event_finder_utils.html
,
Oct 16
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/e4b18306674979a2fffe59ae60e51320aa20ad6e commit e4b18306674979a2fffe59ae60e51320aa20ad6e Author: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Date: Tue Oct 16 05:59:06 2018 Roll src/third_party/catapult 2be20fdd2d70..88afab4ff0f0 (4 commits) https://chromium.googlesource.com/catapult.git/+log/2be20fdd2d70..88afab4ff0f0 git log 2be20fdd2d70..88afab4ff0f0 --date=short --no-merges --format='%ad %ae %s' 2018-10-15 benjhayden@chromium.org Add ReportCacheRequest for v2spa service worker 2018-10-15 pasko@chromium.org event_finder_util: skip renderer events when no mainThread 2018-10-15 chiniforooshan@chromium.org Telemetry: fix a bug in percentage_smooth 2018-10-15 dproy@chromium.org Fix top level scheduler task title Created with: gclient setdep -r src/third_party/catapult@88afab4ff0f0 The AutoRoll server is located here: https://autoroll.skia.org/r/catapult-autoroll Documentation for the AutoRoller is here: https://skia.googlesource.com/buildbot/+/master/autoroll/README.md If the roll is causing failures, please contact the current sheriff, who should be CC'd on the roll, and stop the roller if necessary. CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel BUG=chromium:891797, chromium:895096 , chromium:871204 , chromium:832651 TBR=sullivan@chromium.org Change-Id: I2a5a1b05066c3c5f10bbec768c0bd430c80e5fa4 Reviewed-on: https://chromium-review.googlesource.com/c/1282342 Reviewed-by: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Commit-Queue: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Cr-Commit-Position: refs/heads/master@{#599878} [modify] https://crrev.com/e4b18306674979a2fffe59ae60e51320aa20ad6e/DEPS
,
Oct 22
The following revision refers to this bug: https://chromium.googlesource.com/catapult/+/6292d2f5eb002433047a93c0f6832f1826179afd commit 6292d2f5eb002433047a93c0f6832f1826179afd Author: Egor Pasko <pasko@chromium.org> Date: Mon Oct 22 18:26:55 2018 androidStartupMetric: ignore the 2nd run With systrace not immediately helping (trace buffer too small), the analysis of the noise on the 2nd run starts taking more time that I anticipated. Shortcut: ignore the 2nd run in the metrics. Not proud of it. Bug: chromium:891797 Change-Id: I9eb7848715f68c73459f5895b7a0d343dc07eabb Reviewed-on: https://chromium-review.googlesource.com/c/1291371 Reviewed-by: Ben Hayden <benjhayden@chromium.org> Commit-Queue: Egor Pasko <pasko@chromium.org> [modify] https://crrev.com/6292d2f5eb002433047a93c0f6832f1826179afd/tracing/tracing/metrics/android_startup_metric_test.html [modify] https://crrev.com/6292d2f5eb002433047a93c0f6832f1826179afd/tracing/tracing/metrics/android_startup_metric.html
,
Oct 22
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/caa07154b402a1876ce3dc0b3a4f06dd397c9652 commit caa07154b402a1876ce3dc0b3a4f06dd397c9652 Author: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Date: Mon Oct 22 21:23:56 2018 Roll src/third_party/catapult 623a134fbd08..b145370ba063 (2 commits) https://chromium.googlesource.com/catapult.git/+log/623a134fbd08..b145370ba063 git log 623a134fbd08..b145370ba063 --date=short --no-merges --format='%ad %ae %s' 2018-10-22 Max) Gu [CpuFCP] Support CPU time FCP 2018-10-22 pasko@chromium.org androidStartupMetric: ignore the 2nd run Created with: gclient setdep -r src/third_party/catapult@b145370ba063 The AutoRoll server is located here: https://autoroll.skia.org/r/catapult-autoroll Documentation for the AutoRoller is here: https://skia.googlesource.com/buildbot/+/master/autoroll/README.md If the roll is causing failures, please contact the current sheriff, who should be CC'd on the roll, and stop the roller if necessary. CQ_INCLUDE_TRYBOTS=luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;luci.chromium.try:win_optional_gpu_tests_rel BUG=chromium:891797 TBR=sullivan@chromium.org Change-Id: If83ef19e92bf4dae24946252090007cdae728505 Reviewed-on: https://chromium-review.googlesource.com/c/1294709 Reviewed-by: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Commit-Queue: chromium-autoroll <chromium-autoroll@skia-public.iam.gserviceaccount.com> Cr-Commit-Position: refs/heads/master@{#601727} [modify] https://crrev.com/caa07154b402a1876ce3dc0b3a4f06dd397c9652/DEPS
,
Oct 29
With ignoring the 2nd run the noise got down to 10-40ms (stdev). The last trace that did not ignore those is at: https://console.developers.google.com/m/cloudstorage/b/chrome-telemetry-output/o/intent_coldish_bbc_2018-10-18_18-44-49_23846.html I am going to clean up the extra trace events that were added for this investigation.
,
Oct 30
,
Oct 30
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/43ad0f88fd17ccee1c03eeeebaf7dcb2b960f4ca commit 43ad0f88fd17ccee1c03eeeebaf7dcb2b960f4ca Author: Egor Pasko <pasko@chromium.org> Date: Tue Oct 30 14:04:30 2018 startup.mobile benchmark: disable systrace collection I enabled systrace in http://crrev.com/598334 as an attempt to find out why the 2nd startup (out of 10) is sometimes slow. The systrace probably did not have a buffer large enough for 10 startups, so I've got the data for the last ~2 startups. Asking Telemetry to enable a larger buffer was not trivial to plumb. Without the 2nd startup the noise levels are quite low (10-40ms on N5). Further investigations down the rabbit hole are probably not worth it. Cleaning up: back to disabled systrace collection. Bug: 891797 Change-Id: If57e2ec5a9527add1e281087c734d1244345eb4f Reviewed-on: https://chromium-review.googlesource.com/c/1305553 Reviewed-by: Juan Antonio Navarro PĆ©rez <perezju@chromium.org> Commit-Queue: Egor Pasko <pasko@chromium.org> Cr-Commit-Position: refs/heads/master@{#603885} [modify] https://crrev.com/43ad0f88fd17ccee1c03eeeebaf7dcb2b960f4ca/tools/perf/benchmarks/startup_mobile.py
,
Oct 30
The following revision refers to this bug: https://chromium.googlesource.com/chromium/src.git/+/a395bea87d4bb0392ec6e8d632b928fe2da3c56d commit a395bea87d4bb0392ec6e8d632b928fe2da3c56d Author: Egor Pasko <pasko@chromium.org> Date: Tue Oct 30 21:30:33 2018 Android startup: remove a few quick trace events In http://crrev.com/596588 a few events were introduced to find out where time is spent on occasional slow runs (see the bug for more details). Remove the trace events that have proven to be quick (not noticed to take more than 1 frame on N5). On the other hand, in a trace from comment http://crbug.com/891797#c24 we observed these durations for the second startup: * ProcessInitializationHandler.initializePreNative(): 15ms of wall time (11ms CPU time) * ChromeBrowserInitializer.preInflationStartup: 55ms Keeping these events for now to keep the traces more informative. Bug: 891797 Change-Id: I543502973d19d768a94bbc5bec0a1446cc4338c5 Reviewed-on: https://chromium-review.googlesource.com/c/1305557 Commit-Queue: Egor Pasko <pasko@chromium.org> Reviewed-by: Boris Sazonov <bsazonov@chromium.org> Reviewed-by: Yaron Friedman <yfriedman@chromium.org> Cr-Commit-Position: refs/heads/master@{#604019} [modify] https://crrev.com/a395bea87d4bb0392ec6e8d632b928fe2da3c56d/chrome/android/java/src/org/chromium/chrome/browser/ChromeStrictMode.java [modify] https://crrev.com/a395bea87d4bb0392ec6e8d632b928fe2da3c56d/chrome/android/java/src/org/chromium/chrome/browser/init/ChromeBrowserInitializer.java [modify] https://crrev.com/a395bea87d4bb0392ec6e8d632b928fe2da3c56d/components/signin/core/browser/android/java/src/org/chromium/components/signin/AccountManagerFacade.java
,
Nov 8
The metrics are now ignoring these unexplained outliers and the noise is lower than ever: https://chromeperf.appspot.com/report?sid=39315879ca04233d2896f6d5ba68ce41c6bd9c4e7ce2cd849f72342d2881a646&start_rev=1540940133&end_rev=1541664820 not closing since we still did not explain the outliers, but P3
,
Jan 11
Available, but no owner or component? Please find a component, as no one will ever find this without one. |
||||||||||
►
Sign in to add a comment |
||||||||||
Comment 1 by pasko@chromium.org
, Oct 3