Significant regressions in Web Notification click-to-page time on Android for cold startup |
|||||
Issue description
We have significantly regressed on click-to-page time for clicks on Web Notifications on Android.
The following snippet is logcat output when clicking on a notification in a ToT build:
15:47:17.243 31246 31246 I NotificationService: Received a notification intent in the NotificationService's receiver.
15:47:18.138 31246 31246 I cr_LibraryLoader: Time to load native libraries: 850 ms (timestamps 6096-6946)
15:47:18.138 31246 31246 I cr_LibraryLoader: Expected native library version number "51.0.2695.0", actual native library version number "51.0.2695.0"
15:47:18.587 31246 31279 I chromium: [INFO:notification_event_dispatcher_impl.cc(104)] Trying to dispatch notification for SW with status: 0
15:47:18.990 31284 31284 I cr_ChildProcessService: Creating new ChildProcessService pid=31284
15:47:19.182 31307 31307 I cr_ChildProcessService: Creating new ChildProcessService pid=31307
15:47:20.828 31284 31323 I cr_LibraryLoader: Time to load native libraries: 1810 ms (timestamps 7826-9636)
15:47:21.031 31307 31324 I cr_LibraryLoader: Time to load native libraries: 1779 ms (timestamps 8052-9831)
15:47:21.284 31246 31279 I chromium: [INFO:notification_event_dispatcher_impl.cc(53)] The notification event has finished: 0
15:47:21.308 934 30620 I ActivityManager: START u0 {act=android.intent.action.VIEW dat=https://tests.peter.sh/... flg=0x10000000 pkg=org.chromium.chrome cmp=org.chromium.chrome/.browser.document.ChromeLauncherActivity (has extras)} from uid 10123 on display 0
15:47:21.837 31246 31246 D StrictMode: StrictMode policy violation; ~duration=308 ms: android.os.StrictMode$StrictModeDiskReadViolation: policy=17891359 violation=2
15:47:21.837 31246 31246 D StrictMode: StrictMode policy violation; ~duration=304 ms: android.os.StrictMode$StrictModeDiskReadViolation: policy=17891359 violation=2
15:47:22.022 31336 31336 I cr_ChildProcessService: Creating new ChildProcessService pid=31336
15:47:23.070 31336 31356 I cr_LibraryLoader: Time to load native libraries: 879 ms (timestamps 999-1878)
Summarized:
- It takes ~850ms to load the native library on click.
- We then create two child processes.
- (1) for the Service Worker. Takes 1810ms to load the native libraries.
- (2) seems to be unused? Takes 1779ms to load the native libraries.
- The `notificationclick` event is done dispatching after four seconds. An intent has been fired to open a window.
- Two strict mode violations occur, each taking ~300ms. Related to shared preferences.
- Another child process has been created. Takes 879ms to load the native libraries.
- Six seconds after clicking on the notification, the window has been opened.
This is terribly long, and visibly degrades the user experience. I get similar times on Android N and M, on a Nexus 5X, 6, and 6P, as well as debug and release builds.
,
Mar 31 2016
,
Apr 1 2016
I can confirm it takes ~6 seconds on a Nexus 5X running a local debug ChromePublic.apk Looking at it with Primiano, it seems suspicious that a regular launch from the home screen is much faster (e.g. 2x, 3x faster for loading the native library) than launching from a notification. Could there be a prioritization difference?
,
Apr 1 2016
Both M49 stable and M50 beta seem fine, taking ~2 seconds. Stable launches a DocumentActivity, Beta a ChromeTabbedActivity. But that doesn't seem to matter for the time it takes. A local release build (which launched a ChromeTabbedActivity) takes ~6 seconds, just like the debug build.
,
Apr 1 2016
51.0.2673.0-arm-ChromeCanary.apk is the most recent build I could find that was working correctly, loading in ~2 seconds. That's from 10 March: crrev.com/380313
,
Apr 1 2016
Peter landed a fix for intent handling yesterday as revision 384292: https://codereview.chromium.org/1847573003/ 51.0.2696.0-arm-ChromeCanary.apk (revision 384437) includes that fix and is fast. My locally built ChromePublic.apk is slow, and basically on the same revision (384321). Could it be that only ChromePublic.apk is slow? In that case this is not a release blocker.
,
Apr 1 2016
A locally built clankium, release, at revision 384545 is also slow. Not sure what it is, but it seems something about the locally built ones is slow.
,
Apr 1 2016
I've been getting this for a while with facebook notifications, clicking on them can take forever (either up to a minute, or never at all) for chrome to launch.
,
Apr 1 2016
Chrome not opening at all is captured by Issue 534537 , but UMA shows that this is not a huge widespread issue. (Though it definitely is on the M-52 list.)
,
Apr 4 2016
,
Apr 5 2016
tldr: I don't think there is a regression here.
My local builds became equally fast to official builds when I built with an official configuration as well (not release). The slowness helped express the difference between the two use cases, detailed below.
I verified historical behavior on various historical builds, the oldest one is 45.0.2445.3 (Canary) from 1 July 2015. Nothing significant seems to have changed.
Cold start from homescreen logs (minimized):
04-04 18:41:32.647 897 3530 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x10200000 cmp=com.chrome.canary/com.google.android.apps.chrome.Main bnds=[435,1254][646,1507] (has extras)} from uid 10030 on display 0
04-04 18:41:32.724 897 4747 I ActivityManager: Start proc 11126:com.chrome.canary/u0a172 for activity com.chrome.canary/com.google.android.apps.chrome.Main
04-04 18:41:32.826 897 3527 I ActivityManager: START u0 {act=android.intent.action.MAIN cat=[android.intent.category.LAUNCHER] flg=0x14002000 cmp=com.chrome.canary/org.chromium.chrome.browser.ChromeTabbedActivity bnds=[435,1254][646,1507] (has extras)} from uid 10172 on display 0
04-04 18:41:33.090 11126 11142 I LibraryLoader: Time to load native libraries: 172 ms (timestamps 1491-1663)
04-04 18:41:33.128 897 12556 I ActivityManager: Start proc 11149:com.chrome.canary:sandboxed_process0/u0i122 for service com.chrome.canary/org.chromium.content.app.SandboxedProcessService0
04-04 18:41:33.267 897 928 I ActivityManager: Displayed com.chrome.canary/org.chromium.chrome.browser.ChromeTabbedActivity: +428ms (total +555ms)
04-04 18:41:33.482 897 3506 I ActivityManager: Start proc 11179:com.chrome.canary:privileged_process0/u0a172 for service com.chrome.canary/org.chromium.content.app.PrivilegedProcessService0
04-04 18:41:33.650 11179 11202 I LibraryLoader: Time to load native libraries: 60 ms (timestamps 2163-2223)
04-04 18:41:33.772 11149 11164 I LibraryLoader: Time to load native libraries: 62 ms (timestamps 2282-2344)
Cold start from notification logs (minimized):
04-04 18:31:18.828 3063 3063 D StatusBar: Clicked on content of 0|com.chrome.canary|-1|NotificationUIManager;https://tests.peter.sh/;1|10172
04-04 18:31:18.852 897 920 I ActivityManager: Start proc 10142:com.chrome.canary/u0a172 for broadcast com.chrome.canary/org.chromium.chrome.browser.notifications.NotificationService$Receiver
04-04 18:31:19.079 10142 10142 I LibraryLoader: Time to load native libraries: 113 ms (timestamps 7539-7652)
04-04 18:31:19.305 897 5771 I ActivityManager: Start proc 10181:com.chrome.canary:privileged_process0/u0a172 for service com.chrome.canary/org.chromium.content.app.PrivilegedProcessService0
04-04 18:31:19.531 897 4747 I ActivityManager: Start proc 10202:com.chrome.canary:sandboxed_process0/u0i117 for service com.chrome.canary/org.chromium.content.app.SandboxedProcessService0
04-04 18:31:19.857 10181 10215 I LibraryLoader: Time to load native libraries: 203 ms (timestamps 8226-8429)
04-04 18:31:19.911 10202 10217 I LibraryLoader: Time to load native libraries: 204 ms (timestamps 8279-8483)
04-04 18:31:20.110 897 4748 I ActivityManager: START u0 {act=android.intent.action.VIEW dat=document://125?https://tests.peter.sh/notification-generator/ flg=0x10082000 pkg=com.chrome.canary cmp=com.chrome.canary/org.chromium.chrome.browser.document.DocumentActivity (has extras)} from uid 10172 on display 0
04-04 18:31:20.258 897 3565 I ActivityManager: Start proc 10241:com.chrome.canary:sandboxed_process1/u0i118 for service com.chrome.canary/org.chromium.content.app.SandboxedProcessService1
04-04 18:31:20.357 897 928 I ActivityManager: Displayed com.chrome.canary/org.chromium.chrome.browser.document.DocumentActivity: +230ms
04-04 18:31:20.622 10241 10258 I LibraryLoader: Time to load native libraries: 61 ms (timestamps 9134-9195)
The times until ActivityManager displays something are as follows.
homescreen: 0.620 seconds
notification: 1.529 seconds
The time from notification click to seeing something happening on screen is longer because Chrome first launches and initialize 3 processes (browser, gpu, service worker renderer). Then the notificationclick event is fired on the worker, V8 runs the event handler script, and only then is the intent fired to display the site in the DocumentActivity, which fires up another renderer, presumably one fully configured for rendering the site.
In contrast, when launching from the homescreen, the ActivityManager displays the (blank) ChromeTabbedActivity before the gpu and renderer processes are fully initialized, and never launches a separate worker process.
I'll file a separate bug to follow up for optimizations, as I suspect there may be some options. If this takes 1.529 seconds on a Nexus 5X, it's probably kind of awful on older devices.
,
Apr 5 2016
I filed issue 600707 for exploring optimizations. |
|||||
►
Sign in to add a comment |
|||||
Comment 1 by miguelg@chromium.org
, Mar 30 2016