Add Startup Timing to CPM

Add Startup Timing to CPM

Add in support for timing chrome's startup and session restore times.

BUG=130212
TEST=Included


Committed: http://src.chromium.org/viewvc/chrome?view=rev&revision=150881

[Devlin, 2012-07-30 18:51:11]

When you have time :)
Comes after https://chromiumcodereview.appspot.com/10815079/  (unclean exits).

[Yoyo Zhou, 2012-07-31 09:57:32]

http://codereview.chromium.org/10834015/diff/8018/base/time.h
File base/time.h (right):

http://codereview.chromium.org/10834015/diff/8018/base/time.h#newcode85
base/time.h:85: bool is_null() const {
I'm not sure this is right. A delta of 0 could actually be valid (whereas a Time
of 0 is not).

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/chrome_brows...
File chrome/browser/chrome_browser_main.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/chrome_brows...
chrome/browser/chrome_browser_main.cc:1946:
startup_timer_->SignalStartupComplete(false);  // not normal startup.
Looks like this could go in the if (!run_message_loop_) at 1958.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/constants.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/constants.cc:59: "The startup time of unusual
startups measured in microseconds";
Be consistent here. If we only mean to include tests (and everywhere else, it
says tests), say tests.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/performance_monitor_browsertest.cc
(right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/performance_monitor_browsertest.cc:637: const
base::TimeDelta kMaxStartupTime = base::TimeDelta::FromMinutes(1);
Seems like you could put this in an anonymous namespace, since it's useful in
more than one test. Also, you could err on the conservative side and make this,
say, 1 hour. (Who knows if in the future, test timeouts might be longer?)

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/startup_timer.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.cc:84: total_pause_ =
base::TimeTicks::Now() - pause_started_;
If this = was += you could probably support more than one pause.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/startup_timer.h (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:26: bool
SignalStartupComplete(bool normal_startup);
This would be more understandable as an enum, since the choice is not "normal"
or "abnormal" but rather "normal" or "test".

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:29: // does not count towards
the total.
Please document the return values.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:50: void InsertStartupTime();
These names are vaguely confusing because "time" can mean both a point and a
duration. InsertElapsedStartupTime would be better because that disambiguates
time. I'd suggest a similar change for session restore time.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:87: // The singleton of this
class.
Use base/memory/singleton.h for this purpose.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/ui/startup/s...
File chrome/browser/ui/startup/startup_browser_creator_impl.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/ui/startup/s...
chrome/browser/ui/startup/startup_browser_creator_impl.cc:614: // Pause the
StartupTimer. Since the restore here is synchronous, we can
This comment doesn't make sense. Maybe "we can keep these two metrics separate"?

[Devlin, 2012-07-31 16:43:40]

http://codereview.chromium.org/10834015/diff/8018/base/time.h
File base/time.h (right):

http://codereview.chromium.org/10834015/diff/8018/base/time.h#newcode85
base/time.h:85: bool is_null() const {
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> I'm not sure this is right. A delta of 0 could actually be valid (whereas a
Time
> of 0 is not).

Oooh, good point. I was wondering why there wasn't already one of these... :)
Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/chrome_brows...
File chrome/browser/chrome_browser_main.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/chrome_brows...
chrome/browser/chrome_browser_main.cc:1946:
startup_timer_->SignalStartupComplete(false);  // not normal startup.
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> Looks like this could go in the if (!run_message_loop_) at 1958.

I thought the same thing, but the problem is that the test process itself is
considered a ui_task. So if we put the stop at 1958, we actually finish the test
process (i.e. get to the final ASSERTs) prior to inserting the startup time, and
the test will fail.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/constants.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/constants.cc:59: "The startup time of unusual
startups measured in microseconds";
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> Be consistent here. If we only mean to include tests (and everywhere else, it
> says tests), say tests.

Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/performance_monitor_browsertest.cc
(right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/performance_monitor_browsertest.cc:637: const
base::TimeDelta kMaxStartupTime = base::TimeDelta::FromMinutes(1);
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> Seems like you could put this in an anonymous namespace, since it's useful in
> more than one test. Also, you could err on the conservative side and make
this,
> say, 1 hour. (Who knows if in the future, test timeouts might be longer?)

Moved to anonymous namespace, but I'm not sure about putting it as an hour. I
see your reasoning, but all this test does is start the browser...I would think
that if the browser ever took even a minute to just start up, we would have a
problem, regardless of testing timeouts. I put it to three minutes to account
for extreme edge cases, but it seems to me that if we ever go longer than that,
we have a problem anyway, right? (If you still want this as an hour, I'll change
it - I just feel like the test is less powerful.)

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/startup_timer.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.cc:84: total_pause_ =
base::TimeTicks::Now() - pause_started_;
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> If this = was += you could probably support more than one pause.

D'oh! Meant to have that... Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
File chrome/browser/performance_monitor/startup_timer.h (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:26: bool
SignalStartupComplete(bool normal_startup);
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> This would be more understandable as an enum, since the choice is not "normal"
> or "abnormal" but rather "normal" or "test".

Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:29: // does not count towards
the total.
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> Please document the return values.

Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:50: void InsertStartupTime();
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> These names are vaguely confusing because "time" can mean both a point and a
> duration. InsertElapsedStartupTime would be better because that disambiguates
> time. I'd suggest a similar change for session restore time.

Done.

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/performance_...
chrome/browser/performance_monitor/startup_timer.h:87: // The singleton of this
class.
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> Use base/memory/singleton.h for this purpose.

And...sorry in advance for a long comment.

Pursuant to the header in base/memory/singleton.h, I opted for not using the
Singleton class (would link to code, but codesearch is refusing to cooperate).
It asks to please find another class that can govern the object's lifespan.
Since ChromeBrowserMainParts works for this purpose, I went with that approach,
rather than "adding another singleton to the mix" and leading to "buggy code and
spurious crashes" (perhaps a little exaggerated, but they have a point).

Also, take a look at StartupTimeBomb's implementation
(http://code.google.com/searchframe#OAMlx_jo-ck/src/chrome/browser/metrics/thr...).
This actually serves a somewhat similar purpose (so much so I was contemplating
combining the two classes, but they aren't quite similar enough). It is
constructed at the start of ChromeBrowserMainParts, keeps an eye on everything
to make sure it goes okay, is signaled at completion, and is then destructed at
destruction of ChromeBrowserMainParts.

Finally, I thought the reason we usually used base::Singleton was to avoid leaky
singletons (e.g. c/b/e/extension_error_reporter.*). If you look at how this one
(and StartupTimeBomb) are created, these don't actually leak - they just enforce
that there's only one in existence. They are still destructed like any other
data member of ChromeBrowserMainParts.

I'm still happy to make this a base::Singleton if it strikes you as better (I
don't have a strong opinion one way or the other - I would have made it a
base::Singleton, if not for the comment in the header), but I wanted to make
sure I explained my initial reasoning.

Okay, that's it :) Whew...

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/ui/startup/s...
File chrome/browser/ui/startup/startup_browser_creator_impl.cc (right):

http://codereview.chromium.org/10834015/diff/8018/chrome/browser/ui/startup/s...
chrome/browser/ui/startup/startup_browser_creator_impl.cc:614: // Pause the
StartupTimer. Since the restore here is synchronous, we can
On 2012/07/31 09:57:32, Yoyo Zhou wrote:
> This comment doesn't make sense. Maybe "we can keep these two metrics
separate"?

Done.

[Yoyo Zhou, 2012-08-02 11:33:34]

LGTM

http://codereview.chromium.org/10834015/diff/15005/chrome/browser/performance...
File chrome/browser/performance_monitor/performance_monitor_browsertest.cc
(right):

http://codereview.chromium.org/10834015/diff/15005/chrome/browser/performance...
chrome/browser/performance_monitor/performance_monitor_browsertest.cc:51:
namespace {
nit: newline after

[Devlin, 2012-08-07 16:12:57]

+ sky for c/b/, c/b/ui/, and c/b/sessions/

[sky, 2012-08-07 19:48:03]

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
File chrome/browser/sessions/session_restore.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
chrome/browser/sessions/session_restore.cc:444:
performance_monitor::StartupTimer::SetElapsedSessionRestoreTime(
What happens if this is invoked multiple times?

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
File chrome/browser/sessions/session_service.h (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
chrome/browser/sessions/session_service.h:61: friend class
performance_monitor::PerformanceMonitorSessionRestoreBrowserTest;
I don't want another friend class. Can you move what is needed into
SessionServiceTestHelper or another standalone class that is only built for
tests and is a friend and exposes whatever you need.

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ui/...
File chrome/browser/ui/startup/startup_browser_creator_impl.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ui/...
chrome/browser/ui/startup/startup_browser_creator_impl.cc:617:
DCHECK(performance_monitor::StartupTimer::PauseTimer());
This structure means PauseTimer isn't invoked in release builds. Is that
intentional?

[Devlin, 2012-08-07 22:51:22]

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/per...
File chrome/browser/performance_monitor/performance_monitor_browsertest.cc
(right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/per...
chrome/browser/performance_monitor/performance_monitor_browsertest.cc:51:
namespace {
On 2012/08/02 11:33:34, Yoyo Zhou wrote:
> nit: newline after

Done.

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
File chrome/browser/sessions/session_restore.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
chrome/browser/sessions/session_restore.cc:444:
performance_monitor::StartupTimer::SetElapsedSessionRestoreTime(
On 2012/08/07 19:48:04, sky wrote:
> What happens if this is invoked multiple times?

Whoops, forgot that session restores can happen multiple times in one startup if
the user has multiple profiles signed in. Now each restore time will be
recorded.

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
File chrome/browser/sessions/session_service.h (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ses...
chrome/browser/sessions/session_service.h:61: friend class
performance_monitor::PerformanceMonitorSessionRestoreBrowserTest;
On 2012/08/07 19:48:04, sky wrote:
> I don't want another friend class. Can you move what is needed into
> SessionServiceTestHelper or another standalone class that is only built for
> tests and is a friend and exposes whatever you need.

Done. Since SessionRestoreTest needed the same thing, also removed that friend
class.

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ui/...
File chrome/browser/ui/startup/startup_browser_creator_impl.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/15005/chrome/browser/ui/...
chrome/browser/ui/startup/startup_browser_creator_impl.cc:617:
DCHECK(performance_monitor::StartupTimer::PauseTimer());
On 2012/08/07 19:48:04, sky wrote:
> This structure means PauseTimer isn't invoked in release builds. Is that
> intentional?

D'oh! Was using that as a shortcut for "bool x = PauseTimer(); DCHECK(x)" and
forgot to undo it. Fixed; moved the DCHECKs to all be internal.

[sky, 2012-08-07 23:19:12]

LGTM

https://chromiumcodereview.appspot.com/10834015/diff/11007/chrome/browser/ses...
File chrome/browser/sessions/session_restore_browsertest.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/11007/chrome/browser/ses...
chrome/browser/sessions/session_restore_browsertest.cc:55: //
SessionServiceFactory::GetForProfile(browser()->profile())->
remove these two lines.

[commit-bot: I haz the power, 2012-08-08 17:24:20]

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

[commit-bot: I haz the power, 2012-08-08 19:45:02]

Try job failure for 10834015-16033 (retry) on win_rel for step "unit_tests".
It's a second try, previously, step "unit_tests" failed.
http://build.chromium.org/p/tryserver.chromium/buildstatus?builder=win_rel&nu...

[commit-bot: I haz the power, 2012-08-09 18:22:36]

CQ is trying da patch. Follow status at
https://chromium-status.appspot.com/cq/rdevlin.cronin@chromium.org/10834015/2...

[commit-bot: I haz the power, 2012-08-09 20:30:26]

Change committed as 150881

[Nico, 2012-08-10 01:27:58]

https://chromiumcodereview.appspot.com/10834015/diff/20016/chrome/browser/per...
File chrome/browser/performance_monitor/metric_details.cc (right):

https://chromiumcodereview.appspot.com/10834015/diff/20016/chrome/browser/per...
chrome/browser/performance_monitor/metric_details.cc:39: },
This adds a static initializer to chrome. Because our baseline was too high, the
bots didn't notice.

This is because kMetricStartupTimeName and friends are defined in another
translation unit and hence the compiler doesn't know their value when compiling
this file.