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