Telemetry: Initialize smoothness and thread_times metrics before page load, not after.

Telemetry: Initialize smoothness and thread_times metrics before page load, not after.

Currently both smoothness and thread_times initialize their metrics after page
load. This leads to a gap between the page load and the page actions starting.
This patch moves the initialization before the page load, thus eliminating the
gap. It is safe to do so because smoothness and thread_times require a page load
before each run (even when repeating the same page).

Note to perf sheriffs:
This patch is likely to cause performance numbers to worsen, because the browser is often more busy immediately after page load. If you get alerts related to this CL, feel free to ignore them. If there is a reference build for the bot, the number for the reference build should also change accordingly.

BUG=392895
Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=285297

Committed: https://src.chromium.org/viewvc/chrome?view=rev&revision=285616

[Dominik Grewe, 2014-07-14 14:43:01]

ptal

[Sami, 2014-07-14 14:51:10]

lgtm. Could you add a note to the perf sheriff in the description since this
could cause something that looks a lot like a regression, right?

[Dominik Grewe, 2014-07-14 15:07:15]

On 2014/07/14 14:51:10, Sami wrote:
> lgtm. Could you add a note to the perf sheriff in the description since this
> could cause something that looks a lot like a regression, right?

Yes, thanks for reminding me. I've updated the description.

[tonyg, 2014-07-14 16:10:16]

lgtm

https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
File tools/perf/measurements/smoothness.py (right):

https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
tools/perf/measurements/smoothness.py:26: self._power_metric.Start(page, tab)
Could we please keep this in WillRunAction. That way the page load won't be
included in the power measurement.

[Dominik Grewe, 2014-07-14 16:50:25]

https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
File tools/perf/measurements/smoothness.py (right):

https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
tools/perf/measurements/smoothness.py:26: self._power_metric.Start(page, tab)
On 2014/07/14 16:10:15, tonyg wrote:
> Could we please keep this in WillRunAction. That way the page load won't be
> included in the power measurement.

Doing that leads to a gap of about 500ms between page load and page actions
starting. Pretty much all of that time is spent in cpu_stats:
https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/metrics...

Is it safe to move that call to a separate initialization method that we can
call before page load?

[tonyg, 2014-07-14 17:06:07]

On 2014/07/14 16:50:25, Dominik Grewe wrote:
>
https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
> File tools/perf/measurements/smoothness.py (right):
> 
>
https://codereview.chromium.org/392613002/diff/1/tools/perf/measurements/smoo...
> tools/perf/measurements/smoothness.py:26: self._power_metric.Start(page, tab)
> On 2014/07/14 16:10:15, tonyg wrote:
> > Could we please keep this in WillRunAction. That way the page load won't be
> > included in the power measurement.
> 
> Doing that leads to a gap of about 500ms between page load and page actions
> starting. Pretty much all of that time is spent in cpu_stats:
>
https://code.google.com/p/chromium/codesearch#chromium/src/tools/perf/metrics...
> 
> Is it safe to move that call to a separate initialization method that we can
> call before page load?

Ah, makes sense. Thinking about this more, we're overlapping some of load with
scroll. So it seems reasonable to measure power for the whole thing. Please feel
free to land as-is.

[Dominik Grewe, 2014-07-15 09:06:51]

The CQ bit was checked by dominikg@chromium.org

[Dominik Grewe, 2014-07-15 09:06:52]

The CQ bit was unchecked by dominikg@chromium.org

[Dominik Grewe, 2014-07-17 10:34:00]

The CQ bit was checked by dominikg@chromium.org

[commit-bot: I haz the power, 2014-07-17 10:35:20]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/dominikg@chromium.org/392613002/1

[commit-bot: I haz the power, 2014-07-17 12:08:09]

FYI, CQ is re-trying this CL (attempt #1).
The failing builders are:
  linux_chromium_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/linux_chromium_rel/bu...)
  mac_chromium_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/mac_chromium_rel/buil...)
  win_chromium_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/win_chromium_rel/buil...)
  win_chromium_x64_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/win_chromium_x64_rel/...)

[commit-bot: I haz the power, 2014-07-17 12:29:10]

The CQ bit was unchecked by commit-bot@chromium.org

[commit-bot: I haz the power, 2014-07-17 12:29:11]

Try jobs failed on following builders:
  linux_chromium_rel on tryserver.chromium
(http://build.chromium.org/p/tryserver.chromium/builders/linux_chromium_rel/bu...)

[Dominik Grewe, 2014-07-18 11:20:13]

Two tests failed:

I fixed testSyntheticDelayConfiguration by calling WillNavigateToPage instead of
WillRunActions in the unit test.

testSmoothnessForPageWithNoGesture fails because it can't find the
Interaction.Gesture_ScrollAction/is_smooth event in the trace. We do call
console.time and console.timeEnd for that event, but only the timeEnd call seems
to show up in the trace (there's an event with 'ph = F' but no corresponding 'ph
= S').
Since we're now calling console.time (in SmoothnessController::Start) before
page navigation, could it be that we lose that event during the navigation
somehow?

[picksi, 2014-07-18 11:30:59]

Ponderings on the issue.

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
File tools/perf/measurements/smoothness_unittest.py (right):

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
tools/perf/measurements/smoothness_unittest.py:64:
measurement.WillNavigateToPage(test_page, tab)
Are we just moving this problem to somewhere else for a future developer to run
into? Is there other work being done in WillRunActions that we are now failing
to do (or will fail to do in the future as the code grows)? I can't think of an
easy solution here, as we are relying on an unexpected side effect of a function
(i.e. starting the metric stuff)... :)

[Dominik Grewe, 2014-07-18 16:10:51]

It seems like the first console.time is being discarded when we do a page
navigation. Thinking about it, we probably don't want to have the smoothness
trace event covering the page load. It should only cover the page actions.

So I've split the start method into SetUp (start the tracing etc) and Start
(start the interaction which calls console.time). SetUp is called at
WillNavigateToPage and Start is called at WillRunPageActions.
I've made a similar change to TimelineController which is used by the
thread_times measurement.

Ptal, thanks.

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
File tools/perf/measurements/smoothness_unittest.py (right):

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
tools/perf/measurements/smoothness_unittest.py:64:
measurement.WillNavigateToPage(test_page, tab)
On 2014/07/18 11:30:58, picksi wrote:
> Are we just moving this problem to somewhere else for a future developer to
run
> into? Is there other work being done in WillRunActions that we are now failing
> to do (or will fail to do in the future as the code grows)? I can't think of
an
> easy solution here, as we are relying on an unexpected side effect of a
function
> (i.e. starting the metric stuff)... :)

