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
MainEntryPointTimeInternal()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
GetSubsystemStartupTimeHash()32 SubsystemStartupTimeHash* GetSubsystemStartupTimeHash() {
33 static SubsystemStartupTimeHash* slow_startup_time_hash =
34 new SubsystemStartupTimeHash;
35 return slow_startup_time_hash;
36 }
37
GetSubsystemStartupTimeHashLock()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.
RecordMainEntryTimeHistogram()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
WasNonBrowserUIDisplayed()82 bool WasNonBrowserUIDisplayed() {
83 return g_non_browser_ui_displayed;
84 }
85
SetNonBrowserUIDisplayed()86 void SetNonBrowserUIDisplayed() {
87 g_non_browser_ui_displayed = true;
88 }
89
RecordMainEntryPointTime()90 void RecordMainEntryPointTime() {
91 DCHECK(!g_main_entry_time_was_recorded);
92 g_main_entry_time_was_recorded = true;
93 MainEntryPointTimeInternal();
94 }
95
RecordExeMainEntryTime()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)
RecordSavedMainEntryPointTime(const base::Time & entry_point_time)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().
MainEntryStartTime()112 const base::Time MainEntryStartTime() {
113 DCHECK(g_main_entry_time_was_recorded);
114 return *MainEntryPointTimeInternal();
115 }
116
OnBrowserStartupComplete(bool is_first_run)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
OnInitialPageLoadComplete()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
MainEntryPointTime()231 const base::Time* MainEntryPointTime() {
232 if (!g_main_entry_time_was_recorded)
233 return NULL;
234 return MainEntryPointTimeInternal();
235 }
236
~ScopedSlowStartupUMA()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