Closed Bug 817095 (Email-Startup) Opened 12 years ago Closed 11 years ago

[meta][Gaia::E-Mail] Long initial startup time for E-Mail app

Categories

(Firefox OS Graveyard :: Gaia::E-Mail, defect, P1)

Product:
Firefox OS Graveyard
Component:
Gaia::E-Mail
Platform:
All
Gonk (Firefox OS)
Type:
defect

Tracking

(Not tracked)

Status:
RESOLVED DUPLICATE of bug 892069

People

(Reporter: pla, Unassigned)

References

Details

(Keywords: meta, perf, Whiteboard: interaction, [BTG-1129] [c= s=2013.08.09])

Attachments

(1 file)

adb logcat output of Email Load latency. Please optimize time between “start of mail.js::Cards.pushCard()” to “end of email loading”
(deleted), text/plain
Details 
What makes it feel slow/broken?
It takes too long to startup the E-Mail app after a reset.  Currently ~9-11.5 seconds, or more.  David Clarke to provide more accurate, recent numbers.

Did it prevent you from doing what you wanted? Why?

How does this make you feel?

[ ]  :)  I feel happy about it
[ ]  :|  Meh
[X]  :(  I'm upset
[ ] >:O  I'm angry

Device: Original numbers from Unagi, Nov. 22 nightly.  David Clarke to get Otoro numbers.

Details:

B2G on Unagi:               9-11.5 seconds
Android ICS 4.0.4 on Otoro: 3 seconds

David Clarke to provide updated B2G on Otoro numbers.

Bonus: can you attach a video of the problem?
See metabug 814981
blocking-basecamp: --- → ?
OS: Mac OS X → Gonk (Firefox OS)
Hardware: x86 → All
We already have Bug 768697 for e-mail startup being slow, although it doesn't have  the cool emoticon scale.  We should probably close/dupe one of the bugs.
blocking-basecamp: ? → ---
Flags: needinfo?(gsvelto)
This is a full profiled run of the e-mail app starting up, it's on an Otoro using the latest sources available from this morning and it's with a single account configured (Yahoo mail).

http://people.mozilla.com/~bgirard/cleopatra/#report=64805c22e5ec5a6ecf0860a253e3b47de148b994

Total measured startup time is 6.5s. The major problem showing up is that there is a very long delay between the evaluation of message-cards.js and that of gaia-email-opt.js (>3s).

Unfortunately it's hard to tell what's going on and what is the cause of it but by looking at the specific functions been called we can get some hints. First of all there's a lot of Cairo activity (>800ms), both painting and compositing; so it seems that something very expensive is being drawn. Afterwards there is a very long delay (over 2s) where the main thread seems blocked in a lock. The backtrace doesn't show where unfortunately but I might try inspecting it with the debugger to figure out what's going on in there.

After this first phase gaia-email-opt.js is executed and it takes another ~570ms, followed by l10n.js taking 280ms.

I'll further investigate the long initial delay and come back with some extra data.
Flags: needinfo?(gsvelto)
(In reply to Gabriele Svelto [:gsvelto] from comment #2)

FWIW, it looks like the profile is using the wrong libxul symbols. JS::EvaluateString should not be calling into cairo directly without going through other symbols.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #3)
> FWIW, it looks like the profile is using the wrong libxul symbols.
> JS::EvaluateString should not be calling into cairo directly without going
> through other symbols.

The issue is that this is a pseudo-profile, we don't have native profiling working on B2G so some of the stack traces will look funny. The results have to be taken with a pinch of salt and verified every time.
(In reply to Gabriele Svelto [:gsvelto] from comment #4)
> (In reply to Jeff Muizelaar [:jrmuizel] from comment #3)
> > FWIW, it looks like the profile is using the wrong libxul symbols.
> > JS::EvaluateString should not be calling into cairo directly without going
> > through other symbols.
> 
> The issue is that this is a pseudo-profile, we don't have native profiling
> working on B2G so some of the stack traces will look funny. The results have
> to be taken with a pinch of salt and verified every time.

I understand that, but all calls to cairo should be happening under the PresShell::Paint label or javascript calling into Canvas. That isn't happening here which suggests that the symbols for the leaf nodes are wrong. There are many more examples of the wrong symbols in the profile. e.g GlyphBuffer::cairo_show_glyphs() does not call sweepCrossCompartmentWrappers, gfxContext::fill() does not call AffixMgr::parse_file() etc.

If you look at the profile on bug 819091 you will see that the leaf node symbols match up properly, which suggests that there is something wrong with your setup.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #5)
> I understand that, but all calls to cairo should be happening under the
> PresShell::Paint label or javascript calling into Canvas. That isn't
> happening here which suggests that the symbols for the leaf nodes are wrong.
> There are many more examples of the wrong symbols in the profile. e.g
> GlyphBuffer::cairo_show_glyphs() does not call
> sweepCrossCompartmentWrappers, gfxContext::fill() does not call
> AffixMgr::parse_file() etc.

I see, I may have had a broken setup at the time then. I'll redo the profile and double-check for the issues you have spotted.
Whiteboard: interaction → interaction, [FFOS_perf]
Assignee: nobody → bugmail
Assignee: bugmail → kgrandon
Keywords: meta
Summary: [Gaia::E-Mail] Long initial startup time for E-Mail app → [meta][Gaia::E-Mail] Long initial startup time for E-Mail app
Gabriele, do you still have time to profile that? Or at least to help Kevin get profiles and read them?
(In reply to Fabrice Desré [:fabrice] from comment #7)
> Gabriele, do you still have time to profile that? Or at least to help Kevin
> get profiles and read them?

Yes, I'm trying to get a bunch of patches through today and close a few bugs and then I'll be back to this. If this needs action before tomorrow however I won't be able to help.
Two objectives from speaking to Fabrice:

1) Remove the black screen at startup

2) Remove the blank list after the black screen (I'm not seeing a blank list, is this referring to the inbox with the 'loading messages' text? As this is a meta bug I can open separate bugs for these items.
(In reply to Kevin Grandon from comment #9)
> 2) Remove the blank list after the black screen (I'm not seeing a blank
> list, is this referring to the inbox with the 'loading messages' text? As
> this is a meta bug I can open separate bugs for these items.

This nets out to be bug 822882.  Patch should go up for review very soon; need to finish up unit tests.
Depends on: 835507
Depends on: 814271
Depends on: 814267
Depends on: 814257
I would have loved to re-run this in the profiler today and make a detailed breakdown of the startup time but with today's build my Otoro is almost unusable so I can't test (it reboots every couple of minutes due to an issue with rild). I'll post a follow up as soon as possible.
Here's a new profile of the e-mail app, unfortunately it's a bit hard to read as is, the relevant samples are between 6204 and 6717, that's the actual startup time i.e. ~5s.

http://people.mozilla.com/~bgirard/cleopatra/#report=aaf72ff941a5b5ead98d84f310dce6adfd098e96

Without native profiling unfortunately some parts of the profile are fairly hard to crack so I'll post a few follow ups in which I'll inspect manually the biggest timesinks:

- First of all we have 2s invocation of nsJSContext::EvaluateString(), this is split in ~800ms of native code which seems to be related to font processing and another long ~1200ms delay caused by a lock. I'll figure out what's going on in there by stepping inside the call with GDB and post a follow up shortly as this is the single biggest timesink we have and it's completely opaque to the profiler.

- 300ms are spent in a gaia-email-opt.js, a call to main() is triggered by a timeout in line 248, this in turn calls callDep(), this in turn calls main(), which calls callDep() and so on in a bunch of recursive calls. The code is a bit opaque to me but it seems to be loading properties of some kind, probably in a not very efficient way.

- Layout accounts for another ~300ms in total, followed by a very expensive painting operation of ~500ms. To make matters worse during this repainting we trigger the GC which accounts for another ~100ms of delay. I'll try to investigate what's consuming so much memory to see if we can save a bit there and get rid of that particular delay.

- Another issue is that painting seems to happen even before the main layout phase, it would be worth verifying if we're triggering spurious layout/draw cycles while setting up the app.

- Finally another significant chunk of time (~400ms) is spent in a stack of calls that begins with gaia-email-opts.js:handleMessage() which through a bunch of calls invokes common-mail.js::Cards.pushCard() which in turn triggers a very expensive uninterruptible layout event (~200ms).
(In reply to Gabriele Svelto [:gsvelto] from comment #12)
> Here's a new profile of the e-mail app, unfortunately it's a bit hard to
> read as is, the relevant samples are between 6204 and 6717, that's the
> actual startup time i.e. ~5s.
> 
> http://people.mozilla.com/~bgirard/cleopatra/
> #report=aaf72ff941a5b5ead98d84f310dce6adfd098e96

This profile still does not have correct libxul symbols.
(In reply to Jeff Muizelaar [:jrmuizel] from comment #13)
> This profile still does not have correct libxul symbols.

Yes, I noticed it while stepping through the calls with GDB, I'll re-profile with elfhack disabled, I think that's causing the problem. Long story short, the callstack regarding gaia-email-opt.js was misleading me, it seems to me that it's the sheer size of the JS source that's taking long to process.

As soon as my rebuild with elfhack disabled finishes I'll re-post the profile and the manual analysis of the gaia-email-opt.js part.
Here's a clean profile, disabling elfhack did the trick. Relevant samples are [3908, 4415]:

http://people.mozilla.com/~bgirard/cleopatra/#report=6e54c691510ca5bd0d203a8c5b59013f613c313b

The call to nsJSContext::EvaluateString() which parses gaia-email-opt.js is taking >1.8s and is responsible for the huge glob I was seeing in the previous profiles. With correct libxul symbols it's now far more clear that it's exercising the JS engine hard. I would say that our first priority would be to remove that thing from the critical path (and yes, it didn't have anything to do with fonts, sorry for the confusion there).

Looking at the other call stacks later on it seems to me that only part of that file is immediately needed for execution so it might be worth splitting it up into at least a few of the original sources it was made of and maybe minify it too.
Thanks for the profiling!

(In reply to Gabriele Svelto [:gsvelto] from comment #12)
> - 300ms are spent in a gaia-email-opt.js, a call to main() is triggered by a
> timeout in line 248, this in turn calls callDep(), this in turn calls
> main(), which calls callDep() and so on in a bunch of recursive calls. The
> code is a bit opaque to me but it seems to be loading properties of some
> kind, probably in a not very efficient way.

callDep is part of the almond AMD JS module loader.  Our copy lives at:
https://github.com/mozilla-b2g/gaia-email-libs-and-more/blob/master/deps/almond.js

The timeout is unnecessary and is due to how we invoke require() at the end of gaia-email-opt.js.  I'll file a bug and fix this in gaia-email-libs-and-more.  The patch looks like this:
-require(['mailapi/same-frame-setup'], function () {});
+require('mailapi/same-frame-setup');

I have filed https://github.com/jrburke/almond/issues/51 in almond about the choice of setTimeout(15) there even though we are no longer going to use that codepath.


> - Finally another significant chunk of time (~400ms) is spent in a stack of
> calls that begins with gaia-email-opts.js:handleMessage() which through a
> bunch of calls invokes common-mail.js::Cards.pushCard() which in turn
> triggers a very expensive uninterruptible layout event (~200ms).

Our card abstraction logic pokes clientWidth in a number of places to make sure animations actually happen, don't happen, or so that pre-rendering happens so that we don't have black portions of the screen during animation.  We might be being a little too aggressive about this in some cases like for immediate card display when we are starting from nothing.

The message list card also does some poking of clientHeight as messages are added to the list or removed.  Much of this may be happening after your profile, but we can probably deal with a lot of it through a combination of caching item height values (messages have homogeneous height right now) and/or using some absolute positioning in the list (as discussed on bug 796474) to avoid needing to apply fix-ups, or at least not as frequently.
(In reply to Andrew Sutherland (:asuth) from comment #16)
> The message list card also does some poking of clientHeight as messages are
> added to the list or removed.  Much of this may be happening after your
> profile [...]

Yes, I've analyzed only the part that gets you to the point where the app becomes responsive to user input (i.e. a black screen essentially). There's still a few seconds of activity afterwards before the application finally settles down but since it's already responding to user interaction I didn't consider it part of the startup phase.
gsvelto, you'll get much better data on startup if you apply https://bugzilla.mozilla.org/attachment.cgi?id=706602 .  That will limit the sample buffer to 10s though, so the window will be smaller.
Here's the callstack for the __futex_syscall3:
#0  __futex_syscall3 () at bionic/libc/arch-arm/bionic/atomics_arm.S:183
#1  0x40101254 in _normal_lock (mutex=0x41a8bba0) at bionic/libc/bionic/pthread.c:951
#2  pthread_mutex_lock (mutex=0x41a8bba0) at bionic/libc/bionic/pthread.c:1041
#3  0x415742c8 in PR_Lock (lock=0xfffffff5) at /home/jrmuizel/src/B2G/gecko/nsprpub/pr/src/pthreads/ptsynch.c:174
#4  0x40e78a5a in js::SourceCompressorThread::waitOnCompression (this=<value optimized out>) at /home/jrmuizel/src/B2G/gecko/js/src/jsscript.cpp:1004
#5  js::SourceCompressionToken::ensureReady (this=<value optimized out>) at /home/jrmuizel/src/B2G/gecko/js/src/jsscript.cpp:1184
#6  0x40ed88c0 in ~SourceCompressionToken (cx=0x0, scopeChain=..., callerFrame=0x43644e98, options=..., chars=0x44700008, length=1276722, source_=0x0, staticLevel=0) at /home/jrmuizel/src/B2G/gecko/js/src/jsscript.h:1154
#7  js::frontend::CompileScript (cx=0x0, scopeChain=..., callerFrame=0x43644e98, options=..., chars=0x44700008, length=1276722, source_=0x0, staticLevel=0) at /home/jrmuizel/src/B2G/gecko/js/src/frontend/BytecodeCompiler.cpp:249
#8  0x40dc6ea4 in JS::Evaluate (cx=0x42a5fbf0, obj=..., options=..., chars=0x0, length=1077758579, rval=0x0) at /home/jrmuizel/src/B2G/gecko/js/src/jsapi.cpp:5702
#9  0x40713476 in nsJSContext::EvaluateString (this=0x4353ee20, aScript=..., aScopeObject=0x43612040, aPrincipal=<value optimized out>, aOriginPrincipal=0x42bdb1c0, aURL=0x43eff0c8 "app://email.gaiamobile.org/js/ext/gaia-email-opt.js", aLineNo=1, aVersion=JSVERSION_1_8, aRetValue=0x0, aIsUndefined=0xbefced9f) at /home/jrmuizel/src/B2G/gecko/dom/base/nsJSEnvironment.cpp:1525

We're waiting for the compression to end. This seems a bit silly to me as we shouldn't ever need to wait for compression. Before compression is finished we should be able to use the existing uncompressed source to answer any toSource() queries.
Depends on: 836515
I made this profile with the NO_SOURCE patch; it's on a clean profile, the e-mail app had not been previously run, so it's a lot more obvious when startup has completed because there are no active daemon processes:
http://people.mozilla.com/~bgirard/cleopatra/#report=a1e82ffadf9949d3cb2b1c45584c49cb5b60ca09

The relevant time range seems to basically be [474, 742].  There are some little humps afterwards that seem to be some type of delayed paints or GCs that aren't tremendously interesting.

This is my first time having run the profiler against real hardware, so I might have screwed up somehow, like if I was supposed to put some stuff in my .userconfig before building gecko.  It's a mozilla-b2g18 from today.  I also applied the require() patch I mentioned in comment 16.
(In reply to Andrew Sutherland (:asuth) from comment #20)
> This is my first time having run the profiler against real hardware, so I
> might have screwed up somehow, like if I was supposed to put some stuff in
> my .userconfig before building gecko.

Your profile seems to be having the same issue mine had: to get proper symbols for native functions you will need to disable elfhack, clobber everything and re-run the profile. I don't know an easy way of doing it via .userconfig unfortunately. What you can do is add the following line:

ac_add_options --disable-elf-hack

At the end of gonk-misc/default-gecko-config, this will do the trick. You'll need to remove objdir-gecko and rebuild it afterwards.
Depends on: 837836
(In reply to Andrew Sutherland (:asuth) from comment #16)
> The message list card also does some poking of clientHeight as messages are
> added to the list or removed.  Much of this may be happening after your
> profile, but we can probably deal with a lot of it through a combination of
> caching item height values (messages have homogeneous height right now)
> and/or using some absolute positioning in the list (as discussed on bug
> 796474) to avoid needing to apply fix-ups, or at least not as frequently.

I've poked around with the profiler a bit more and the first long non-interruptible layout event (~170ms) is caused by message-cards.js:_hideSearchBoxByScrolling() which is poking searchBar.offsetHeight. Would it be possible to push that part ahead so that it happens after the layout has already happened and offsetHeight has already been calculated?
I saw the _hideSearchBoxByScrolling thing too.  Is it a wasted layout?  Which is to say, if you comment that call out, do we startup any faster, or does the layout just get deferred slightly but still takes the same amount of time?

It's worth noting that we used to not do the manual scrollTop poking.  Previously, the scroll region went under the header as well, so we could just use CSS with padding to make things work out right.  Unfortunately, this resulted in the header being a valid scroll initiation target.  We could approximate that by hard-coding the same 'rems' size and mapping it so we don't need to ask the layout engine about that.  Or if CSS has grown away to pre-set the scrollTop...?
Depends on: 837715
Are we taking some type of NO_SOURCE opt-in completely off the table (an option discussed in bug 836515)?  Per bug 837715 numbers, it still is responsible for 330ms of load time.  Even if we implement bug 814271 so we can completely avoid the load of un-needed things from the back-end, it still probably will amount to 200ms standing in the way of the user getting their new messages.
(In reply to Andrew Sutherland (:asuth) from comment #24)
> Per bug 837715 numbers, it still is
> responsible for 330ms of load time.

FWIW, the 330ms was on non-minified source. The minified number could be as low as half of that.
It's probably worth reprofiling this now that some of the improvements have landed.
Depends on: 837111
This is a fresh profile the relevant samples are [4563, 4893]:

http://people.mozilla.com/~bgirard/cleopatra/#report=7a953279ab5d1e8b13f1c374bc78a8ff1e03795f

The profile has changed quite a bit so I hope I'm calculating things right. The overall startup time seems to be ~3.16s, so almost 2s better than the last profile I took. The largest chunks of time are:

- the processing of gaia-email-opt.js which now takes ~1s (down from ~1.8s)

- the main() invocation in gaia-email-opt.js ~270ms (down from ~300ms in the last measurements, the reduction is small so it might be just a statistical error in the measurement)

- the invocation of Cards.pushCard() which takes 90ms for itself and causes the ~370ms sync reflow; on this topic I haven't tried Andrew's suggestion in comment 23 but I will ASAP to see if it makes a difference
I've commented out the relevant section in _hideSearchBoxByScrolling() and the reflow happens anyway, probably deliberately triggered by this:

https://github.com/mozilla-b2g/gaia/blob/master/apps/email/js/mail-common.js#L450

So as Andrew correctly guessed _hideSearchBoxByScrolling() only anticipates the layout a bit but overall startup time is unaffected.
Whiteboard: interaction, [FFOS_perf] → interaction, [FFOS_perf] [BTG-1129]
Severity: normal → blocker
Priority: -- → P1
blocking-b2g: --- → tef+
Last update is 3.16s on 2/16. What is current status?
I used following method for email load test.

1) I added email account after 1st time flashing device. 
2) I launched Email App and scrolled it to load all emails in inbox once
3) I rebooted device.
4) I launched email app and measured loading time.

Here is my observation:

1) Delay between touch down to mail-common.js _init() function (dalay is 4.5 seconds) :
       mail-common.js _init() function binds itself to listen different events like click , trasitionend etc to listen events in case of click or scroll.
    
       Here, we see that Email thread (thread id 471) is busy in allocating lots of GC Objects by calling TryNewGCObject function. 

2) Database Activity: 1st Database activity starts after 3.9 sec from touch down. Database performed series of operation. Total time spend in database is: 

61ms+52ms+132ms+17ms+8ms+485ms .  Here last delay step 485ms seems to me a major delay.

Email thread (id-471) calls database Transaction(), ObjectStore() and Run() method during these operation. But actual database operation is carried out in a different thread


2) Database Activity:
    1st Database activity starts after 3.9 sec from touch down. Database performed series of operation. Total time spend in database is: 

61ms+52ms+132ms+17ms+8ms+485ms .  Here last delay step 485ms seems to me a major delay. It is our major concern.

Email thread calls database Transaction(), ObjectStore() and Run() method during these operation. But actual database operation is carried out in a different thread
common-mail.js::Cards.pushCard() itself is taking 400ms to 500ms to complete . We also see 200ms delay between common-mail.js::Cards.pushCard() to updateMessageDom(). We also observe some database activity between these two.  

updateMessageDom() performes some CSS style rearrangement.  We also see time between updateMessageDom() to “end of loading” is 800ms to 1sec.  During this period, main mail Email thread calls CSS:ProcessRestyledFrames()  and CSS:ComputeStyleChange() multiple times and spend 400ms to 700ms. 

Can we optimize time period between “start of mail.js::Cards.pushCard()”  to “end of email loading” .  It is doing mostly html CSS works here and it is spending 1.5 sec to 1.9 sec here.
It's great that you're gathering this data.  Can you provide some details to help provide context:
- what hardware is this running on? unagi?
- what b2g branch/commit, what gaia branch/commit?  Note that only gaia/master has any of the results of our performance work so far.
- Are you using the gecko SPS profiler?  If so, what sample rate, and does your build have elfhack disabled to improve native symbols?
- Can you provide raw data like upload your profiles via cleopatra, etc?
Flags: needinfo?(tkundu)
(In reply to Tapas Kumar Kundu from comment #31)
> I used following method for email load test.
> 
> 1) I added email account after 1st time flashing device. 
> 2) I launched Email App and scrolled it to load all emails in inbox once
> 3) I rebooted device.
> 4) I launched email app and measured loading time.
> 
> Here is my observation:
> 
> 1) Delay between touch down to mail-common.js _init() function (dalay is 4.5
> seconds) :
>        mail-common.js _init() function binds itself to listen different
> events like click , trasitionend etc to listen events in case of click or
> scroll.
>     
>        Here, we see that Email thread (thread id 471) is busy in allocating
> lots of GC Objects by calling TryNewGCObject function. 
> 
> 2) Database Activity: 1st Database activity starts after 3.9 sec from touch
> down. Database performed series of operation. Total time spend in database
> is: 
> 
> 61ms+52ms+132ms+17ms+8ms+485ms .  Here last delay step 485ms seems to me a
> major delay.
> 
> Email thread (id-471) calls database Transaction(), ObjectStore() and Run()
> method during these operation. But actual database operation is carried out
> in a different thread
> 
> 
> 2) Database Activity:
>     1st Database activity starts after 3.9 sec from touch down. Database
> performed series of operation. Total time spend in database is: 
> 
> 61ms+52ms+132ms+17ms+8ms+485ms .  Here last delay step 485ms seems to me a
> major delay. It is our major concern.
> 
> Email thread calls database Transaction(), ObjectStore() and Run() method
> during these operation. But actual database operation is carried out in a
> different thread

