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