// Copyright 2013 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 "components/startup_metric_utils/startup_metric_utils.h" #include "base/containers/hash_tables.h" #include "base/environment.h" #include "base/logging.h" #include "base/metrics/histogram.h" #include "base/metrics/histogram_base.h" #include "base/metrics/statistics_recorder.h" #include "base/process/process_info.h" #include "base/strings/string_number_conversions.h" #include "base/synchronization/lock.h" #include "base/sys_info.h" #include "base/time/time.h" namespace { // Mark as volatile to defensively make sure usage is thread-safe. // Note that at the time of this writing, access is only on the UI thread. volatile bool g_non_browser_ui_displayed = false; base::Time* MainEntryPointTimeInternal() { static base::Time main_start_time = base::Time::Now(); return &main_start_time; } typedef base::hash_map SubsystemStartupTimeHash; SubsystemStartupTimeHash* GetSubsystemStartupTimeHash() { static SubsystemStartupTimeHash* slow_startup_time_hash = new SubsystemStartupTimeHash; return slow_startup_time_hash; } base::Lock* GetSubsystemStartupTimeHashLock() { static base::Lock* slow_startup_time_hash_lock = new base::Lock; return slow_startup_time_hash_lock; } // Record time of main entry so it can be read from Telemetry performance // tests. // TODO(jeremy): Remove once crbug.com/317481 is fixed. void RecordMainEntryTimeHistogram() { const int kLowWordMask = 0xFFFFFFFF; const int kLower31BitsMask = 0x7FFFFFFF; base::TimeDelta browser_main_entry_time_absolute = base::TimeDelta::FromMilliseconds( MainEntryPointTimeInternal()->ToInternalValue() / 1000.0); uint64 browser_main_entry_time_raw_ms = browser_main_entry_time_absolute.InMilliseconds(); base::TimeDelta browser_main_entry_time_raw_ms_high_word = base::TimeDelta::FromMilliseconds( (browser_main_entry_time_raw_ms >> 32) & kLowWordMask); // Shift by one because histograms only support non-negative values. base::TimeDelta browser_main_entry_time_raw_ms_low_word = base::TimeDelta::FromMilliseconds( (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask); // A timestamp is a 64 bit value, yet histograms can only store 32 bits. LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord", browser_main_entry_time_raw_ms_high_word); LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord", browser_main_entry_time_raw_ms_low_word); } bool g_main_entry_time_was_recorded = false; bool g_startup_stats_collection_finished = false; bool g_was_slow_startup = false; // Environment variable that stores the timestamp when the executable's main() // function was entered. const char kChromeMainTimeEnvVar[] = "CHROME_MAIN_TIME"; } // namespace namespace startup_metric_utils { bool WasNonBrowserUIDisplayed() { return g_non_browser_ui_displayed; } void SetNonBrowserUIDisplayed() { g_non_browser_ui_displayed = true; } void RecordMainEntryPointTime() { DCHECK(!g_main_entry_time_was_recorded); g_main_entry_time_was_recorded = true; MainEntryPointTimeInternal(); } void RecordExeMainEntryTime() { std::string exe_load_time = base::Int64ToString(base::Time::Now().ToInternalValue()); scoped_ptr env(base::Environment::Create()); env->SetVar(kChromeMainTimeEnvVar, exe_load_time); } #if defined(OS_ANDROID) void RecordSavedMainEntryPointTime(const base::Time& entry_point_time) { DCHECK(!g_main_entry_time_was_recorded); g_main_entry_time_was_recorded = true; *MainEntryPointTimeInternal() = entry_point_time; } #endif // OS_ANDROID // Return the time recorded by RecordMainEntryPointTime(). const base::Time MainEntryStartTime() { DCHECK(g_main_entry_time_was_recorded); return *MainEntryPointTimeInternal(); } void OnBrowserStartupComplete(bool is_first_run) { RecordMainEntryTimeHistogram(); // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been // autostarted and the machine is under io pressure. const int64 kSevenMinutesInMilliseconds = base::TimeDelta::FromMinutes(7).InMilliseconds(); if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds) { g_startup_stats_collection_finished = true; return; } // The Startup.BrowserMessageLoopStartTime histogram recorded in // chrome_browser_main.cc exhibits instability in the field which limits its // usefulness in all scenarios except when we have a very large sample size. // Attempt to mitigate this with a new metric: // * Measure time from main entry rather than the OS' notion of process start // time. // * Only measure launches that occur 7 minutes after boot to try to avoid // cases where Chrome is auto-started and IO is heavily loaded. base::TimeDelta startup_time_from_main_entry = base::Time::Now() - MainEntryStartTime(); if (is_first_run) { UMA_HISTOGRAM_LONG_TIMES( "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun", startup_time_from_main_entry); } else { UMA_HISTOGRAM_LONG_TIMES( "Startup.BrowserMessageLoopStartTimeFromMainEntry", startup_time_from_main_entry); } // CurrentProcessInfo::CreationTime() is currently only implemented on some // platforms. #if (defined(OS_MACOSX) && !defined(OS_IOS)) || defined(OS_WIN) || \ defined(OS_LINUX) // Record timings between process creation, the main() in the executable being // reached and the main() in the shared library being reached. scoped_ptr env(base::Environment::Create()); std::string chrome_main_entry_time_string; if (env->GetVar(kChromeMainTimeEnvVar, &chrome_main_entry_time_string)) { // The time that the Chrome executable's main() function was entered. int64 chrome_main_entry_time_int = 0; if (base::StringToInt64(chrome_main_entry_time_string, &chrome_main_entry_time_int)) { base::Time process_create_time = base::CurrentProcessInfo::CreationTime(); base::Time exe_main_time = base::Time::FromInternalValue(chrome_main_entry_time_int); base::Time dll_main_time = MainEntryStartTime(); // Process create to chrome.exe:main(). UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToExeMain", exe_main_time - process_create_time); // chrome.exe:main() to chrome.dll:main(). UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ExeMainToDllMain", dll_main_time - exe_main_time); // Process create to chrome.dll:main(). UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToDllMain", dll_main_time - process_create_time); } } #endif // Record histograms for the subsystem times for startups > 10 seconds. const base::TimeDelta kTenSeconds = base::TimeDelta::FromSeconds(10); if (startup_time_from_main_entry < kTenSeconds) { g_startup_stats_collection_finished = true; return; } // If we got here this was what we consider to be a slow startup which we // want to record stats for. g_was_slow_startup = true; } void OnInitialPageLoadComplete() { if (!g_was_slow_startup) return; DCHECK(!g_startup_stats_collection_finished); const base::TimeDelta kStartupTimeMin( base::TimeDelta::FromMilliseconds(1)); const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5)); static const size_t kStartupTimeBuckets = 100; // Set UMA flag for histograms outside chrome/ that can't use the // ScopedSlowStartupUMA class. base::HistogramBase* histogram = base::StatisticsRecorder::FindHistogram("Startup.SlowStartupNSSInit"); if (histogram) histogram->SetFlags(base::HistogramBase::kUmaTargetedHistogramFlag); // Iterate over the stats recorded by ScopedSlowStartupUMA and create // histograms for them. base::AutoLock locker(*GetSubsystemStartupTimeHashLock()); SubsystemStartupTimeHash* time_hash = GetSubsystemStartupTimeHash(); for (SubsystemStartupTimeHash::iterator i = time_hash->begin(); i != time_hash->end(); ++i) { const std::string histogram_name = i->first; base::HistogramBase* counter = base::Histogram::FactoryTimeGet( histogram_name, kStartupTimeMin, kStartupTimeMax, kStartupTimeBuckets, base::Histogram::kUmaTargetedHistogramFlag); counter->AddTime(i->second); } g_startup_stats_collection_finished = true; } const base::Time* MainEntryPointTime() { if (!g_main_entry_time_was_recorded) return NULL; return MainEntryPointTimeInternal(); } ScopedSlowStartupUMA::~ScopedSlowStartupUMA() { if (g_startup_stats_collection_finished) return; base::AutoLock locker(*GetSubsystemStartupTimeHashLock()); SubsystemStartupTimeHash* hash = GetSubsystemStartupTimeHash(); // Only record the initial sample for a given histogram. if (hash->find(histogram_name_) != hash->end()) return; (*hash)[histogram_name_] = base::TimeTicks::Now() - start_time_; } } // namespace startup_metric_utils