713780 - Performance : regression on performance startup between 12/12 and 12/13

Status: RESOLVED FIXED

(Firefox for Android Graveyard :: General, defect, P1)

Description

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

It seems like the regression between 12/12 to 12/13 is due to this change set.  I'm unsure exactly why.

[e-mail] – Mon Dec 12 06:17:41 2011 PST (compare: )List changeset URLsSelf-serve Build API

    73979783bac9
    Kartikaya Gupta – Bug 708683 - Improve JSON generation by using JSONStringer. r=pcwalton a=java-only
    4850eb9ce32a
    Kartikaya Gupta – Bug 708683 - Fix NaN viewport values. r=pcwalton


See the Chart at R/50 located here:
https://docs.google.com/spreadsheet/ccc?key=0Arku3jleCA0UdFNQdkpuWVZIbjBPQ1gxa3RldzF2b1E&hl=en_US#gid=29

Steps to reproduce the performance test can be found : https://etherpad.mozilla.org/fennec_perf_ts_take2

Comment 1

[Kartikaya Gupta (email:[e-mail])]

Ok, so I've been looking at the data on that chart and I'm a little confused. From what I understand, the chart consists of 7 data points, which are average load times. The averages are taken from different builds (according to the chronologically increasing timestamp values) in order to isolate the exact changeset that introduced a regression. However, the averages are also considering different page loads. The first two times (rows 50 and 60) are of "warm - local file - onload". The next one (row 80) is "warm - local network - onload", same as row 70, which is the 6th data point on the chart. And so on. The page being loaded (startup5 vs favorites2) is also different, and I can't make any sense of this.

I loaded the dec 12 and dec 13 nightlies on my Galaxy Tab and tried to reproduce the performance measurements, and I found that the dec 13 nightly loaded startup5.html significantly faster than the dec 12 nightly - dec 12 took avg=948.4ms and dec 13 took avg=601.9ms. So basically I found a performance improvement rather than a regression.

nhirata, could you please clarify how you isolated those two changes and what the data in the spreadsheet represents?

Comment 2

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

row 50, 60, 70, 80 were incorrect.  I have corrected them; I had duplicated a previous spreadsheet and tried to get the numbers in quick.  They are all run with the local file, startup5.html.  You will have to take into account to throw away the first value and run it multiple times as indicated in the directions found in  https://etherpad.mozilla.org/fennec_perf_ts_take2  

These values were taken on the nexus s, which I believe is a neon processor: http://www.arm.com/products/processors/cortex-a/cortex-a8.php; http://en.wikipedia.org/wiki/Nexus_S  That may make a difference in terms of time.

Comment 3

[Kartikaya Gupta (email:[e-mail])]

Thanks, the data makes a little more sense now. However I would still like to know which build corresponds to which changeset. Next to the fennec-11.0a1.en-US.android-arm_1323681138_12122011 cell, there is a note saying "Backed out in 50a9ea86cd44", which leads to me to believe that fennec-11.0a1.en-US.android-arm_1323681138_12122011 corresponds to dougt's changesets shown at https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=bcc015450e7a and therefore the fennec-11.0a1.en-US.android-arm_1323699498_12122011 corresponds to the backout changeset at https://hg.mozilla.org/mozilla-central/pushloghtml?changeset=50a9ea86cd44. This means one of the last two builds listed correspond to my changes, but the performance data indicates that both of those builds are faster than their respective previous builds.

So if anything, it seems like the regression was introduced *before* my changes. Please let me know if my analysis is incorrect.

It's just that I looked closely at the two changes and it seems unlikely to me that either of them would significantly impact load time - it's possible that the JSON stringification got a little slower, but as it's used very infrequently during browser startup and page load, it shouldn't really be noticeable.

Comment 4

[Naoki Hirata :nhirata (please use needinfo instead of cc)]

