1214810 - Provide a consistent logcat message determining Fennec start time.

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, enhancement)

Description

[Bob Clary [:bc] (inactive)]

Attachment: autophone-nexus-one-1.txt (example logcat messages from Nexus One)

Autophone attempts to measure the performance of Fennec by loading pages and parsing the "absolute" Throbber start and Throbber stop messages from logcat to determine how long it takes to start loading a page and how long it takes to complete loading the page.

The relevant messages look like:

10-14 02:17:45.518 I/ActivityManager(  173): Starting: Intent { act=android.intent.action.VIEW dat=/sdcard/tests/autophone/TalosTest/initialize_profile.html flg=0x10000000 cmp=org.mozilla.fennec/.App (has extras) } from pid 1784
10-14 02:17:45.558 I/ActivityManager(  173): Start proc org.mozilla.fennec for activity org.mozilla.fennec/.App: pid=1792 uid=10047 gids={3003, 1015, 1006}
10-14 02:17:47.110 I/GeckoToolbarDisplayLayout( 1792): zerdatime 203122 - Throbber start
10-14 02:17:47.150 W/GeckoThread( 1792): zerdatime 203168 - runGecko
10-14 02:17:52.625 D/GeckoBrowser( 1792): zerdatime 1444814272642 - browser chrome startup finished.
10-14 02:17:54.887 I/GeckoToolbarDisplayLayout( 1792): zerdatime 210907 - Throbber stop

To make the "absolute" Throbber start and Throbber stop measurements meaningful, they need to be measured relative to the time when the browser was started (Start time). These "relative" Throbber start and Throbber stop times are the actual measurements we care about. However we don't have a specific message we can use to determine the Start time.

Note that the "Starting: Intent" and "Start proc org.mozilla.fennec" messages are not available on all devices. Even if the Starting and Start proc messages were available, the time between when we request the browser be started, and the times the system emits the corresponding logcat messages is not consistent.

zerdatime isn't useful since it is the device uptime in milliseconds and we don't have a zerdatime for the initial request to start the browser.

Currently, Autophone uses the logcat message times (e.g. 10-14 02:17:45.558) of messages instead of zerdatimes. If the Start proc fennec message is available, it will use that time as the start time. If the Start proc message is not available, it will use the logcat time of the first message which contains [Gg]ecko.

http://phonedash.mozilla.org/#/org.mozilla.fennec/throbberstart/local-blank/norejected/2015-10-07/2015-10-14/notcached/errorbars/standarderror/notry illustrates the noisy data we get for Throbber start. The noise is compounded by the fact that the relative Throbber start times are under 2 seconds and the variation hides the signal that the measurement has regressed.

If we could provide a consistent message from a meaningful place during start up that Autophone can use to determine the Start time, I think we can make Autophone's measurements more reliable.

Something like

10-14 02:17:45.558 I/GeckoWhatever( 1792): zerdatime 202000 - Browser start

would be great. This would also allow Autophone to start using the zerdatime instead of the logcat message time which will eliminate some variation on the order of 50ms and also eliminate the New Years problem when the logcat date changes from 12-31 23:59:59.999 to 01-01 00:00:00.000.

Comment 1

[James Willcox (:snorp) ([e-mail]) (he/him)]

Attachment: Add a message indicating that Gecko is ready on Android

Comment 2

[Dylan Roeh (:droeh) (he/him)]

Comment on attachment 8689818 [details] [diff] [review]
Add a message indicating that Gecko is ready on Android

Review of attachment 8689818 [details] [diff] [review]:
-----------------------------------------------------------------

Looks good to me.

Comment 3

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/db9e19d4bbb9

Comment 4

[Wes Kocher (:KWierso) (Not reading bugmail; email directly if needed)]

https://hg.mozilla.org/mozilla-central/rev/db9e19d4bbb9

Comment 5

[Bob Clary [:bc] (inactive)]

This doesn't quite do what we wanted. It appears that the Throbber start message consistently appears before the Gecko ready message. Example:

12-02 23:42:02.327 I/ActivityManager(  813): Start proc 3271:org.mozilla.fennec/u0a54 for activity org.mozilla.fennec/.App
12-02 23:42:03.137 I/GeckoToolbarDisplayLayout( 3271): zerdatime 117835 - Throbber start
12-02 23:42:05.248 W/GeckoThread( 3271): zerdatime 119945 - Gecko ready
12-02 23:42:05.694 I/GeckoToolbarDisplayLayout( 3271): zerdatime 120392 - Throbber stop

Comment 6

[Bob Clary [:bc] (inactive)]

I wonder if we have Throbber start and Gecko ready backwards? That is the current "Throbber start" should be the real start time while "Gecko ready" should be the new "Throbber start" ?

Comment 7

[James Willcox (:snorp) ([e-mail]) (he/him)]

Ah, that's because the throbber does actually start before gecko is up and running. We know we're going to load a page, so we show that feedback even before the page has started loading.

I think I misunderstood the point of this bug. You want to have a timestamp that shows when Fennec has started at all, right, not when Gecko is ready. Oops. I'll add another message for that.

Comment 8

[James Willcox (:snorp) ([e-mail]) (he/him)]

Attachment: Print a timestamp when Fennec is started

Comment 9

[Bob Clary [:bc] (inactive)]

snorp, can you refresh the patch ? Since bug 1107811 landed it no longer applies. I intended to run a quick test of my start detection before bugging you to land this. kthxbye. ;-)

Comment 10

[Eugen Sawin [:esawin]]

Attachment: Bug-1214810---Print-a-timestamp-when-Fennec-is-sta.patch

Rebased on m-c.

Comment 11

[Bob Clary [:bc] (inactive)]

fyi, i tested this and it seems to work fine. webapps emit two messages but i can ignore the second and don't consider that a problem. land ahoy!

Comment 12

[Pulsebot]

https://hg.mozilla.org/integration/mozilla-inbound/rev/1ab40d49b272

Comment 13

[Carsten Book [:Tomcat]]

https://hg.mozilla.org/mozilla-central/rev/1ab40d49b272