components/startup_metric_utils/startup_metric_utils.cc

   1 // Copyright 2013 The Chromium Authors. All rights reserved.
   2 // Use of this source code is governed by a BSD-style license that can be
   3 // found in the LICENSE file.
   4
   5 #include "components/startup_metric_utils/startup_metric_utils.h"
   6
   7 #include "base/containers/hash_tables.h"
   8 #include "base/environment.h"
   9 #include "base/logging.h"
  10 #include "base/metrics/histogram.h"
  11 #include "base/metrics/histogram_base.h"
  12 #include "base/metrics/statistics_recorder.h"
  13 #include "base/process/process_info.h"
  14 #include "base/strings/string_number_conversions.h"
  15 #include "base/synchronization/lock.h"
  16 #include "base/sys_info.h"
  17 #include "base/time/time.h"
  18
  19 namespace {
  20
  21 // Mark as volatile to defensively make sure usage is thread-safe.
  22 // Note that at the time of this writing, access is only on the UI thread.
  23 volatile bool g_non_browser_ui_displayed = false;
  24
  25 base::Time* MainEntryPointTimeInternal() {
  26   static base::Time main_start_time = base::Time::Now();
  27   return &main_start_time;
  28 }
  29
  30 typedef base::hash_map<std::string,base::TimeDelta> SubsystemStartupTimeHash;
  31
  32 SubsystemStartupTimeHash* GetSubsystemStartupTimeHash() {
  33   static SubsystemStartupTimeHash* slow_startup_time_hash =
  34                                     new SubsystemStartupTimeHash;
  35   return slow_startup_time_hash;
  36 }
  37
  38 base::Lock* GetSubsystemStartupTimeHashLock() {
  39   static base::Lock* slow_startup_time_hash_lock = new base::Lock;
  40   return slow_startup_time_hash_lock;
  41 }
  42
  43 // Record time of main entry so it can be read from Telemetry performance
  44 // tests.
  45 // TODO(jeremy): Remove once crbug.com/317481 is fixed.
  46 void RecordMainEntryTimeHistogram() {
  47   const int kLowWordMask = 0xFFFFFFFF;
  48   const int kLower31BitsMask = 0x7FFFFFFF;
  49   base::TimeDelta browser_main_entry_time_absolute =
  50       base::TimeDelta::FromMilliseconds(
  51           MainEntryPointTimeInternal()->ToInternalValue() / 1000.0);
  52
  53   uint64 browser_main_entry_time_raw_ms =
  54       browser_main_entry_time_absolute.InMilliseconds();
  55
  56   base::TimeDelta browser_main_entry_time_raw_ms_high_word =
  57       base::TimeDelta::FromMilliseconds(
  58           (browser_main_entry_time_raw_ms >> 32) & kLowWordMask);
  59   // Shift by one because histograms only support non-negative values.
  60   base::TimeDelta browser_main_entry_time_raw_ms_low_word =
  61       base::TimeDelta::FromMilliseconds(
  62           (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask);
  63
  64   // A timestamp is a 64 bit value, yet histograms can only store 32 bits.
  65   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord",
  66       browser_main_entry_time_raw_ms_high_word);
  67   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord",
  68       browser_main_entry_time_raw_ms_low_word);
  69 }
  70
  71 bool g_main_entry_time_was_recorded = false;
  72 bool g_startup_stats_collection_finished = false;
  73 bool g_was_slow_startup = false;
  74
  75 // Environment variable that stores the timestamp when the executable's main()
  76 // function was entered.
  77 const char kChromeMainTimeEnvVar[] = "CHROME_MAIN_TIME";
  78
  79 }  // namespace
  80
  81 namespace startup_metric_utils {
  82
  83 bool WasNonBrowserUIDisplayed() {
  84   return g_non_browser_ui_displayed;
  85 }
  86
  87 void SetNonBrowserUIDisplayed() {
  88   g_non_browser_ui_displayed = true;
  89 }
  90
  91 void RecordMainEntryPointTime() {
  92   DCHECK(!g_main_entry_time_was_recorded);
  93   g_main_entry_time_was_recorded = true;
  94   MainEntryPointTimeInternal();
  95 }
  96
  97 void RecordExeMainEntryTime() {
  98   std::string exe_load_time =
  99       base::Int64ToString(base::Time::Now().ToInternalValue());
 100   scoped_ptr<base::Environment> env(base::Environment::Create());
 101   env->SetVar(kChromeMainTimeEnvVar, exe_load_time);
 102 }
 103
 104 #if defined(OS_ANDROID)
 105 void RecordSavedMainEntryPointTime(const base::Time& entry_point_time) {
 106   DCHECK(!g_main_entry_time_was_recorded);
 107   g_main_entry_time_was_recorded = true;
 108   *MainEntryPointTimeInternal() = entry_point_time;
 109 }
 110 #endif // OS_ANDROID
 111
 112 // Return the time recorded by RecordMainEntryPointTime().
 113 const base::Time MainEntryStartTime() {
 114   DCHECK(g_main_entry_time_was_recorded);
 115   return *MainEntryPointTimeInternal();
 116 }
 117
 118 void OnBrowserStartupComplete(bool is_first_run) {
 119   RecordMainEntryTimeHistogram();
 120
 121   // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
 122   // autostarted and the machine is under io pressure.
 123   const int64 kSevenMinutesInMilliseconds =
 124       base::TimeDelta::FromMinutes(7).InMilliseconds();
 125   if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds) {
 126     g_startup_stats_collection_finished = true;
 127     return;
 128   }
 129
 130   // The Startup.BrowserMessageLoopStartTime histogram recorded in
 131   // chrome_browser_main.cc exhibits instability in the field which limits its
 132   // usefulness in all scenarios except when we have a very large sample size.
 133   // Attempt to mitigate this with a new metric:
 134   // * Measure time from main entry rather than the OS' notion of process start
 135   //   time.
 136   // * Only measure launches that occur 7 minutes after boot to try to avoid
 137   //   cases where Chrome is auto-started and IO is heavily loaded.
 138   base::TimeDelta startup_time_from_main_entry =
 139       base::Time::Now() - MainEntryStartTime();
 140   if (is_first_run) {
 141     UMA_HISTOGRAM_LONG_TIMES(
 142         "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun",
 143         startup_time_from_main_entry);
 144   } else {
 145     UMA_HISTOGRAM_LONG_TIMES(
 146         "Startup.BrowserMessageLoopStartTimeFromMainEntry",
 147         startup_time_from_main_entry);
 148   }
 149
 150 // CurrentProcessInfo::CreationTime() is currently only implemented on some
 151 // platforms.
 152 #if (defined(OS_MACOSX) && !defined(OS_IOS)) || defined(OS_WIN) || \
 153     defined(OS_LINUX)
 154   // Record timings between process creation, the main() in the executable being
 155   // reached and the main() in the shared library being reached.
 156   scoped_ptr<base::Environment> env(base::Environment::Create());
 157   std::string chrome_main_entry_time_string;
 158   if (env->GetVar(kChromeMainTimeEnvVar, &chrome_main_entry_time_string)) {
 159     // The time that the Chrome executable's main() function was entered.
 160     int64 chrome_main_entry_time_int = 0;
 161     if (base::StringToInt64(chrome_main_entry_time_string,
 162                             &chrome_main_entry_time_int)) {
 163       base::Time process_create_time = base::CurrentProcessInfo::CreationTime();
 164       base::Time exe_main_time =
 165           base::Time::FromInternalValue(chrome_main_entry_time_int);
 166       base::Time dll_main_time = MainEntryStartTime();
 167
 168       // Process create to chrome.exe:main().
 169       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToExeMain",
 170                                exe_main_time - process_create_time);
 171
 172       // chrome.exe:main() to chrome.dll:main().
 173       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ExeMainToDllMain",
 174                                dll_main_time - exe_main_time);
 175
 176       // Process create to chrome.dll:main().
 177       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToDllMain",
 178                                dll_main_time - process_create_time);
 179     }
 180   }
 181 #endif
 182
 183   // Record histograms for the subsystem times for startups > 10 seconds.
 184   const base::TimeDelta kTenSeconds = base::TimeDelta::FromSeconds(10);
 185   if (startup_time_from_main_entry < kTenSeconds) {
 186     g_startup_stats_collection_finished = true;
 187     return;
 188   }
 189
 190   // If we got here this was what we consider to be a slow startup which we
 191   // want to record stats for.
 192   g_was_slow_startup = true;
 193 }
 194
 195 void OnInitialPageLoadComplete() {
 196   if (!g_was_slow_startup)
 197     return;
 198   DCHECK(!g_startup_stats_collection_finished);
 199
 200   const base::TimeDelta kStartupTimeMin(
 201       base::TimeDelta::FromMilliseconds(1));
 202   const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5));
 203   static const size_t kStartupTimeBuckets = 100;
 204
 205   // Set UMA flag for histograms outside chrome/ that can't use the
 206   // ScopedSlowStartupUMA class.
 207   base::HistogramBase* histogram =
 208       base::StatisticsRecorder::FindHistogram("Startup.SlowStartupNSSInit");
 209   if (histogram)
 210     histogram->SetFlags(base::HistogramBase::kUmaTargetedHistogramFlag);
 211
 212   // Iterate over the stats recorded by ScopedSlowStartupUMA and create
 213   // histograms for them.
 214   base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
 215   SubsystemStartupTimeHash* time_hash = GetSubsystemStartupTimeHash();
 216   for (SubsystemStartupTimeHash::iterator i = time_hash->begin();
 217       i != time_hash->end();
 218       ++i) {
 219     const std::string histogram_name = i->first;
 220     base::HistogramBase* counter = base::Histogram::FactoryTimeGet(
 221         histogram_name,
 222         kStartupTimeMin,
 223         kStartupTimeMax,
 224         kStartupTimeBuckets,
 225         base::Histogram::kUmaTargetedHistogramFlag);
 226     counter->AddTime(i->second);
 227   }
 228
 229   g_startup_stats_collection_finished = true;
 230 }
 231
 232 const base::Time* MainEntryPointTime() {
 233   if (!g_main_entry_time_was_recorded)
 234     return NULL;
 235   return MainEntryPointTimeInternal();
 236 }
 237
 238 ScopedSlowStartupUMA::~ScopedSlowStartupUMA() {
 239   if (g_startup_stats_collection_finished)
 240     return;
 241
 242   base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
 243   SubsystemStartupTimeHash* hash = GetSubsystemStartupTimeHash();
 244   // Only record the initial sample for a given histogram.
 245   if (hash->find(histogram_name_) !=  hash->end())
 246     return;
 247
 248   (*hash)[histogram_name_] =
 249       base::TimeTicks::Now() - start_time_;
 250 }
 251
 252 }  // namespace startup_metric_utils