Closed Bug 1214810 Opened 4 years ago Closed 4 years ago

Provide a consistent logcat message determining Fennec start time.

Categories

(Firefox for Android :: General, enhancement)

enhancement
Not set

Tracking

()

RESOLVED FIXED
Firefox 45
Tracking Status
firefox44 --- affected
firefox45 --- fixed
firefox46 --- fixed

People

(Reporter: bc, Unassigned)

References

Details

Attachments

(3 files, 1 obsolete file)

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.
Flags: needinfo?(snorp)
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.
Attachment #8689818 - Flags: review?(droeh) → review+
Blocks: 1227188
https://hg.mozilla.org/mozilla-central/rev/db9e19d4bbb9
Status: NEW → RESOLVED
Closed: 4 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 45
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
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" ?
Flags: needinfo?(snorp)
Flags: needinfo?(droeh)
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.
Flags: needinfo?(snorp)
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
Flags: needinfo?(droeh)
Attachment #8695307 - Flags: review?(esawin) → review+
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. ;-)
Flags: needinfo?(snorp)
Rebased on m-c.
Attachment #8695307 - Attachment is obsolete: true
Flags: needinfo?(snorp)
Attachment #8699200 - Flags: review+
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!
https://hg.mozilla.org/mozilla-central/rev/1ab40d49b272
Status: REOPENED → RESOLVED
Closed: 4 years ago4 years ago
Resolution: --- → FIXED
You need to log in before you can comment on or make changes to this bug.