Last Comment Bug 721634 - Compare Startup times for Multi-Locale vs. Single Locale Builds
: Compare Startup times for Multi-Locale vs. Single Locale Builds
Status: RESOLVED FIXED
:
Product: Firefox for Android
Classification: Client Software
Component: General (show other bugs)
: 11 Branch
: ARM Android
: P1 normal (vote)
: Firefox 11
Assigned To: Naoki Hirata :nhirata (please use needinfo instead of cc)
:
:
Mentors:
Depends on: 721644
Blocks:
  Show dependency treegraph
 
Reported: 2012-01-26 21:38 PST by Erin Lancaster [:elan]
Modified: 2012-02-24 14:21 PST (History)
8 users (show)
See Also:
Crash Signature:
(edit)
QA Whiteboard:
Iteration: ---
Points: ---
Has Regression Range: ---
Has STR: ---
fixed
beta+


Attachments

Description Erin Lancaster [:elan] 2012-01-26 21:38:11 PST
We need to understand delta in start up time (% faster or slower) for single-locale compared to multi-locale apks.
Comment 1 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-26 21:51:36 PST
Yesterday, did not have Galaxy S to try to compare the data with.  
- Ran on G2 and Galaxy SII with the English local versus Multi pack; result : no major time difference (yesterday)
- Noticed that English local is 1 meg smaller than all localized builds in the l10n dir which is in turn 1 meg smaller than Multipack (today)
- Received Galaxy S Captivate today; issue with trying to get into the phone.

