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
19namespace {
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.
23volatile bool g_non_browser_ui_displayed = false;
24
25base::Time* MainEntryPointTimeInternal() {
26  static base::Time main_start_time = base::Time::Now();
27  return &main_start_time;
28}
29
30typedef base::hash_map<std::string,base::TimeDelta> SubsystemStartupTimeHash;
31
32SubsystemStartupTimeHash* GetSubsystemStartupTimeHash() {
33  static SubsystemStartupTimeHash* slow_startup_time_hash =
34                                    new SubsystemStartupTimeHash;
35  return slow_startup_time_hash;
36}
37
38base::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.
46void 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
70bool g_main_entry_time_was_recorded = false;
71bool g_startup_stats_collection_finished = false;
72bool g_was_slow_startup = false;
73
74// Environment variable that stores the timestamp when the executable's main()
75// function was entered.
76const char kChromeMainTimeEnvVar[] = "CHROME_MAIN_TIME";
77
78}  // namespace
79
80namespace startup_metric_utils {
81
82bool WasNonBrowserUIDisplayed() {
83  return g_non_browser_ui_displayed;
84}
85
86void SetNonBrowserUIDisplayed() {
87  g_non_browser_ui_displayed = true;
88}
89
90void RecordMainEntryPointTime() {
91  DCHECK(!g_main_entry_time_was_recorded);
92  g_main_entry_time_was_recorded = true;
93  MainEntryPointTimeInternal();
94}
95
96void 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)
104void 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().
112const base::Time MainEntryStartTime() {
113  DCHECK(g_main_entry_time_was_recorded);
114  return *MainEntryPointTimeInternal();
115}
116
117void 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
194void 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
231const base::Time* MainEntryPointTime() {
232  if (!g_main_entry_time_was_recorded)
233    return NULL;
234  return MainEntryPointTimeInternal();
235}
236
237ScopedSlowStartupUMA::~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