There are 2 pushes that I missed prior to dougt's pushes:
1323671178 - https://tbpl.mozilla.org/php/getParsedLog.php?id=7882664&tree=Firefox
1323680178 - https://tbpl.mozilla.org/php/getParsedLog.php?id=7883431&tree=Firefox

I'll check those out.

Comment 5

[Kartikaya Gupta (email:[e-mail])]

Thanks for updating the spreadsheet, the data makes sense now. Quick summary for my future self revisiting this bug:

Changeset 1e81f179adf2 had an average load time of 2598.3571428572
Changeset bcc015450e7a had an average load time of 2463.0714285714
Changeset 73979783bac9 had an average load time of 2661.4285714286

Between 1e81f179adf2 and 73979783bac9 there were a net of 4 patches that went in (of which two were mine). There were also 4 patches by dougt that went in and were reverted. Therefore the jump from 2598 -> 2661 must have been caused by those 4 patches. There is also the 2463 time from bcc015450e7a, which contains the 2 patches that weren't mine and dougt's 4 patches. So either my patches caused the regression, or it came from one of the other two and dougt's changes caused an improvement so big that it cancelled out the regression and still managed to improve performance.

I'll look at my patches again to see how they could impact startup page/load time.

Comment 6

[Kartikaya Gupta (email:[e-mail])]

So using the JSONStringer (as in 73979783bac9) takes about 3x the time as the old manual string method. I don't think it gets called that often during startup anymore (it used to be called more often before) but I can optimize it anyway.

Comment 7

[Brad Lassey [:blassey] (use needinfo?)]

why did we switch to JSONStringer?

Comment 8

[Kartikaya Gupta (email:[e-mail])]

(In reply to Brad Lassey [:blassey] from comment #7)
> why did we switch to JSONStringer?

Partly because the code was cleaner, and partly because it would catch attempts to serialize NaN earlier (on the Java side, rather than in browser.js).

I wrote a few different versions of this and compared them to the old way we were doing things. Using an appropriately-sized StringBuffer resulted in a slight speed gain, but using a simple JSONSerializer class (which is much simpler than JSONStringer) was still slow. This makes me think that most of the extra overhead is actually in function calls.

I'll have a patch up shortly with the StringBuffer version, which is faster than the original version we had.

Comment 9

[Kartikaya Gupta (email:[e-mail])]

Attachment: Remove JSONStringer for being slow

Comment 10

[Chris Lord [:cwiiis]]

Comment on attachment 589960 [details] [diff] [review]
Remove JSONStringer for being slow

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

Looks good, though is 128 characters enough? I count 114 characters needed for the viewport string without the numbers, then there are 9 numbers - leaving 14 characters for them. This leads me to think that the StringBuffer will always be expanded, would it make sense to make the initial size 256?

Comment 11

[Kartikaya Gupta (email:[e-mail])]

Good catch, changed to 256 on landing.

https://hg.mozilla.org/integration/mozilla-inbound/rev/88370023d850

Comment 12

[Ed Morley [:emorley]]

https://hg.mozilla.org/mozilla-central/rev/88370023d850

Comment 13

[Kartikaya Gupta (email:[e-mail])]

Comment on attachment 589960 [details] [diff] [review]
Remove JSONStringer for being slow

[Approval Request Comment]
Regression caused by (bug #): bug 708683
User impact if declined: performance regression
Testing completed (on m-c, etc.): on m-c
Risk to taking this patch (and alternatives if risky): minor risk that I screwed something up during JSON serialization, which would result in a corrupt viewport (gray screen instead of page). should have showed up pretty early if that were the case though.

Comment 14

[Alex Keybl [:akeybl]]

Comment on attachment 589960 [details] [diff] [review]
Remove JSONStringer for being slow

[Triage Comment]
Mobile only - approved for Aurora.

Comment 15

[Matt Brubeck (:mbrubeck)]

https://hg.mozilla.org/releases/mozilla-aurora/rev/b6715e9bb2d0