How about we call both? :) That's what's happening inside Telemetry and it means
we don't need to know what happens when. (And I need it for the test to pass in
my new patch set...)

[picksi, 2014-07-18 16:47:20]

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
File tools/perf/measurements/smoothness_unittest.py (right):

https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
tools/perf/measurements/smoothness_unittest.py:64:
measurement.WillNavigateToPage(test_page, tab)
Can it safely be doubly initialized without losing the data recorded between 1st
init and 2nd init?

Would it be too big and scary to make the whole thing lazily initialize, so it
gets initialized the first time it is used? Is there some sort of singleton at
the bottom of this?

[Dominik Grewe, 2014-07-18 17:13:50]

On 2014/07/18 16:47:20, picksi wrote:
>
https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
> File tools/perf/measurements/smoothness_unittest.py (right):
> 
>
https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
> tools/perf/measurements/smoothness_unittest.py:64:
> measurement.WillNavigateToPage(test_page, tab)
> Can it safely be doubly initialized without losing the data recorded between
1st
> init and 2nd init?

There's no double initialization. The two steps do different things.
WillNavigateToPage has be called before WillRunPageActions (as it currently is).

> 
> Would it be too big and scary to make the whole thing lazily initialize, so it
> gets initialized the first time it is used? Is there some sort of singleton at
> the bottom of this?

We could make the initialization lazy, but then we lose control over when the
initialization happens. We want to make sure that the initialization happens
before page load.

[Dominik Grewe, 2014-07-22 12:22:42]

On 2014/07/18 17:13:50, Dominik Grewe wrote:
> On 2014/07/18 16:47:20, picksi wrote:
> >
>
https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
> > File tools/perf/measurements/smoothness_unittest.py (right):
> > 
> >
>
https://codereview.chromium.org/392613002/diff/20001/tools/perf/measurements/...
> > tools/perf/measurements/smoothness_unittest.py:64:
> > measurement.WillNavigateToPage(test_page, tab)
> > Can it safely be doubly initialized without losing the data recorded between
> 1st
> > init and 2nd init?
> 
> There's no double initialization. The two steps do different things.
> WillNavigateToPage has be called before WillRunPageActions (as it currently
is).
> 
> > 
> > Would it be too big and scary to make the whole thing lazily initialize, so
it
> > gets initialized the first time it is used? Is there some sort of singleton
at
> > the bottom of this?
> 
> We could make the initialization lazy, but then we lose control over when the
> initialization happens. We want to make sure that the initialization happens
> before page load.

Any comments on this?

[picksi, 2014-07-22 13:07:30]

Yes, you're right!

[tonyg, 2014-07-24 14:50:31]

lgtm

[commit-bot: I haz the power, 2014-07-24 16:43:32]

Change committed as 285297

[tonyg, 2014-07-24 22:34:53]

A revert of this CL has been created in
https://codereview.chromium.org/419623002/ by tonyg@chromium.org.

The reason for reverting is: Breaks smoothness tests on N4 (at least) with no
frames error. Possible this is a legit perf regression? But reverting anyway to
green things up.

http://build.chromium.org/p/chromium.perf/builders/Android%20Nexus5%20Perf/bu....

[Dominik Grewe, 2014-07-25 12:35:07]

On 2014/07/24 22:34:53, tonyg wrote:
> A revert of this CL has been created in
> https://codereview.chromium.org/419623002/ by mailto:tonyg@chromium.org.
> 
> The reason for reverting is: Breaks smoothness tests on N4 (at least) with no
> frames error. Possible this is a legit perf regression? But reverting anyway
to
> green things up.
> 
>
http://build.chromium.org/p/chromium.perf/builders/Android%20Nexus5%20Perf/bu....

I've got a fix for the page that started failing here:
https://codereview.chromium.org/418133008/
Once that's landed, this CL should be safe to re-commit afaict.

[Dominik Grewe, 2014-07-25 17:43:16]

Re-committing because the fix has now landed
(https://codereview.chromium.org/418133008/)

[Dominik Grewe, 2014-07-25 17:43:20]

The CQ bit was checked by dominikg@chromium.org

[commit-bot: I haz the power, 2014-07-25 17:44:17]

CQ is trying da patch. Follow status at
 https://chromium-status.appspot.com/cq/dominikg@chromium.org/392613002/40001

[commit-bot: I haz the power, 2014-07-25 17:57:12]

Change committed as 285616