711201 - instrument when the throbber ends and when we're done painting for performance testing

Status: RESOLVED FIXED

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

Comment 1

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

Attachment: patch for throbber

Comment 2

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

Attachment: patch for painting

Comment 3

[Doug Turner (:dougt)]

Comment on attachment 591232 [details] [diff] [review]
patch for painting

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

::: mobile/android/base/gfx/GeckoSoftwareLayerClient.java
@@ +264,5 @@
>                  endTransaction(mTileLayer);
>              }
>          }
> +        Log.i(LOGTAG, "zerdatime " + SystemClock.uptimeMillis() + " - endDrawing");
> +

extra white space.  Do we only get one of these per page load?

Comment 4

[cmtalbert]

This looks pretty parseable.  I'm parsing for the GeckoToolbar logtag with zerdatime in it, right?  Building now to see how it works in practice, but that's as parsable as anything else.

Seems to be what other things are using on android for this kind of stuff.

Comment 5

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

I was thinking you'd key on "- Throbber start" and "- Throbber stop"

Comment 6

[cmtalbert]

Attachment: logcat sample

Yeah I could do that when just pulling out the throbber points.  I was thinking about a way to pull all the timing lines that I might care about so I could verify what order they are happening in.  

So, I have a question here now that I've run it.  I ran 
am start -a android.intent.action.VIEW -n org.mozilla.fennec_ctalbert/.App -d http://www.mozilla.org

And I got the attached file.

You can see the following:
* Throbber start line 137
* Throbber stop line 317
* endDrawing happens between throbber start and stop several times, see lines 148, 152, 154, 179, 181, 260, 261, 262, 264, 265, 313.
* endDrawing happens outside of throbber stop at line 343 and 344.
Which of these endDrawing lines am I supposed to count?

Comment 7

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

(In reply to Clint Talbert ( :ctalbert ) from comment #6)
> Created attachment 591640 [details]
> logcat sample
> 
> Yeah I could do that when just pulling out the throbber points.  I was
> thinking about a way to pull all the timing lines that I might care about so
> I could verify what order they are happening in.  
> 
> So, I have a question here now that I've run it.  I ran 
> am start -a android.intent.action.VIEW -n org.mozilla.fennec_ctalbert/.App
> -d http://www.mozilla.org
> 
> And I got the attached file.
> 
> You can see the following:
> * Throbber start line 137
> * Throbber stop line 317
> * endDrawing happens between throbber start and stop several times, see
> lines 148, 152, 154, 179, 181, 260, 261, 262, 264, 265, 313.
> * endDrawing happens outside of throbber stop at line 343 and 344.
> Which of these endDrawing lines am I supposed to count?

the last one. When we discussed this about a month ago, I said it was going to be hard for Fennec to know when the page is done painting. Instead the automation should wait until it hasn't seen an endDrawing message for some time out (~5s) and then use the last one it saw.

Comment 8

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

https://hg.mozilla.org/integration/mozilla-inbound/rev/5aadcbb1dfce
https://hg.mozilla.org/integration/mozilla-inbound/rev/218a7935768b

Comment 9

[cmtalbert]

(In reply to Brad Lassey [:blassey] from comment #7)
> the last one. When we discussed this about a month ago, I said it was going
> to be hard for Fennec to know when the page is done painting. Instead the
> automation should wait until it hasn't seen an endDrawing message for some
> time out (~5s) and then use the last one it saw.
That should be pretty simple.  I do remember this discussion now that you remind me of it.  Thanks.

Comment 10

[Marco Bonardo [:mak]]

https://hg.mozilla.org/mozilla-central/rev/218a7935768b
https://hg.mozilla.org/mozilla-central/rev/5aadcbb1dfce

Comment 11

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

Comment on attachment 591225 [details] [diff] [review]
patch for throbber

[Approval Request Comment]
Regression caused by (bug #): 
User impact if declined: 
no user impact, this is for performance testing
Testing completed (on m-c, etc.): 
Risk to taking this patch (and alternatives if risky):
its just logging

Comment 12

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

Comment on attachment 591232 [details] [diff] [review]
patch for painting

[Approval Request Comment]
Regression caused by (bug #): 
User impact if declined: 
no user impact, this is for performance testing
Testing completed (on m-c, etc.): 
Risk to taking this patch (and alternatives if risky):
its just logging

Comment 13

[Alex Keybl [:akeybl]]

Comment on attachment 591225 [details] [diff] [review]
patch for throbber

[Triage Comment]
Mobile only - approved for Aurora.

Comment 14

[Alex Keybl [:akeybl]]

Comment on attachment 591232 [details] [diff] [review]
patch for painting

[Triage Comment]
Mobile only - approved for Aurora.

Comment 15

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

https://hg.mozilla.org/releases/mozilla-aurora/rev/1e3863b4cf08

landed the throbber instrumentation, leaving status-11 as affected for the paint patch

Comment 16

[cmtalbert]

(In reply to Brad Lassey [:blassey] from comment #15)
> https://hg.mozilla.org/releases/mozilla-aurora/rev/1e3863b4cf08
> 
> landed the throbber instrumentation, leaving status-11 as affected for the
> paint patch

Is the paint patch going to land on aurora as well? Now that I have the graphs working, I'd love to do metrics for aurora as well.