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
+#endif  // !defined(OS_ANDROID)
 
   if (!base::debug::BeingDebugged()) {
     // Create watchdog thread after creating all other threads because it will
     // watch the other threads and they must be running.
     browser_process_->watchdog_thread();
   }
 
   // Do any initializating in the browser process that requires all threads
   // running.
   browser_process_->PreMainMessageLoopRun();
@@ skipping 14 matching lines @@
   }
 
   if (parsed_command_line().HasSwitch(switches::kHideIcons) ||
       parsed_command_line().HasSwitch(switches::kShowIcons)) {
     return ChromeBrowserMainPartsWin::HandleIconsCommands(
         parsed_command_line_);
   }
 
   ui::SelectFileDialog::SetFactory(new ChromeSelectFileDialogFactory(
       BrowserThread::GetMessageLoopProxyForThread(BrowserThread::IO)));
-#endif
+#endif  // OS_WIN

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

defined()

[Lei Zhang, 2015/03/02 22:22:29]

nit: Please be consistent and add defined(). Ditto below.

 
   if (parsed_command_line().HasSwitch(switches::kMakeDefaultBrowser)) {
     return ShellIntegration::SetAsDefaultBrowser() ?
         static_cast<int>(content::RESULT_CODE_NORMAL_EXIT) :
         static_cast<int>(chrome::RESULT_CODE_SHELL_INTEGRATION_FAILED);
   }
 
 #if defined(USE_AURA)
   // Make sure aura::Env has been initialized.
   CHECK(aura::Env::GetInstance());
