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