- Currently working on trying to root Galaxy S Captivate to make the video shooting easier/faster.  [It helps shave time and also tends to have more consistent numbers if it's automated]
Comment 2 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-26 23:14:19 PST
Details were talked about in the Browser Tech Meeting.

Update Status : 
- Galaxy S rooted.
- starting video capture and going to compare english vs spanish vs multi on Galaxy S

- note : twitter web page changed to output to log, logcat being captured for review purposes for the video; this allows for faster processing as I don't have to bother looking for the onload number.
Comment 3 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-27 00:20:39 PST
Ran into bug 721644 for the spanish build.
Comment 4 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-27 00:35:39 PST
Video capture for multi and en done; other single locale languages are blocked by bug 721644.  Importing videos.
Comment 5 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-27 09:13:03 PST
Data posted : https://docs.google.com/spreadsheet/ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4

About a 200 ms difference or so.  2 crashes occurred during video testing which need to be tracked down.  logcat of the run still available; on PTO today (house inspections), need to take care of some personal things so I'll try to get them when I get back home.  Also need to investigate if I had builds flipflopped for the G2 at some point.

Do we care about the numbers for the other single locale builds?
Comment 6 Axel Hecht [:Pike] 2012-01-27 09:34:08 PST
Yes, we should care about startup time of localized builds.
Comment 7 Tony Chung [:tchung] 2012-01-27 11:29:54 PST
(In reply to Naoki Hirata :nhirata from comment #5)
> Data posted :
> https://docs.google.com/spreadsheet/
> ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4
> 
> About a 200 ms difference or so.  2 crashes occurred during video testing
> which need to be tracked down.  logcat of the run still available; on PTO
> today (house inspections), need to take care of some personal things so I'll
> try to get them when I get back home.  Also need to investigate if I had
> builds flipflopped for the G2 at some point.
> 
> Do we care about the numbers for the other single locale builds?

The data shows the G2 single-locale build is overall slower than the G2 Multi-locale build.  is this really true? 

Also, is there a reason you didn't label the builds on both devices consistent in their graph color theme?
Comment 8 Doug Turner (:dougt) 2012-01-27 13:00:13 PST
right tony... this data doesn't make sense.

Also, why are you collecting data via video.  We added instrumentation to the builds that will produce the numbers you want.
Comment 9 Tony Chung [:tchung] 2012-01-27 16:45:23 PST
(In reply to Doug Turner (:dougt) from comment #8)
> right tony... this data doesn't make sense.
> 
> Also, why are you collecting data via video.  We added instrumentation to
> the builds that will produce the numbers you want.

Since there are some questions around the results of the G2, Naoki will double, and TRIPLE! check his results when he gets home later tonite.   Additionally, there's been engineering request to have results from automated performance runs, which he'll check against a rooted Motorola Droid Pro and a Nexus S.  

Stay tuned for more results posted in here and the comment 5 spreadsheet.
Comment 10 Alex Keybl [:akeybl] 2012-01-29 18:58:13 PST
(In reply to Tony Chung [:tchung] from comment #9)
> Stay tuned for more results posted in here and the comment 5 spreadsheet.

Any updates here?
Comment 11 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-30 09:13:00 PST
I need to borrow the G2 from kbrosnan; it does look like I had the builds switched.
Comment 12 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-30 15:00:25 PST
Based on today's build using the instrumentation:
https://docs.google.com/spreadsheet/ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4

I had the builds reversed in my video footage originally.
Note: the throbber time is calculated from throbber start to throbber stop, so it may very but should be roughly the same.
Comment 13 Tony Chung [:tchung] 2012-01-30 19:17:00 PST
Thanks Naoki for confirming those results.  Certainly makes more sense this way.   Doug, Brad, do you guys have what you need to resolve this issue?
Comment 14 Brad Lassey [:blassey] (use needinfo?) 2012-01-31 09:52:50 PST
(In reply to Naoki Hirata :nhirata from comment #12)
> Based on today's build using the instrumentation:
> https://docs.google.com/spreadsheet/
> ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4
> 
> I had the builds reversed in my video footage originally.
> Note: the throbber time is calculated from throbber start to throbber stop,
> so it may very but should be roughly the same.

can you just report the numbers in the bug please?
Comment 15 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-31 10:20:44 PST
(identifier)	Onload	Throbber	Paint
G2 Multi Native Nightly 1/30/2012	4730.82352941176	1779.11764705882	6094.47058823529
G2 Single-En Native Nightly 1/30/2012	4637.64705882353	1725.52941176471	6056.17647058824
G2 Single-ES Native Nightly 1/30/2012	4544.64705882353	1649.76470588235	5508.47058823529
Comment 16 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-31 11:03:36 PST
With Std dev.

(identifier)	Onload	Throbber	Paint
G2 Multi Native Nightly 1/30/2012	4730.82352941176	1779.11764705882	6094.47058823529
std dev	161.055206099538	180.431040273334	238.715080600037
G2 Single-En Native Nightly 1/30/2012	4637.64705882353	1725.52941176471	6056.17647058824
std dev	113.430012109048	61.0871484510642	288.165151279201
G2 Single-ES Native Nightly 1/30/2012	4544.64705882353	1649.76470588235	5508.47058823529
std dev	85.7772851462368	44.5119778988823	93.4024341539467
Comment 17 Tony Chung [:tchung] 2012-01-31 11:19:11 PST
(In reply to Brad Lassey [:blassey] from comment #14)
> (In reply to Naoki Hirata :nhirata from comment #12)
> > Based on today's build using the instrumentation:
> > https://docs.google.com/spreadsheet/
> > ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4
> > 
> > I had the builds reversed in my video footage originally.
> > Note: the throbber time is calculated from throbber start to throbber stop,
> > so it may very but should be roughly the same.
> 
> can you just report the numbers in the bug please?

Brad, you or anyone else could have done that.   the numbers are publically accessible in the spreadsheet by anyone.   It even includes extra analysis and observations that Naoki included that was not part of the original request.  

If there's any missing information, please ask.  otherwise, please dont require folks to add extra menial work.
Comment 18 Brad Lassey [:blassey] (use needinfo?) 2012-01-31 14:29:13 PST
(In reply to Tony Chung [:tchung] from comment #17)
> (In reply to Brad Lassey [:blassey] from comment #14)
> > (In reply to Naoki Hirata :nhirata from comment #12)
> > > Based on today's build using the instrumentation:
> > > https://docs.google.com/spreadsheet/
> > > ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc&hl=en_US#gid=4
> > > 
> > > I had the builds reversed in my video footage originally.
> > > Note: the throbber time is calculated from throbber start to throbber stop,
> > > so it may very but should be roughly the same.
> > 
> > can you just report the numbers in the bug please?
> 
> Brad, you or anyone else could have done that.   the numbers are publically
> accessible in the spreadsheet by anyone.   It even includes extra analysis
> and observations that Naoki included that was not part of the original
> request.  
> 
> If there's any missing information, please ask.  otherwise, please dont
> require folks to add extra menial work.

Tony, I've generally pushed back on putting data in google docs, which is why I asked for this to be reported in the bug and in the past have asked for things to be put in wikis and what not.
Comment 19 Brad Lassey [:blassey] (use needinfo?) 2012-01-31 14:55:11 PST
(In reply to Tony Chung [:tchung] from comment #17)
> Brad, you or anyone else could have done that.   the numbers are publically
> accessible in the spreadsheet by anyone.   It even includes extra analysis
> and observations that Naoki included that was not part of the original
> request.  

Also, no. There are bunch of numbers in the "Overview Data" sheet of that spread sheet. Which ones am I supposed to be looking at??? Summarizing in the bug would be very useful.

So, looking at this section of the data (reformatted to be readable):
Device	Lang Pack  Build      Onload   Throbber Paint
G2	Multi	   1/25/2012  4673.78  4325     5075
G2	Single-En  1/25/2012  4488.71  4211.11	4655.56

There is ~400ms hit in final paint and ~200ms hit in onload measurement, which looks to be statistically significant.

Also I should note that Naoki asked me on irc if onCreate is a good place to be measuring the start of start up time. Not knowing why he was asking I said it was a good approximation. Seeing now that he was asking for the purposes of comparing single vs. multilocale, it is a very poor approximation. Most of the hit we take from multilocale happens before onCreate gets called. Which of these numbers are tainted by that?
Comment 20 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-31 16:18:29 PST
Looking at the information in the log, I see what you mean.  Would starting from the start intent of fennec for the device work instead of onCreate?
Comment 21 Brad Lassey [:blassey] (use needinfo?) 2012-01-31 19:43:58 PST
(In reply to Naoki Hirata :nhirata from comment #20)
> Looking at the information in the log, I see what you mean.  Would starting
> from the start intent of fennec for the device work instead of onCreate?

Yup
Comment 22 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-01-31 23:28:17 PST
After stopping for a moment, I came to realize that the onload value should always include the hit from the multilocale regardless, because the value that is passed is taken from the start intent to the time of the onload value being pushed out to the log.  

Also, looking at Comment 19, that was from the 1/25/2012 build which was done on video.  The "start time" was calculated from the visual transition from the settings to fennec.  The value from the time of the throbber ending and the paint ending was subtracted from the "start time".  Having said that, I am not sure if I can say with confidence that the multilocale hit had happened at the visual transition or if it had happened prior to the transition.

I believe that the 1/27/2012 was the first build that includes the instrumentation in which values are past to the console, so they are nonvideo automations and have different calculations in terms of the throbber time and paint time.  I did make a mistake in using onstart (which is actually a worse than oncreate to use) as the "start time".  I had saved the builds to my computer and had tested out the droid pro, but the numbers for the paint does not look right so I am withholding the announcement of the values until I figure out why the numbers are looking odd.  I may have to retest again.
Comment 23 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-02-24 14:10:31 PST
It looks like I just forgot to update this bug.  The following shows the Single locale versus Multi locale numbers for 1/30/2012 build

https://docs.google.com/spreadsheet/ccc?key=0Arku3jleCA0UdE5OTGZLdXJCR3gwWjdqV3RTcmNvMGc#gid=4
Comment 24 Naoki Hirata :nhirata (please use needinfo instead of cc) 2012-02-24 14:21:43 PST
For those allergic to Google Docs/Spreadsheet:

Droid Pro - Build : 1/30/2012	
	onLoad 			Throbber			Page Paint	
multi	4110.76923076923	1597.30769230793	4968.84615384596
	62.7404094213528	44.1708512776252	76.2253743340281
	
es	4096.5625		1577.18749999981	4936.4666666667
	50.5581760615102	31.0874438749648	78.345267581271		

G2 - Native Nightly 1/30/2012

	Onload			Throbber		Paint
Multi 	4730.82352941176	1779.11764705882	6094.47058823529
	161.055206099538	180.431040273334	238.715080600037

En	4637.64705882353	1725.52941176471	6056.17647058824
	113.430012109048	61.0871484510642	288.165151279201

ES 	4544.64705882353	1649.76470588235	5508.47058823529
	85.7772851462368	44.5119778988823	93.4024341539467

Note You need to log in before you can comment on or make changes to this bug.