1019037 - Loading the call log regressed from 3.5s to close to 9s

Status: RESOLVED FIXED

(Firefox OS Graveyard :: Gaia::Dialer, defect, P1)

Description

[Anthony Ricaud (:rik)]

First chunk: https://datazilla.mozilla.org/b2g/?branch=master&device=hamachi&range=7&test=Dialer/callLog_rendering_time_%3E_first-chunk-ready&app_list=communications/dialer&app=communications/dialer&gaia_rev=e57a57bf88ac30af&gecko_rev=d6fccb7c56a8&plot=avg

Call log ready: https://datazilla.mozilla.org/b2g/?branch=master&device=hamachi&range=30&test=Dialer/callLog_rendering_time_%3E_call-log-ready&app_list=communications/dialer&app=communications/dialer&gaia_rev=e57a57bf88ac30af&gecko_rev=d6fccb7c56a8&plot=avg

This may only be a change in the performance or marionette frameworks but this is really worrying. We need to know what happened in that interval.

Comment 1

[:Eli Perelman]

Gaia last-known-good: 59f7880
Gaia first-known-bad: e4d250f

---

It appears the location of the event dispatch has changed from where it is in master in relation to the above commits, to the point where the tests completely fail when I test locally on my Flame. Moving the event to a comparable location allows me to run the tests.

---

Gaia 59f7880

APP=communications/dialer make test-perf: Dialer/callLog rendering time > call-log-ready
Average: 235.13, All: 244.421, 235.130, 204.722, 284.896, 233.508

---

Gaia e4d250f

APP=communications/dialer make test-perf: Dialer/callLog rendering time > call-log-ready
Average: 1533.532, All: 1450.106, 1618.416, 1574.501, 1581.489, 1443.145

---

I can replicate the regression. Bisecting:

git bisect start e4d250f 59f7880
Bisecting: 7 revisions left to test after this (roughly 3 steps)
[cd0a5af834212a802c333bfa7839d2d40e5a21aa] Bug 1005751 - (Part VI) PerformanceTimer.PRINT_LOG = false

APP=communications/dialer make test-perf: Dialer/callLog rendering time > call-log-ready
Average: 230.710, All: 236.086, 248.383, 208.057, 246.825, 214.198

---

git bisect good
Bisecting: 4 revisions left to test after this (roughly 2 steps)
[2dabcaf728e8fd74c0d2959ad28dfe8e5dc5e9b2] Merge pull request #18697 from hfiguiere/bug846909-take3.5

APP=communications/dialer make test-perf: Dialer/callLog rendering time > call-log-ready
Average: 1577.058, All: 1495.710, 1573.661, 1544.285, 1715.974, 1555.658

---

git bisect bad
Bisecting: 0 revisions left to test after this (roughly 1 step)
[9b883e5ed10b3733d88091487e055a7e4458effe] Bug 846909 - Part 2: remove some debug messages. Use Object.defineProperty()

Average: 1538.765, All: 1524.714, 1486.328, 1565.120, 1568.846, 1548.815

---

git bisect bad
Bisecting: 0 revisions left to test after this (roughly 0 steps)
[1dce8bf8d01ad235d60f158771a8ee2377ffe6c9] Bug 846909 - Inject performance helper atom with marionette

Average: 1551.897, All: 1511.481, 1582.896, 1614.185, 1537.736, 1513.185

---


git bisect bad
1dce8bf8d01ad235d60f158771a8ee2377ffe6c9 is the first bad commit
commit 1dce8bf8d01ad235d60f158771a8ee2377ffe6c9
Author: Hubert Figuière <[e-mail]>
Date:   Fri Apr 25 12:56:37 2014 -0400

    Bug 846909 - Inject performance helper atom with marionette

:040000 040000 ffdc3f479a345b069cdc3ab251312e3c4552db2c ff9d19de75854385eeb87eef7ca88bace9961f3f M	apps
:040000 040000 4ebad4728e6468627ff5445fef2737f59d57e10e a84960978a737dc5d82b9d04da230e37b92d2d5e M	tests

---

Hub, do you have any insight into this? I don't see anything crazy in this commit that would cause a direct regression in the call log, could this merely be a consequence of the way this test is performed?

Comment 2

[Wesley Huang [:wesley_huang] (EPM) (NI me)]

triage: plus, for the performance is not good

Comment 3

[Hubert Figuiere [:hub]]

Yes I think what is wrong. It is not that we have gone slower, it is that we set the start time in a different place, and that's bad.

I will have a patch soon.

This came when reviewing bug 837668, which might be blocked by this.

Comment 4

[Hubert Figuiere [:hub]]

Attachment: Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/20252

Expect the timing to be so much slower. But this is much more accurate.

Comment 5

[:Eli Perelman]

Comment on attachment 8437254 [details] [review]
Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/20252

I think that is reasonable and makes perfect sense.

Comment 6

[Anthony Ricaud (:rik)]

This seems like a general problem for every performance test, choosing when to start measuring. Shouldn't we use a more generic name for that event?

Comment 7

[Hubert Figuiere [:hub]]

Rik, we can discuss that this week face to face. But I agree in principle.

Comment 8

[Hubert Figuiere [:hub]]

The main reason I didn't just dispatch a "start" event is because I didn't to make it possible to break the startup test when reaching a different code path.

Comment 9

[Hubert Figuiere [:hub]]

It should be noted that on hamachi I get this test at ~2000ms. This is a reset of the performance as it now closer to the reality.

Comment 10

[Etienne Segonzac (:etienne)]

Comment on attachment 8437254 [details] [review]
Link to Github pull-request: https://github.com/mozilla-b2g/gaia/pull/20252

small comment on github.


We'll probably have more generic tests for loading lists eventually, but right now I'm fine with using Eli's nomenclature for perf events applicable to all apps startup and specific names for everything else.

Comment 11

[Hubert Figuiere [:hub]]

Addressed comment

Merged.
https://github.com/mozilla-b2g/gaia/commit/e71325af679638b9e0c7df091554f0478e2f7cde

Comment 12

[Anthony Ricaud (:rik)]

FYI, Hub and I discussed IRL and I agree that we can't use a generic name. So my concern was addressed.

Comment 13

[Ryan VanderMeulen [:RyanVM]]

v2.0: https://github.com/mozilla-b2g/gaia/commit/b7d1aaed98b7b016545e61166e71e7a8ca9cb572