Add extra histogram latency tracking in PreMainMessageLoopRunImpl.

chrome/browser/chrome_browser_main.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 "chrome/browser/chrome_browser_main.h"
 
 #include <set>
 #include <string>
 #include <vector>
 
@@ skipping 1103 matching lines @@
       BrowserThread::UI,
       FROM_HERE,
       base::Bind(&WebRtcLogUtil::DeleteOldWebRtcLogFilesForAllProfiles),
       base::TimeDelta::FromMinutes(1));
 #endif
 }
 
 int ChromeBrowserMainParts::PreMainMessageLoopRunImpl() {
   TRACE_EVENT0("startup", "ChromeBrowserMainParts::PreMainMessageLoopRunImpl");
   SCOPED_UMA_HISTOGRAM_LONG_TIMER("Startup.PreMainMessageLoopRunImplLongTime");
+  const base::TimeTicks start_time_step1 = base::TimeTicks::Now();
   // Android updates the metrics service dynamically depending on whether the
   // application is in the foreground or not. Do not start here.
 #if !defined(OS_ANDROID)
   // Now that the file thread has been started, start recording.
   StartMetricsRecording();
 #endif
 
   if (!base::debug::BeingDebugged()) {
     // Create watchdog thread after creating all other threads because it will
     // watch the other threads and they must be running.
@@ skipping 152 matching lines @@
 #endif  // defined(OS_LINUX) && !defined(OS_CHROMEOS)
 
   // Desktop construction occurs here, (required before profile creation).
   PreProfileInit();
 
   // Profile creation ----------------------------------------------------------
 
   metrics::MetricsService::SetExecutionPhase(
       metrics::MetricsService::CREATE_PROFILE,
       g_browser_process->local_state());
+
+  UMA_HISTOGRAM_TIMES("Startup.PreMainMessageLoopRunImplStep1Time",
+                       base::TimeTicks::Now() - start_time_step1);
+
   profile_ = CreatePrimaryProfile(parameters(),

[Alexei Svitkine (slow), 2015/02/26 20:58:39]

Add a comment that this function is covered by a histogram, else it looks like a
bug that your histograms aren't covering it.

[rkaplow, 2015/02/28 20:09:47]

Done.

                                   user_data_dir_,
                                   parsed_command_line());
   if (!profile_)
     return content::RESULT_CODE_NORMAL_EXIT;
 
+  const base::TimeTicks start_time_step2 = base::TimeTicks::Now();
+
 #if !defined(OS_ANDROID)
   // The first run sentinel must be created after the process singleton was
   // grabbed and no early return paths were otherwise hit above.
   first_run::CreateSentinelIfNeeded();
 #endif  // !defined(OS_ANDROID)
 
 #if defined(ENABLE_BACKGROUND)
   // Autoload any profiles which are running background apps.
   // TODO(rlp): Do this on a separate thread. See http://crbug.com/99075.
   browser_process_->profile_manager()->AutoloadProfiles();
@@ skipping 227 matching lines @@
 #if defined(OS_CHROMEOS)
   // On ChromeOS multiple profiles doesn't apply, and will break if we load
   // them this early as the cryptohome hasn't yet been mounted (which happens
   // only once we log in.
   std::vector<Profile*> last_opened_profiles;
 #else
   std::vector<Profile*> last_opened_profiles =
       g_browser_process->profile_manager()->GetLastOpenedProfiles();
 #endif
 
-  if (browser_creator_->Start(parsed_command_line(), base::FilePath(),
-                              profile_, last_opened_profiles)) {
+  UMA_HISTOGRAM_TIMES("Startup.PreMainMessageLoopRunImplStep2Time",
+                       base::TimeTicks::Now() - start_time_step2);
+
+  bool started = browser_creator_->Start(parsed_command_line(),

[Alexei Svitkine (slow), 2015/02/26 20:58:40]

Ditto.

[rkaplow, 2015/02/28 20:09:47]

Done.

+                                         base::FilePath(),
+                                         profile_,
+                                         last_opened_profiles);
+  const base::TimeTicks start_time_step3 = base::TimeTicks::Now();
+  if (started) {
 #if defined(OS_WIN) || (defined(OS_LINUX) && !defined(OS_CHROMEOS))
     // Initialize autoupdate timer. Timer callback costs basically nothing
     // when browser is not in persistent mode, so it's OK to let it ride on
     // the main thread. This needs to be done here because we don't want
     // to start the timer when Chrome is run inside a test harness.
     browser_process_->StartAutoupdateTimer();
 #endif
 
 #if defined(OS_LINUX) && !defined(OS_CHROMEOS)
     // On Linux, the running exe will be updated if an upgrade becomes
@@ skipping 58 matching lines @@
     run_message_loop_ = false;
   }
 #if defined(OS_ANDROID)
   // We never run the C++ main loop on Android, since the UI thread message
   // loop is controlled by the OS, so this is as close as we can get to
   // the start of the main loop
   if (result_code_ <= 0) {
     RecordBrowserStartupTime();
   }
 #endif
+
+  UMA_HISTOGRAM_TIMES("Startup.PreMainMessageLoopRunImplStep3Time",
+                       base::TimeTicks::Now() - start_time_step3);
+
   return result_code_;
 }
 
 bool ChromeBrowserMainParts::MainMessageLoopRun(int* result_code) {
   TRACE_EVENT0("startup", "ChromeBrowserMainParts::MainMessageLoopRun");
 #if defined(OS_ANDROID)
   // Chrome on Android does not use default MessageLoop. It has its own
   // Android specific MessageLoop
   NOTREACHED();
   return true;
@@ skipping 91 matching lines @@
   chromeos::CrosSettings::Shutdown();
 #endif
 #endif
 }
 
 // Public members:
 
 void ChromeBrowserMainParts::AddParts(ChromeBrowserMainExtraParts* parts) {
   chrome_extra_parts_.push_back(parts);
 }