Add Histograms to Measure Time in BrowserMainRunnerImpl::Initialize

content/browser/browser_main_runner.cc

 // Copyright (c) 2012 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
 #include "content/public/browser/browser_main_runner.h"
 
 #include "base/base_switches.h"
 #include "base/command_line.h"
 #include "base/debug/leak_annotations.h"
 #include "base/logging.h"
 #include "base/metrics/histogram.h"
+#include "base/metrics/histogram_macros.h"
 #include "base/metrics/statistics_recorder.h"
 #include "base/profiler/scoped_profile.h"
 #include "base/profiler/scoped_tracker.h"
+#include "base/time/time.h"
 #include "base/trace_event/trace_event.h"
 #include "base/tracked_objects.h"
 #include "components/tracing/trace_config_file.h"
 #include "components/tracing/tracing_switches.h"
 #include "content/browser/browser_main_loop.h"
 #include "content/browser/browser_shutdown_profile_dumper.h"
 #include "content/browser/notification_service_impl.h"
 #include "content/public/browser/tracing_controller.h"
 #include "content/public/common/content_switches.h"
 #include "content/public/common/main_function_params.h"
@@ skipping 106 matching lines @@
  public:
   BrowserMainRunnerImpl()
       : initialization_started_(false), is_shutdown_(false) {}
 
   ~BrowserMainRunnerImpl() override {
     if (initialization_started_ && !is_shutdown_)
       Shutdown();
   }
 
   int Initialize(const MainFunctionParams& parameters) override {
+    SCOPED_UMA_HISTOGRAM_LONG_TIMER(
+        "Startup.BrowserMainRunnerImplInitializeLongTime");
+
     // TODO(vadimt, yiyaoliu): Remove all tracked_objects references below once
     // crbug.com/453640 is fixed.
     tracked_objects::ThreadData::InitializeThreadContext("CrBrowserMain");
     TRACK_SCOPED_REGION(
         "Startup", "BrowserMainRunnerImpl::Initialize");
     TRACE_EVENT0("startup", "BrowserMainRunnerImpl::Initialize");
 
     // On Android we normally initialize the browser in a series of UI thread
     // tasks. While this is happening a second request can come from the OS or
     // another application to start the browser. If this happens then we must
     // not run these parts of initialization twice.

[ncarter (slow), 2015/09/23 16:34:19]

This comment suggests that on Android, step2 might happen more than once. Will
that be a source of measurement bias in the step2 metrics? Similarly, for the
LongTime case, there may be more samples to that histogram than to the Step1
histogram? 

My best guess: this is probably uncommon and we can know for sure if we pay
attention to the relative sample counts for these histograms.

[robliao, 2015/09/23 16:55:13]

Agreed. My analysis currently excludes Android as we're focusing on desktop
startup performance. We can revisit when Android becomes more interesting to us.

     if (!initialization_started_) {
       initialization_started_ = true;
 
+      const base::TimeTicks start_time_step1 = base::TimeTicks::Now();
+
       SkGraphics::Init();
 
 #if !defined(OS_IOS)
       if (parameters.command_line.HasSwitch(switches::kWaitForDebugger))

[ncarter (slow), 2015/09/23 16:34:19]

FYI, this may skew the results (though I expect it to be a rare case, it could
explain a significant chunk of outlier samples).

[robliao, 2015/09/23 16:55:13]

Good catch. I agree with the analysis and if we have a debugger attached a
priori, that would also skew the results a bit. Given that the existing numbers
that capture a superset of this section are reasonable, I would also guess that
this instance is low.

It's certainly a tradeoff between code simplicity and absolute correctness. If
the numbers look wrong, we can revisit.

         base::debug::WaitForDebugger(60, true);
 #endif
 
 #if defined(OS_WIN)
       if (base::win::GetVersion() < base::win::VERSION_VISTA) {
         // When "Extend support of advanced text services to all programs"
         // (a.k.a. Cicero Unaware Application Support; CUAS) is enabled on
         // Windows XP and handwriting modules shipped with Office 2003 are
         // installed, "penjpn.dll" and "skchui.dll" will be loaded and then
         // crash unless a user installs Office 2003 SP3. To prevent these
@@ skipping 30 matching lines @@
 
       main_loop_->PreMainMessageLoopStart();
       main_loop_->MainMessageLoopStart();
       main_loop_->PostMainMessageLoopStart();
 
 // WARNING: If we get a WM_ENDSESSION, objects created on the stack here
 // are NOT deleted. If you need something to run during WM_ENDSESSION add it
 // to browser_shutdown::Shutdown or BrowserProcess::EndSession.
 
       ui::InitializeInputMethod();
+      UMA_HISTOGRAM_TIMES("Startup.BrowserMainRunnerImplInitializeStep1Time",
+                          base::TimeTicks::Now() - start_time_step1);
     }
+    const base::TimeTicks start_time_step2 = base::TimeTicks::Now();
     main_loop_->CreateStartupTasks();
     int result_code = main_loop_->GetResultCode();
     if (result_code > 0)
       return result_code;
 
+    UMA_HISTOGRAM_TIMES("Startup.BrowserMainRunnerImplInitializeStep2Time",
+                        base::TimeTicks::Now() - start_time_step2);
+
     // Return -1 to indicate no early termination.
     return -1;
   }
 
   int Run() override {
     DCHECK(initialization_started_);
     DCHECK(!is_shutdown_);
     main_loop_->RunMainMessageLoopParts();
     return main_loop_->GetResultCode();
   }
@@ skipping 92 matching lines @@
 BrowserMainRunner* BrowserMainRunner::Create() {
   return new BrowserMainRunnerImpl();
 }
 
 // static
 bool BrowserMainRunner::ExitedMainMessageLoop() {
   return g_exited_main_message_loop;
 }
 
 }  // namespace content