Updates:

1) Delay between touch down to mail-common.js _init() function (dalay is 2.371 seconds) :
       Here, we see that Email thread (thread id 471) is busy in allocating lots of GC Objects by calling TryNewGCObject function. 

Can we optimize this 2.371 second delay ?

2) Database Activity:
    1st Database activity starts after 2.079 secs from touch down. Database performed series of operation. Total time spend in database is: 

49ms+32ms+897us+6ms+17ms+9ms+39ms+21ms+865us+75ms+49ms+13ms. We observed this delay for sqlite3_step, sqlite3_exec() function. 

Email thread calls database Transaction(), ObjectStore() and Run() method during these operation. But actual database operation (sqlite function calls) is carried out in a different thread.
Flags: needinfo?(tkundu)
(In reply to Andrew Sutherland (:asuth) from comment #33)
> It's great that you're gathering this data.  Can you provide some details to
> help provide context:
> - what hardware is this running on? unagi?
> - what b2g branch/commit, what gaia branch/commit?  Note that only
> gaia/master has any of the results of our performance work so far.
> - Are you using the gecko SPS profiler?  If so, what sample rate, and does
> your build have elfhack disabled to improve native symbols?
> - Can you provide raw data like upload your profiles via cleopatra, etc?

(In reply to Tapas Kumar Kundu from comment #32)
> common-mail.js::Cards.pushCard() itself is taking 400ms to 500ms to complete
> . We also see 200ms delay between common-mail.js::Cards.pushCard() to
> updateMessageDom(). We also observe some database activity between these
> two.  
> 
> updateMessageDom() performes some CSS style rearrangement.  We also see time
> between updateMessageDom() to “end of loading” is 800ms to 1sec.  During
> this period, main mail Email thread calls CSS:ProcessRestyledFrames()  and
> CSS:ComputeStyleChange() multiple times and spend 400ms to 700ms. 
> 
> Can we optimize time period between “start of mail.js::Cards.pushCard()”  to
> “end of email loading” .  It is doing mostly html CSS works here and it is
> spending 1.5 sec to 1.9 sec here.

We are still observing same delay.
(In reply to Andrew Sutherland (:asuth) from comment #33)
> It's great that you're gathering this data.  Can you provide some details to
> help provide context:
> - what hardware is this running on? unagi?
> - what b2g branch/commit, what gaia branch/commit?  Note that only
> gaia/master has any of the results of our performance work so far.
> - Are you using the gecko SPS profiler?  If so, what sample rate, and does
> your build have elfhack disabled to improve native symbols?
> - Can you provide raw data like upload your profiles via cleopatra, etc?

We are using QRD 7627a device. We are not using SPS profiler and cleopatra.
(In reply to Tapas Kumar Kundu from comment #36)
> (In reply to Andrew Sutherland (:asuth) from comment #33)
> > It's great that you're gathering this data.  Can you provide some details to
> > help provide context:
> > - what hardware is this running on? unagi?
> > - what b2g branch/commit, what gaia branch/commit?  Note that only
> > gaia/master has any of the results of our performance work so far.
> > - Are you using the gecko SPS profiler?  If so, what sample rate, and does
> > your build have elfhack disabled to improve native symbols?
> > - Can you provide raw data like upload your profiles via cleopatra, etc?
> 
> We are using QRD 7627a device. We are not using SPS profiler and cleopatra.

I don't know what a QRD 7627a device is, and googling it isn't proving very helpful.  It sounds like a development board?  Does use of the development board imply a specific debugging/profiling toolchain?

You are clearly getting your numbers from some type of tool.  Can the data provided by that tool be attached to the bug or posted on a website somewhere?
Here is output of logcat for my comments at https://bugzilla.mozilla.org/show_bug.cgi?id=817095#c35. I have not attached DB logs and GC New Object creation logs here.

This logs can be analyzed with my comment on https://bugzilla.mozilla.org/show_bug.cgi?id=817095#c35
(In reply to Andrew Sutherland (:asuth) from comment #37)
> (In reply to Tapas Kumar Kundu from comment #36)
> > (In reply to Andrew Sutherland (:asuth) from comment #33)
> > > It's great that you're gathering this data.  Can you provide some details to
> > > help provide context:
> > > - what hardware is this running on? unagi?
> > > - what b2g branch/commit, what gaia branch/commit?  Note that only
> > > gaia/master has any of the results of our performance work so far.
> > > - Are you using the gecko SPS profiler?  If so, what sample rate, and does
> > > your build have elfhack disabled to improve native symbols?
> > > - Can you provide raw data like upload your profiles via cleopatra, etc?
> > 
> > We are using QRD 7627a device. We are not using SPS profiler and cleopatra.
> 
> I don't know what a QRD 7627a device is, and googling it isn't proving very
> helpful.  It sounds like a development board?  Does use of the development
> board imply a specific debugging/profiling toolchain?
> 
> You are clearly getting your numbers from some type of tool.  Can the data
> provided by that tool be attached to the bug or posted on a website
> somewhere?

I attached adb logcat for this.
We need to get to a specific number and methodology before this can be considered a blocking bug.  It can't be fixed without clear success criteria.
Surya, can you share what you consider the success criteria for v1.0.1 here please?
Flags: needinfo?(suryanar)
Thank you for the logs!

From the logcat output it appears that printf's have been added to some paint and reflow methods to generate traces as well as some dump() calls in the JS which also amount to printf calls.  It is my understanding from cjones and others that these calls are distorting of performance information due to the stdout/logcat overhead.  (I was kind of hoping an ICE was being thrown at the problem...)

It seems like a mechanism like the SPS profiler which uses an in-memory buffer during sampling and can regurgitate the logs after the critical analysis period and/or provide stacks would be preferable.  I think the SPS mechanism can be used to generate trace-style logs as well since its synthetic stack frame pushing/popping can be changed to use that.
Also, the timestamps from the logcat seem to be operating at the default linux tick rate of 100 Hz which is not great resolution-wise for such log output.
I fully support Andrew's position on this one, please obtain profiling information via the SPS profiler. Native stack traces are not available but you can introduce your own sample points by using the SAMPLE_LABEL() macro (see https://mxr.mozilla.org/mozilla-central/source/tools/profiler/sps_sampler.h) to mark events for sample-based profiling or SAMPLE_MARKER() to poll on specific events (be careful with the latter as it may distort the profile when abused).

The default sample interval is 10ms, if you need finer granularity you can manually change the value of the PROFILE_DEFAULT_INTERVAL macro (for example to 1 for 1ms sampling):

https://mxr.mozilla.org/mozilla-central/source/tools/profiler/sps_sampler.h#179

As for the above using shorter intervals may alter the profile significantly (at 1ms granularity it can slow down the application by as much as 25% from what I could gather).
Assignee: kgrandon → bugmail
For Email app launch latency, the target is 2sec.
The latest measured value is 3.6sec.
Method of measurement.
- High speed camera is used to capture the frames at 240fps. The latency is measured as the time duration between the highlight of icon to Email App completely rendered the frame.

We don't use SPS profiler.
Flags: needinfo?(suryanar)
(In reply to Surya from comment #45)
> For Email app launch latency, the target is 2sec.
> The latest measured value is 3.6sec.

Is this with the printf/dump-instrumented build, or a standard optimized build?  And again, is this v1.0.1, v1-train, or gaia/master?
All our perf work is on v1.0.1 cause that's what we're shipping first.  This is with a standard build.
Alias: Email-Startup
Depends on: 852710
Setting needinfo for comment 46.

Bug 814257 is the only tef+ blocking bug here. If there are any other bugs that we need in order to meet our goal, they need to be nominated and marked as blocking.
Flags: needinfo?(suryanar)
(In reply to Andrew Sutherland (:asuth) from comment #46)
> (In reply to Surya from comment #45)
> > For Email app launch latency, the target is 2sec.
> > The latest measured value is 3.6sec.
> 
> Is this with the printf/dump-instrumented build, or a standard optimized
> build?  And again, is this v1.0.1, v1-train, or gaia/master?

(In reply to Michael Vines [:m1] [:evilmachines] from comment #47)
> All our perf work is on v1.0.1 cause that's what we're shipping first.  This
> is with a standard build.

Just to be perfectly clear, it's a standard optimized build with no printf/dump instrumentation, right?
We'll follow up in email to make sure we're able to repro your startup times. Clearing the needinfo.
Flags: needinfo?(suryanar)
We did the "big uplift" of Bug 851124 after the measurements in Comment 45 were done. So I think it would be fair to do the measurements again.

Also, I uplifted some other big changes today that won't likely improve the startup time but will improve the general responsiveness.
Surya - please retest and file a new bug with how much we're off of the target (if we still are). We'll consider this meta bug stale at this point.
blocking-b2g: tef+ → -
Flags: needinfo?(suryanar)
I will create a new bug with more details.
Blocks: 863988
Flags: needinfo?(suryanar)
Assignee: bugmail → nobody
Whiteboard: interaction, [FFOS_perf] [BTG-1129] → interaction, [FFOS_perf] [BTG-1129] c=
Whiteboard: interaction, [FFOS_perf] [BTG-1129] c= → interaction, [BTG-1129] [c= ]
Even though this is an earlier bug, marking as duplicate for 892069, which is marked fixed on gaia master. That bug included a final round of speedups and only loading the correct start card for activity actions, so startup should be now at acceptable levels.
Status: NEW → RESOLVED
Closed: 11 years ago
Resolution: --- → DUPLICATE
blocking-b2g: koi? → ---
Whiteboard: interaction, [BTG-1129] [c= ] → interaction, [BTG-1129] [c= s=2013.08.09]
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: