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 #if defined(OS_WIN)
  20 #include <winternl.h>
  21 #include "base/win/windows_version.h"
  22 #endif
  23
  24 namespace {
  25
  26 // Mark as volatile to defensively make sure usage is thread-safe.
  27 // Note that at the time of this writing, access is only on the UI thread.
  28 volatile bool g_non_browser_ui_displayed = false;
  29
  30 base::Time* MainEntryPointTimeInternal() {
  31   static base::Time main_start_time = base::Time::Now();
  32   return &main_start_time;
  33 }
  34
  35 typedef base::hash_map<std::string,base::TimeDelta> SubsystemStartupTimeHash;
  36
  37 SubsystemStartupTimeHash* GetSubsystemStartupTimeHash() {
  38   static SubsystemStartupTimeHash* slow_startup_time_hash =
  39                                     new SubsystemStartupTimeHash;
  40   return slow_startup_time_hash;
  41 }
  42
  43 base::Lock* GetSubsystemStartupTimeHashLock() {
  44   static base::Lock* slow_startup_time_hash_lock = new base::Lock;
  45   return slow_startup_time_hash_lock;
  46 }
  47
  48 #if defined(OS_WIN)
  49
  50 // The struct used to return system process information via the NT internal
  51 // QuerySystemInformation call. This is partially documented at
  52 // http://goo.gl/Ja9MrH and fully documented at http://goo.gl/QJ70rn
  53 // This structure is laid out in the same format on both 32-bit and 64-bit
  54 // systems, but has a different size due to the various pointer-sized fields.
  55 struct SYSTEM_PROCESS_INFORMATION_EX {
  56   ULONG NextEntryOffset;
  57   ULONG NumberOfThreads;
  58   LARGE_INTEGER WorkingSetPrivateSize;
  59   ULONG HardFaultCount;
  60   BYTE Reserved1[36];
  61   PVOID Reserved2[3];
  62   // This is labeled a handle so that it expands to the correct size for 32-bit
  63   // and 64-bit operating systems. However, under the hood it's a 32-bit DWORD
  64   // containing the process ID.
  65   HANDLE UniqueProcessId;
  66   PVOID Reserved3;
  67   ULONG HandleCount;
  68   BYTE Reserved4[4];
  69   PVOID Reserved5[11];
  70   SIZE_T PeakPagefileUsage;
  71   SIZE_T PrivatePageCount;
  72   LARGE_INTEGER Reserved6[6];
  73   // Array of SYSTEM_THREAD_INFORMATION structs follows.
  74 };
  75
  76 // The signature of the NtQuerySystemInformation function.
  77 typedef NTSTATUS (WINAPI *NtQuerySystemInformationPtr)(
  78     SYSTEM_INFORMATION_CLASS, PVOID, ULONG, PULONG);
  79
  80 // Gets the hard fault count of the current process, returning it via
  81 // |hard_fault_count|. Returns true on success, false otherwise. Also returns
  82 // whether or not the system call was even possible for the current OS version
  83 // via |has_os_support|.
  84 bool GetHardFaultCountForCurrentProcess(uint32_t* hard_fault_count,
  85                                         bool* has_os_support) {
  86   DCHECK(hard_fault_count);
  87   DCHECK(has_os_support);
  88
  89   if (base::win::GetVersion() < base::win::VERSION_WIN7) {
  90     *has_os_support = false;
  91     return false;
  92   }
  93   // At this point the OS supports the required system call.
  94   *has_os_support = true;
  95
  96   // Get the function pointer.
  97   NtQuerySystemInformationPtr query_sys_info =
  98       reinterpret_cast<NtQuerySystemInformationPtr>(
  99           ::GetProcAddress(GetModuleHandle(L"ntdll.dll"),
 100                            "NtQuerySystemInformation"));
 101   if (query_sys_info == nullptr)
 102     return false;
 103
 104   // The output of this system call depends on the number of threads and
 105   // processes on the entire system, and this can change between calls. Retry
 106   // a small handful of times growing the buffer along the way.
 107   // NOTE: The actual required size depends entirely on the number of processes
 108   //       and threads running on the system. The initial guess suffices for
 109   //       ~100s of processes and ~1000s of threads.
 110   std::vector<uint8_t> buffer(32 * 1024);
 111   for (size_t tries = 0; tries < 3; ++tries) {
 112     ULONG return_length = 0;
 113     NTSTATUS status = query_sys_info(
 114         SystemProcessInformation,
 115         buffer.data(),
 116         static_cast<ULONG>(buffer.size()),
 117         &return_length);
 118     // Insufficient space in the buffer.
 119     if (return_length > buffer.size()) {
 120       buffer.resize(return_length);
 121       continue;
 122     }
 123     if (NT_SUCCESS(status) && return_length <= buffer.size())
 124       break;
 125     return false;
 126   }
 127
 128   // Look for the struct housing information for the current process.
 129   DWORD proc_id = ::GetCurrentProcessId();
 130   size_t index = 0;
 131   while (index < buffer.size()) {
 132     DCHECK_LE(index + sizeof(SYSTEM_PROCESS_INFORMATION_EX), buffer.size());
 133     SYSTEM_PROCESS_INFORMATION_EX* proc_info =
 134         reinterpret_cast<SYSTEM_PROCESS_INFORMATION_EX*>(buffer.data() + index);
 135     if (reinterpret_cast<DWORD>(proc_info->UniqueProcessId) == proc_id) {
 136       *hard_fault_count = proc_info->HardFaultCount;
 137       return true;
 138     }
 139     // The list ends when NextEntryOffset is zero. This also prevents busy
 140     // looping if the data is in fact invalid.
 141     if (proc_info->NextEntryOffset <= 0)
 142       return false;
 143     index += proc_info->NextEntryOffset;
 144   }
 145
 146   return false;
 147 }
 148
 149 #endif  // defined(OS_WIN)
 150
 151 // On Windows, records the number of hard-faults that have occurred in the
 152 // current chrome.exe process since it was started. This is a nop on other
 153 // platforms.
 154 // crbug.com/476923
 155 // TODO(chrisha): If this proves useful, use it to split startup stats in two.
 156 void RecordHardFaultHistogram(bool is_first_run) {
 157 #if defined(OS_WIN)
 158   uint32_t hard_fault_count = 0;
 159   bool has_os_support = false;
 160   bool success = GetHardFaultCountForCurrentProcess(
 161       &hard_fault_count, &has_os_support);
 162
 163   // Log whether or not the system call was successful, assuming the OS was
 164   // detected to support it.
 165   if (has_os_support) {
 166     UMA_HISTOGRAM_BOOLEAN(
 167         "Startup.BrowserMessageLoopStartHardFaultCount.Success",
 168         success);
 169   }
 170
 171   // Don't log a histogram value if unable to get the hard fault count.
 172   if (!success)
 173     return;
 174
 175   // Hard fault counts are expected to be in the thousands range,
 176   // corresponding to faulting in ~10s of MBs of code ~10s of KBs at a time.
 177   // (Observed to vary from 1000 to 10000 on various test machines and
 178   // platforms.)
 179   if (is_first_run) {
 180     UMA_HISTOGRAM_CUSTOM_COUNTS(
 181         "Startup.BrowserMessageLoopStartHardFaultCount.FirstRun",
 182         hard_fault_count,
 183         0, 40000, 50);
 184   } else {
 185     UMA_HISTOGRAM_CUSTOM_COUNTS(
 186         "Startup.BrowserMessageLoopStartHardFaultCount",
 187         hard_fault_count,
 188         0, 40000, 50);
 189   }
 190 #endif  // defined(OS_WIN)
 191 }
 192
 193 // Record time of main entry so it can be read from Telemetry performance
 194 // tests.
 195 // TODO(jeremy): Remove once crbug.com/317481 is fixed.
 196 void RecordMainEntryTimeHistogram() {
 197   const int kLowWordMask = 0xFFFFFFFF;
 198   const int kLower31BitsMask = 0x7FFFFFFF;
 199   base::TimeDelta browser_main_entry_time_absolute =
 200       *MainEntryPointTimeInternal() - base::Time::UnixEpoch();
 201
 202   uint64 browser_main_entry_time_raw_ms =
 203       browser_main_entry_time_absolute.InMilliseconds();
 204
 205   base::TimeDelta browser_main_entry_time_raw_ms_high_word =
 206       base::TimeDelta::FromMilliseconds(
 207           (browser_main_entry_time_raw_ms >> 32) & kLowWordMask);
 208   // Shift by one because histograms only support non-negative values.
 209   base::TimeDelta browser_main_entry_time_raw_ms_low_word =
 210       base::TimeDelta::FromMilliseconds(
 211           (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask);
 212
 213   // A timestamp is a 64 bit value, yet histograms can only store 32 bits.
 214   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord",
 215       browser_main_entry_time_raw_ms_high_word);
 216   LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord",
 217       browser_main_entry_time_raw_ms_low_word);
 218 }
 219
 220 bool g_main_entry_time_was_recorded = false;
 221 bool g_startup_stats_collection_finished = false;
 222 bool g_was_slow_startup = false;
 223
 224 // Environment variable that stores the timestamp when the executable's main()
 225 // function was entered.
 226 const char kChromeMainTimeEnvVar[] = "CHROME_MAIN_TIME";
 227
 228 }  // namespace
 229
 230 namespace startup_metric_utils {
 231
 232 bool WasNonBrowserUIDisplayed() {
 233   return g_non_browser_ui_displayed;
 234 }
 235
 236 void SetNonBrowserUIDisplayed() {
 237   g_non_browser_ui_displayed = true;
 238 }
 239
 240 void RecordMainEntryPointTime() {
 241   DCHECK(!g_main_entry_time_was_recorded);
 242   g_main_entry_time_was_recorded = true;
 243   MainEntryPointTimeInternal();
 244 }
 245
 246 void RecordExeMainEntryTime() {
 247   std::string exe_load_time =
 248       base::Int64ToString(base::Time::Now().ToInternalValue());
 249   scoped_ptr<base::Environment> env(base::Environment::Create());
 250   env->SetVar(kChromeMainTimeEnvVar, exe_load_time);
 251 }
 252
 253 #if defined(OS_ANDROID)
 254 void RecordSavedMainEntryPointTime(const base::Time& entry_point_time) {
 255   DCHECK(!g_main_entry_time_was_recorded);
 256   g_main_entry_time_was_recorded = true;
 257   *MainEntryPointTimeInternal() = entry_point_time;
 258 }
 259 #endif // OS_ANDROID
 260
 261 // Return the time recorded by RecordMainEntryPointTime().
 262 const base::Time MainEntryStartTime() {
 263   DCHECK(g_main_entry_time_was_recorded);
 264   return *MainEntryPointTimeInternal();
 265 }
 266
 267 void OnBrowserStartupComplete(bool is_first_run) {
 268   RecordHardFaultHistogram(is_first_run);
 269   RecordMainEntryTimeHistogram();
 270
 271   // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
 272   // autostarted and the machine is under io pressure.
 273   const int64 kSevenMinutesInMilliseconds =
 274       base::TimeDelta::FromMinutes(7).InMilliseconds();
 275   if (base::SysInfo::Uptime() < kSevenMinutesInMilliseconds) {
 276     g_startup_stats_collection_finished = true;
 277     return;
 278   }
 279
 280   // The Startup.BrowserMessageLoopStartTime histogram recorded in
 281   // chrome_browser_main.cc exhibits instability in the field which limits its
 282   // usefulness in all scenarios except when we have a very large sample size.
 283   // Attempt to mitigate this with a new metric:
 284   // * Measure time from main entry rather than the OS' notion of process start
 285   //   time.
 286   // * Only measure launches that occur 7 minutes after boot to try to avoid
 287   //   cases where Chrome is auto-started and IO is heavily loaded.
 288   base::TimeDelta startup_time_from_main_entry =
 289       base::Time::Now() - MainEntryStartTime();
 290   if (is_first_run) {
 291     UMA_HISTOGRAM_LONG_TIMES(
 292         "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun",
 293         startup_time_from_main_entry);
 294   } else {
 295     UMA_HISTOGRAM_LONG_TIMES(
 296         "Startup.BrowserMessageLoopStartTimeFromMainEntry",
 297         startup_time_from_main_entry);
 298   }
 299
 300 // CurrentProcessInfo::CreationTime() is currently only implemented on some
 301 // platforms.
 302 #if (defined(OS_MACOSX) && !defined(OS_IOS)) || defined(OS_WIN) || \
 303     defined(OS_LINUX)
 304   // Record timings between process creation, the main() in the executable being
 305   // reached and the main() in the shared library being reached.
 306   scoped_ptr<base::Environment> env(base::Environment::Create());
 307   std::string chrome_main_entry_time_string;
 308   if (env->GetVar(kChromeMainTimeEnvVar, &chrome_main_entry_time_string)) {
 309     // The time that the Chrome executable's main() function was entered.
 310     int64 chrome_main_entry_time_int = 0;
 311     if (base::StringToInt64(chrome_main_entry_time_string,
 312                             &chrome_main_entry_time_int)) {
 313       base::Time process_create_time = base::CurrentProcessInfo::CreationTime();
 314       base::Time exe_main_time =
 315           base::Time::FromInternalValue(chrome_main_entry_time_int);
 316       base::Time dll_main_time = MainEntryStartTime();
 317
 318       // Process create to chrome.exe:main().
 319       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToExeMain",
 320                                exe_main_time - process_create_time);
 321
 322       // chrome.exe:main() to chrome.dll:main().
 323       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ExeMainToDllMain",
 324                                dll_main_time - exe_main_time);
 325
 326       // Process create to chrome.dll:main().
 327       UMA_HISTOGRAM_LONG_TIMES("Startup.LoadTime.ProcessCreateToDllMain",
 328                                dll_main_time - process_create_time);
 329     }
 330   }
 331 #endif
 332
 333   // Record histograms for the subsystem times for startups > 10 seconds.
 334   const base::TimeDelta kTenSeconds = base::TimeDelta::FromSeconds(10);
 335   if (startup_time_from_main_entry < kTenSeconds) {
 336     g_startup_stats_collection_finished = true;
 337     return;
 338   }
 339
 340   // If we got here this was what we consider to be a slow startup which we
 341   // want to record stats for.
 342   g_was_slow_startup = true;
 343 }
 344
 345 void OnInitialPageLoadComplete() {
 346   if (!g_was_slow_startup)
 347     return;
 348   DCHECK(!g_startup_stats_collection_finished);
 349
 350   const base::TimeDelta kStartupTimeMin(
 351       base::TimeDelta::FromMilliseconds(1));
 352   const base::TimeDelta kStartupTimeMax(base::TimeDelta::FromMinutes(5));
 353   static const size_t kStartupTimeBuckets = 100;
 354
 355   // Set UMA flag for histograms outside chrome/ that can't use the
 356   // ScopedSlowStartupUMA class.
 357   base::HistogramBase* histogram =
 358       base::StatisticsRecorder::FindHistogram("Startup.SlowStartupNSSInit");
 359   if (histogram)
 360     histogram->SetFlags(base::HistogramBase::kUmaTargetedHistogramFlag);
 361
 362   // Iterate over the stats recorded by ScopedSlowStartupUMA and create
 363   // histograms for them.
 364   base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
 365   SubsystemStartupTimeHash* time_hash = GetSubsystemStartupTimeHash();
 366   for (SubsystemStartupTimeHash::iterator i = time_hash->begin();
 367       i != time_hash->end();
 368       ++i) {
 369     const std::string histogram_name = i->first;
 370     base::HistogramBase* counter = base::Histogram::FactoryTimeGet(
 371         histogram_name,
 372         kStartupTimeMin,
 373         kStartupTimeMax,
 374         kStartupTimeBuckets,
 375         base::Histogram::kUmaTargetedHistogramFlag);
 376     counter->AddTime(i->second);
 377   }
 378
 379   g_startup_stats_collection_finished = true;
 380 }
 381
 382 const base::Time* MainEntryPointTime() {
 383   if (!g_main_entry_time_was_recorded)
 384     return NULL;
 385   return MainEntryPointTimeInternal();
 386 }
 387
 388 ScopedSlowStartupUMA::~ScopedSlowStartupUMA() {
 389   if (g_startup_stats_collection_finished)
 390     return;
 391
 392   base::AutoLock locker(*GetSubsystemStartupTimeHashLock());
 393   SubsystemStartupTimeHash* hash = GetSubsystemStartupTimeHash();
 394   // Only record the initial sample for a given histogram.
 395   if (hash->find(histogram_name_) !=  hash->end())
 396     return;
 397
 398   (*hash)[histogram_name_] =
 399       base::TimeTicks::Now() - start_time_;
 400 }
 401
 402 }  // namespace startup_metric_utils