-#endif
+#endif  // defined(USE_AURA)
 
   // Android doesn't support extensions and doesn't implement ProcessSingleton.
 #if !defined(OS_ANDROID)
   // If the command line specifies --pack-extension, attempt the pack extension
   // startup action and exit.
   if (parsed_command_line().HasSwitch(switches::kPackExtension)) {
     extensions::StartupHelper extension_startup_helper;
     if (extension_startup_helper.PackExtension(parsed_command_line()))
       return content::RESULT_CODE_NORMAL_EXIT;
     return chrome::RESULT_CODE_PACK_EXTENSION_ERROR;
@@ skipping 12 matching lines @@
     notify_result_ = process_singleton_->NotifyOtherProcessOrCreate();
     switch (notify_result_) {
       case ProcessSingleton::PROCESS_NONE:
         // No process already running, fall through to starting a new one.
         break;
 
       case ProcessSingleton::PROCESS_NOTIFIED:
 #if defined(OS_POSIX) && !defined(OS_MACOSX)
         printf("%s\n", base::SysWideToNativeMB(base::UTF16ToWide(
             l10n_util::GetStringUTF16(IDS_USED_EXISTING_BROWSER))).c_str());
-#endif
+#endif  // OS_POSIX && !defined(OS_MACOSX)

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

Nit: defined(OS_POSIX) && !defined(OS_MACOSX)

#if defined(FOO)
is not the same as
#if FOO
better to be precise.

+
         // Having a differentiated return type for testing allows for tests to
         // verify proper handling of some switches. When not testing, stick to
         // the standard Unix convention of returning zero when things went as
         // expected.
         if (parsed_command_line().HasSwitch(switches::kTestType))
           return chrome::RESULT_CODE_NORMAL_EXIT_PROCESS_NOTIFIED;
         return content::RESULT_CODE_NORMAL_EXIT;
 
       case ProcessSingleton::PROFILE_IN_USE:
         return chrome::RESULT_CODE_PROFILE_IN_USE;
@@ skipping 36 matching lines @@
     // At this point the user is willing to try chrome again.
     if (answer == TryChromeDialogView::TRY_CHROME_AS_DEFAULT) {
       // Only set in the unattended case, the interactive case is Windows 8.
       if (ShellIntegration::CanSetAsDefaultBrowser() ==
           ShellIntegration::SET_DEFAULT_UNATTENDED)
         ShellIntegration::SetAsDefaultBrowser();
     }
 #else
     // We don't support retention experiments on Mac or Linux.
     return content::RESULT_CODE_NORMAL_EXIT;
-#endif  // defined(OS_WIN)
+#endif  // OS_WIN
   }
 
 #if defined(OS_WIN)
   // Do the tasks if chrome has been upgraded while it was last running.
   if (!already_running && upgrade_util::DoUpgradeTasks(parsed_command_line()))
     return content::RESULT_CODE_NORMAL_EXIT;
 
   // Check if there is any machine level Chrome installed on the current
   // machine. If yes and the current Chrome process is user level, we do not
   // allow the user level Chrome to run. So we notify the user and uninstall
   // user level Chrome.
   // Note this check needs to happen here (after the process singleton was
   // obtained but before potentially creating the first run sentinel).
   if (ChromeBrowserMainPartsWin::CheckMachineLevelInstall())
     return chrome::RESULT_CODE_MACHINE_LEVEL_INSTALL_EXISTS;
-#endif  // defined(OS_WIN)
+#endif  // OS_WIN
 
 #if defined(OS_LINUX) && !defined(OS_CHROMEOS)
   if (sxs_linux::ShouldMigrateUserDataDir())
     return sxs_linux::MigrateUserDataDir();
-#endif  // defined(OS_LINUX) && !defined(OS_CHROMEOS)
+#endif  // 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);
+
+  // This step is costly and is already measured in Startup.CreateFirstProfile
+  // and more directly Profile.CreateAndInitializeProfile.
   profile_ = CreatePrimaryProfile(parameters(),
                                   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();
-#endif
+#endif  // ENABLE_BACKGROUND

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

defined()

   // Post-profile init ---------------------------------------------------------
 
   TranslateService::Initialize();
 
   // Needs to be done before PostProfileInit, since login manager on CrOS is
   // called inside PostProfileInit.
   content::WebUIControllerFactory::RegisterFactory(
       ChromeWebUIControllerFactory::GetInstance());
 
   // NaClBrowserDelegateImpl is accessed inside PostProfileInit().
   // So make sure to create it before that.
 #if !defined(DISABLE_NACL)
   NaClBrowserDelegateImpl* delegate =
       new NaClBrowserDelegateImpl(browser_process_->profile_manager());
   nacl::NaClBrowser::SetDelegate(delegate);
-#endif
+#endif  // !defined(DISABLE_NACL)
 
   // TODO(stevenjb): Move WIN and MACOSX specific code to appropriate Parts.
   // (requires supporting early exit).
   PostProfileInit();
 
   // Retrieve cached GL strings from local state and use them for GPU
   // blacklist decisions.
   if (g_browser_process->gl_string_manager())
     g_browser_process->gl_string_manager()->Initialize();
 
@@ skipping 57 matching lines @@
   // file thread to be run sometime later. If this is the first run we record
   // the installation event.
   PrefService* pref_service = profile_->GetPrefs();
   int ping_delay = first_run::IsChromeFirstRun() ? master_prefs_->ping_delay :
       pref_service->GetInteger(first_run::GetPingDelayPrefName().c_str());
   // Negative ping delay means to send ping immediately after a first search is
   // recorded.
   RLZTracker::InitRlzFromProfileDelayed(
       profile_, first_run::IsChromeFirstRun(), ping_delay < 0,
       base::TimeDelta::FromMilliseconds(abs(ping_delay)));
-#endif  // defined(ENABLE_RLZ) && !defined(OS_CHROMEOS)
+#endif  // ENABLE_RLZ && !defined(OS_CHROMEOS)

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

Change back to defined()

 
   // Configure modules that need access to resources.
   net::NetModule::SetResourceProvider(chrome_common_net::NetResourceProvider);
 
   // In unittest mode, this will do nothing.  In normal mode, this will create
   // the global IntranetRedirectDetector instance, which will promptly go to
   // sleep for seven seconds (to avoid slowing startup), and wake up afterwards
   // to see if it should do anything else.
   //
   // A simpler way of doing all this would be to have some function which could
@@ skipping 22 matching lines @@
   } else if (sdch_trial_group.starts_with(kDisabledAllGroupName)) {
     net::SdchManager::EnableSdchSupport(false);
   }
 
 #if defined(ENABLE_PRINT_PREVIEW) && !defined(OFFICIAL_BUILD)
   if (parsed_command_line().HasSwitch(switches::kDebugPrint)) {
     base::FilePath path =
         parsed_command_line().GetSwitchValuePath(switches::kDebugPrint);
     printing::PrintedDocument::set_debug_dump_path(path);
   }
-#endif
+#endif  // ENABLE_PRINT_PREVIEW && !defined(OFFICIAL_BUILD)

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

Ditto.

 
   HandleTestParameters(parsed_command_line());
   browser_process_->metrics_service()->RecordBreakpadHasDebugger(
       base::debug::BeingDebugged());
 
   language_usage_metrics::LanguageUsageMetrics::RecordAcceptLanguages(
       profile_->GetPrefs()->GetString(prefs::kAcceptLanguages));
   language_usage_metrics::LanguageUsageMetrics::RecordApplicationLanguage(
       browser_process_->GetApplicationLocale());
 
   // Start watching for hangs during startup. We disarm this hang detector when
   // ThreadWatcher takes over or when browser is shutdown or when
   // startup_watcher_ is deleted.
   metrics::MetricsService::SetExecutionPhase(
       metrics::MetricsService::STARTUP_TIMEBOMB_ARM,
       g_browser_process->local_state());
   startup_watcher_->Arm(base::TimeDelta::FromSeconds(600));
 
   // On mobile, need for clean shutdown arises only when the application comes
   // to foreground (i.e. MetricsService::OnAppEnterForeground is called).
   // http://crbug.com/179143
 #if !defined(OS_ANDROID)
   // Start watching for a hang.
   browser_process_->metrics_service()->LogNeedForCleanShutdown();
-#endif
+#endif  // !defined(OS_ANDROID)
 
 #if defined(ENABLE_PRINT_PREVIEW)
   // Create the instance of the cloud print proxy service so that it can launch
   // the service process if needed. This is needed because the service process
   // might have shutdown because an update was available.
   // TODO(torne): this should maybe be done with
   // BrowserContextKeyedServiceFactory::ServiceIsCreatedWithBrowserContext()
   // instead?
   CloudPrintProxyServiceFactory::GetForProfile(profile_);
-#endif
+#endif  // ENABLE_PRINT_PREVIEW

[Alexei Svitkine (slow), 2015/03/02 22:11:54]

Ditto.

 
   // Start watching all browser threads for responsiveness.
   metrics::MetricsService::SetExecutionPhase(
       metrics::MetricsService::THREAD_WATCHER_START,
       g_browser_process->local_state());
   ThreadWatcherList::StartWatchingAll(parsed_command_line());
 
 #if defined(OS_ANDROID)
   ThreadWatcherAndroid::RegisterApplicationStatusListener();
-#endif
+#endif  // OS_ANDROID

[Alexei Svitkine (slow), 2015/03/02 22:11:54]

Ditto.

 
 #if !defined(DISABLE_NACL)
   BrowserThread::PostTask(
       BrowserThread::IO,
       FROM_HERE,
       base::Bind(nacl::NaClProcessHost::EarlyStartup));
-#endif
+#endif  // !defined(DISABLE_NACL)
 
   // Make sure initial prefs are recorded
   PrefMetricsService::Factory::GetForProfile(profile_);
 
   PreBrowserStart();
 
   // Instantiate the notification UI manager, as this triggers a perf timer
   // used to measure startup time. TODO(stevenjb): Figure out what is actually
   // triggering the timer and call that explicitly in the approprate place.
   // http://crbug.com/105065.
@@ skipping 25 matching lines @@
   // We are in regular browser boot sequence. Open initial tabs and enter the
   // main message loop.
 #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
+#endif  // OS_CHROMEOS

[Alexei Svitkine (slow), 2015/03/02 22:11:55]

Ditto.

 
-  if (browser_creator_->Start(parsed_command_line(), base::FilePath(),
-                              profile_, last_opened_profiles)) {
+  UMA_HISTOGRAM_TIMES("Startup.PreMainMessageLoopRunImplStep2Time",
+                      base::TimeTicks::Now() - start_time_step2);
+
+  // This step is costly and is already measured in
+  // Startup.StartupBrowserCreator_Start.
+  bool started = browser_creator_->Start(
+      parsed_command_line(), 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
+#endif  // OS_WIN || (OS_LINUX && !defined(OS_CHROMEOS))
 
 #if defined(OS_LINUX) && !defined(OS_CHROMEOS)
     // On Linux, the running exe will be updated if an upgrade becomes
     // available while the browser is running.  We need to save the last
     // modified time of the exe, so we can compare to determine if there is
     // an upgrade while the browser is kept alive by a persistent extension.
     upgrade_util::SaveLastModifiedTimeOfExe();
-#endif
+#endif  // OS_LINUX && !defined(OS_CHROMEOS)
 
     // Record now as the last successful chrome start.
     GoogleUpdateSettings::SetLastRunTime();
 
 #if defined(OS_MACOSX)
     // Call Recycle() here as late as possible, before going into the loop
     // because Start() will add things to it while creating the main window.
     if (parameters().autorelease_pool)
       parameters().autorelease_pool->Recycle();
-#endif
+#endif  // defined(OS_MACOSX)
 
     base::TimeDelta delay = base::TimeTicks::Now() - browser_open_start;
     UMA_HISTOGRAM_LONG_TIMES_100("Startup.BrowserOpenTabs", delay);
 
     // If we're running tests (ui_task is non-null), then we don't want to
     // call RequestLanguageList or StartRepeatedVariationsSeedFetch or
     // RequestLanguageList
     if (parameters().ui_task == NULL) {
       // Request new variations seed information from server.
       chrome_variations::VariationsService* variations_service =
           browser_process_->variations_service();
       if (variations_service) {
         variations_service->StartRepeatedVariationsSeedFetch();
 
 #if defined(OS_WIN)
         variations_service->StartGoogleUpdateRegistrySync();
-#endif
+#endif  // OS_WIN
       }
 
       translate::TranslateDownloadManager::RequestLanguageList(
           profile_->GetPrefs());
     }
 
     run_message_loop_ = true;
   } else {
     run_message_loop_ = false;
   }
   browser_creator_.reset();
 
 #if !defined(OS_LINUX) || defined(OS_CHROMEOS)  // http://crbug.com/426393
   if (g_browser_process->metrics_service()->reporting_active())
     content::StartPowerUsageMonitor();
-#endif
+#endif  // !defined(OS_LINUX) || defined(OS_CHROMEOS)
 
   process_power_collector_.reset(new ProcessPowerCollector);
   process_power_collector_->Initialize();
 #endif  // !defined(OS_ANDROID)
 
   PostBrowserStart();
 
   if (parameters().ui_task) {
     parameters().ui_task->Run();
     delete parameters().ui_task;
     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
+  // the start of the main loop.
   if (result_code_ <= 0) {
     RecordBrowserStartupTime();
   }
-#endif
+#endif  // OS_ANDROID
+
+#if !defined(OS_ANDROID)
+  UMA_HISTOGRAM_TIMES("Startup.PreMainMessageLoopRunImplStep3Time",
+                      base::TimeTicks::Now() - start_time_step3);
+#endif  // !defined(OS_ANDROID)
+
   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);
 }