Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(239)

Side by Side Diff: components/startup_metric_utils/startup_metric_utils.cc

Issue 1413153010: Move components/startup_metric_utils/* to components/startup_metric_utils/browser/*. (Closed) Base URL: https://chromium.googlesource.com/chromium/src.git@master
Patch Set: rebase Created 5 years, 1 month ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
« no previous file with comments | « components/startup_metric_utils/startup_metric_utils.h ('k') | no next file » | no next file with comments »
Toggle Intra-line Diffs ('i') | Expand Comments ('e') | Collapse Comments ('c') | Show Comments Hide Comments ('s')
OLDNEW
(Empty)
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 #include "base/trace_event/trace_event.h"
15
16 #if defined(OS_WIN)
17 #include <winternl.h>
18 #include "base/win/windows_version.h"
19 #endif
20
21 namespace startup_metric_utils {
22
23 namespace {
24
25 // Mark as volatile to defensively make sure usage is thread-safe.
26 // Note that at the time of this writing, access is only on the UI thread.
27 volatile bool g_non_browser_ui_displayed = false;
28
29 base::LazyInstance<base::Time>::Leaky g_process_creation_time =
30 LAZY_INSTANCE_INITIALIZER;
31
32 base::LazyInstance<base::Time>::Leaky g_main_entry_point_time =
33 LAZY_INSTANCE_INITIALIZER;
34
35 StartupTemperature g_startup_temperature = UNCERTAIN_STARTUP_TEMPERATURE;
36
37 #if defined(OS_WIN)
38
39 // These values are taken from the Startup.BrowserMessageLoopStartHardFaultCount
40 // histogram. If the cold start histogram starts looking strongly bimodal it may
41 // be because the binary/resource sizes have grown significantly larger than
42 // when these values were set. In this case the new values need to be chosen
43 // from the original histogram.
44 //
45 // Maximum number of hard faults tolerated for a startup to be classified as a
46 // warm start. Set at roughly the 40th percentile of the HardFaultCount
47 // histogram.
48 const uint32_t WARM_START_HARD_FAULT_COUNT_THRESHOLD = 5;
49 // Minimum number of hard faults expected for a startup to be classified as a
50 // cold start. Set at roughly the 60th percentile of the HardFaultCount
51 // histogram.
52 const uint32_t COLD_START_HARD_FAULT_COUNT_THRESHOLD = 1200;
53
54 // The struct used to return system process information via the NT internal
55 // QuerySystemInformation call. This is partially documented at
56 // http://goo.gl/Ja9MrH and fully documented at http://goo.gl/QJ70rn
57 // This structure is laid out in the same format on both 32-bit and 64-bit
58 // systems, but has a different size due to the various pointer-sized fields.
59 struct SYSTEM_PROCESS_INFORMATION_EX {
60 ULONG NextEntryOffset;
61 ULONG NumberOfThreads;
62 LARGE_INTEGER WorkingSetPrivateSize;
63 ULONG HardFaultCount;
64 BYTE Reserved1[36];
65 PVOID Reserved2[3];
66 // This is labeled a handle so that it expands to the correct size for 32-bit
67 // and 64-bit operating systems. However, under the hood it's a 32-bit DWORD
68 // containing the process ID.
69 HANDLE UniqueProcessId;
70 PVOID Reserved3;
71 ULONG HandleCount;
72 BYTE Reserved4[4];
73 PVOID Reserved5[11];
74 SIZE_T PeakPagefileUsage;
75 SIZE_T PrivatePageCount;
76 LARGE_INTEGER Reserved6[6];
77 // Array of SYSTEM_THREAD_INFORMATION structs follows.
78 };
79
80 // The signature of the NtQuerySystemInformation function.
81 typedef NTSTATUS (WINAPI *NtQuerySystemInformationPtr)(
82 SYSTEM_INFORMATION_CLASS, PVOID, ULONG, PULONG);
83
84 // Gets the hard fault count of the current process, returning it via
85 // |hard_fault_count|. Returns true on success, false otherwise. Also returns
86 // whether or not the system call was even possible for the current OS version
87 // via |has_os_support|.
88 bool GetHardFaultCountForCurrentProcess(uint32_t* hard_fault_count,
89 bool* has_os_support) {
90 DCHECK(hard_fault_count);
91 DCHECK(has_os_support);
92
93 if (base::win::GetVersion() < base::win::VERSION_WIN7) {
94 *has_os_support = false;
95 return false;
96 }
97 // At this point the OS supports the required system call.
98 *has_os_support = true;
99
100 // Get the function pointer.
101 NtQuerySystemInformationPtr query_sys_info =
102 reinterpret_cast<NtQuerySystemInformationPtr>(
103 ::GetProcAddress(GetModuleHandle(L"ntdll.dll"),
104 "NtQuerySystemInformation"));
105 if (query_sys_info == nullptr)
106 return false;
107
108 // The output of this system call depends on the number of threads and
109 // processes on the entire system, and this can change between calls. Retry
110 // a small handful of times growing the buffer along the way.
111 // NOTE: The actual required size depends entirely on the number of processes
112 // and threads running on the system. The initial guess suffices for
113 // ~100s of processes and ~1000s of threads.
114 std::vector<uint8_t> buffer(32 * 1024);
115 for (size_t tries = 0; tries < 3; ++tries) {
116 ULONG return_length = 0;
117 NTSTATUS status = query_sys_info(
118 SystemProcessInformation,
119 buffer.data(),
120 static_cast<ULONG>(buffer.size()),
121 &return_length);
122 // Insufficient space in the buffer.
123 if (return_length > buffer.size()) {
124 buffer.resize(return_length);
125 continue;
126 }
127 if (NT_SUCCESS(status) && return_length <= buffer.size())
128 break;
129 return false;
130 }
131
132 // Look for the struct housing information for the current process.
133 DWORD proc_id = ::GetCurrentProcessId();
134 size_t index = 0;
135 while (index < buffer.size()) {
136 DCHECK_LE(index + sizeof(SYSTEM_PROCESS_INFORMATION_EX), buffer.size());
137 SYSTEM_PROCESS_INFORMATION_EX* proc_info =
138 reinterpret_cast<SYSTEM_PROCESS_INFORMATION_EX*>(buffer.data() + index);
139 if (reinterpret_cast<DWORD>(proc_info->UniqueProcessId) == proc_id) {
140 *hard_fault_count = proc_info->HardFaultCount;
141 return true;
142 }
143 // The list ends when NextEntryOffset is zero. This also prevents busy
144 // looping if the data is in fact invalid.
145 if (proc_info->NextEntryOffset <= 0)
146 return false;
147 index += proc_info->NextEntryOffset;
148 }
149
150 return false;
151 }
152
153 #endif // defined(OS_WIN)
154
155
156 // Helper macro for splitting out an UMA histogram based on cold or warm start.
157 // |type| is the histogram type, and corresponds to an UMA macro like
158 // UMA_HISTOGRAM_LONG_TIMES. It must be itself be a macro that only takes two
159 // parameters.
160 // |basename| is the basename of the histogram. A histogram of this name will
161 // always be recorded to. If the startup is either cold or warm then a value
162 // will also be recorded to the histogram with name |basename| and suffix
163 // ".ColdStart" or ".WarmStart", as appropriate.
164 // |value_expr| is an expression evaluating to the value to be recorded. This
165 // will be evaluated exactly once and cached, so side effects are not an issue.
166 #define UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(type, basename, value_expr) \
167 { \
168 const auto kValue = value_expr; \
169 /* Always record to the base histogram. */ \
170 type(basename, kValue); \
171 /* Record to the cold/warm suffixed histogram as appropriate. */ \
172 if (g_startup_temperature == COLD_STARTUP_TEMPERATURE) { \
173 type(basename ".ColdStartup", kValue); \
174 } else if (g_startup_temperature == WARM_STARTUP_TEMPERATURE) { \
175 type(basename ".WarmStartup", kValue); \
176 } \
177 }
178
179 #define UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(type, basename, \
180 begin_time, end_time) \
181 { \
182 UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(type, basename, \
183 end_time - begin_time) \
184 TRACE_EVENT_ASYNC_BEGIN_WITH_TIMESTAMP1( \
185 "startup", basename, 0, \
186 StartupTimeToTimeTicks(begin_time).ToInternalValue(), "Temperature", \
187 g_startup_temperature); \
188 TRACE_EVENT_ASYNC_END_WITH_TIMESTAMP1( \
189 "startup", basename, 0, \
190 StartupTimeToTimeTicks(end_time).ToInternalValue(), "Temperature", \
191 g_startup_temperature); \
192 }
193
194 // On Windows, records the number of hard-faults that have occurred in the
195 // current chrome.exe process since it was started. This is a nop on other
196 // platforms.
197 // crbug.com/476923
198 // TODO(chrisha): If this proves useful, use it to split startup stats in two.
199 void RecordHardFaultHistogram(bool is_first_run) {
200 #if defined(OS_WIN)
201 uint32_t hard_fault_count = 0;
202 bool has_os_support = false;
203 bool success = GetHardFaultCountForCurrentProcess(
204 &hard_fault_count, &has_os_support);
205
206 // Log whether or not the system call was successful, assuming the OS was
207 // detected to support it.
208 if (has_os_support) {
209 UMA_HISTOGRAM_BOOLEAN(
210 "Startup.BrowserMessageLoopStartHardFaultCount.Success",
211 success);
212 }
213
214 // Don't log a histogram value if unable to get the hard fault count.
215 if (!success)
216 return;
217
218 // Hard fault counts are expected to be in the thousands range,
219 // corresponding to faulting in ~10s of MBs of code ~10s of KBs at a time.
220 // (Observed to vary from 1000 to 10000 on various test machines and
221 // platforms.)
222 if (is_first_run) {
223 UMA_HISTOGRAM_CUSTOM_COUNTS(
224 "Startup.BrowserMessageLoopStartHardFaultCount.FirstRun",
225 hard_fault_count,
226 0, 40000, 50);
227 } else {
228 UMA_HISTOGRAM_CUSTOM_COUNTS(
229 "Startup.BrowserMessageLoopStartHardFaultCount",
230 hard_fault_count,
231 0, 40000, 50);
232 }
233
234 // Determine the startup type based on the number of observed hard faults.
235 DCHECK_EQ(UNCERTAIN_STARTUP_TEMPERATURE, g_startup_temperature);
236 if (hard_fault_count < WARM_START_HARD_FAULT_COUNT_THRESHOLD) {
237 g_startup_temperature = WARM_STARTUP_TEMPERATURE;
238 } else if (hard_fault_count >= COLD_START_HARD_FAULT_COUNT_THRESHOLD) {
239 g_startup_temperature = COLD_STARTUP_TEMPERATURE;
240 }
241
242 // Record the startup 'temperature'.
243 UMA_HISTOGRAM_ENUMERATION(
244 "Startup.Temperature", g_startup_temperature, STARTUP_TEMPERATURE_MAX);
245 #endif // defined(OS_WIN)
246 }
247
248 // Converts a base::Time value to a base::TimeTicks value. The conversion isn't
249 // exact, but is within the time delta taken to synchronously resolve
250 // base::Time::Now() and base::TimeTicks::Now() which in practice is pretty
251 // much instant compared to multi-seconds startup timings.
252 // TODO(gab): Find a precise way to do this (http://crbug.com/544131).
253 base::TimeTicks StartupTimeToTimeTicks(const base::Time& time) {
254 // First get a base which represents the same point in time in both units.
255 // The wall clock time it takes to gather both of these is the precision of
256 // this method.
257 static const base::Time time_base = base::Time::Now();
258 static const base::TimeTicks trace_ticks_base = base::TimeTicks::Now();
259
260 // Then use the TimeDelta common ground between the two units to make the
261 // conversion.
262 const base::TimeDelta delta_since_base = time_base - time;
263 return trace_ticks_base - delta_since_base;
264 }
265
266 // Record time of main entry so it can be read from Telemetry performance tests.
267 // TODO(jeremy): Remove once crbug.com/317481 is fixed.
268 void RecordMainEntryTimeHistogram() {
269 const int kLowWordMask = 0xFFFFFFFF;
270 const int kLower31BitsMask = 0x7FFFFFFF;
271 DCHECK(!MainEntryPointTime().is_null());
272 base::TimeDelta browser_main_entry_time_absolute =
273 MainEntryPointTime() - base::Time::UnixEpoch();
274
275 uint64 browser_main_entry_time_raw_ms =
276 browser_main_entry_time_absolute.InMilliseconds();
277
278 base::TimeDelta browser_main_entry_time_raw_ms_high_word =
279 base::TimeDelta::FromMilliseconds(
280 (browser_main_entry_time_raw_ms >> 32) & kLowWordMask);
281 // Shift by one because histograms only support non-negative values.
282 base::TimeDelta browser_main_entry_time_raw_ms_low_word =
283 base::TimeDelta::FromMilliseconds(
284 (browser_main_entry_time_raw_ms >> 1) & kLower31BitsMask);
285
286 // A timestamp is a 64 bit value, yet histograms can only store 32 bits.
287 LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteHighWord",
288 browser_main_entry_time_raw_ms_high_word);
289 LOCAL_HISTOGRAM_TIMES("Startup.BrowserMainEntryTimeAbsoluteLowWord",
290 browser_main_entry_time_raw_ms_low_word);
291 }
292
293 // Environment variable that stores the timestamp when the executable's main()
294 // function was entered.
295 const char kChromeMainTimeEnvVar[] = "CHROME_MAIN_TIME";
296
297 // Returns the time of main entry recorded from RecordExeMainEntryTime.
298 base::Time ExeMainEntryPointTime() {
299 scoped_ptr<base::Environment> env(base::Environment::Create());
300 std::string time_string;
301 int64 time_int = 0;
302 if (env->GetVar(kChromeMainTimeEnvVar, &time_string) &&
303 base::StringToInt64(time_string, &time_int)) {
304 return base::Time::FromInternalValue(time_int);
305 }
306 return base::Time();
307 }
308
309 } // namespace
310
311 bool WasNonBrowserUIDisplayed() {
312 return g_non_browser_ui_displayed;
313 }
314
315 void SetNonBrowserUIDisplayed() {
316 g_non_browser_ui_displayed = true;
317 }
318
319 void RecordStartupProcessCreationTime(const base::Time& time) {
320 DCHECK(g_process_creation_time.Get().is_null());
321 g_process_creation_time.Get() = time;
322 DCHECK(!g_process_creation_time.Get().is_null());
323 }
324
325 void RecordMainEntryPointTime(const base::Time& time) {
326 DCHECK(MainEntryPointTime().is_null());
327 g_main_entry_point_time.Get() = time;
328 DCHECK(!MainEntryPointTime().is_null());
329 }
330
331 void RecordExeMainEntryPointTime(const base::Time& time) {
332 std::string exe_load_time = base::Int64ToString(time.ToInternalValue());
333 scoped_ptr<base::Environment> env(base::Environment::Create());
334 env->SetVar(kChromeMainTimeEnvVar, exe_load_time);
335 }
336
337 void RecordBrowserMainMessageLoopStart(const base::Time& time,
338 bool is_first_run) {
339 RecordHardFaultHistogram(is_first_run);
340 RecordMainEntryTimeHistogram();
341
342 const base::Time& process_creation_time = g_process_creation_time.Get();
343 if (!is_first_run && !process_creation_time.is_null()) {
344 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
345 UMA_HISTOGRAM_LONG_TIMES_100, "Startup.BrowserMessageLoopStartTime",
346 process_creation_time, time);
347 }
348
349 // Bail if uptime < 7 minutes, to filter out cases where Chrome may have been
350 // autostarted and the machine is under io pressure.
351 if (base::SysInfo::Uptime() < base::TimeDelta::FromMinutes(7))
352 return;
353
354 // The Startup.BrowserMessageLoopStartTime histogram exhibits instability in
355 // the field which limits its usefulness in all scenarios except when we have
356 // a very large sample size. Attempt to mitigate this with a new metric:
357 // * Measure time from main entry rather than the OS' notion of process start.
358 // * Only measure launches that occur 7 minutes after boot to try to avoid
359 // cases where Chrome is auto-started and IO is heavily loaded.
360 const base::Time dll_main_time = MainEntryPointTime();
361 if (is_first_run) {
362 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
363 UMA_HISTOGRAM_LONG_TIMES,
364 "Startup.BrowserMessageLoopStartTimeFromMainEntry.FirstRun",
365 dll_main_time, time);
366 } else {
367 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
368 UMA_HISTOGRAM_LONG_TIMES,
369 "Startup.BrowserMessageLoopStartTimeFromMainEntry", dll_main_time,
370 time);
371 }
372
373 // Record timings between process creation, the main() in the executable being
374 // reached and the main() in the shared library being reached.
375 if (!process_creation_time.is_null()) {
376 const base::Time exe_main_time = ExeMainEntryPointTime();
377 if (!exe_main_time.is_null()) {
378 // Process create to chrome.exe:main().
379 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
380 UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToExeMain",
381 process_creation_time, exe_main_time);
382
383 // chrome.exe:main() to chrome.dll:main().
384 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
385 UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ExeMainToDllMain",
386 exe_main_time, dll_main_time);
387
388 // Process create to chrome.dll:main(). Reported as a histogram only as
389 // the other two events above are sufficient for tracing purposes.
390 UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
391 UMA_HISTOGRAM_LONG_TIMES, "Startup.LoadTime.ProcessCreateToDllMain",
392 dll_main_time - process_creation_time);
393 }
394 }
395 }
396
397 void RecordBrowserWindowDisplay(const base::Time& time) {
398 static bool is_first_call = true;
399 if (!is_first_call || time.is_null())
400 return;
401 is_first_call = false;
402 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
403 return;
404
405 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
406 UMA_HISTOGRAM_LONG_TIMES, "Startup.BrowserWindowDisplay",
407 g_process_creation_time.Get(), time);
408 }
409
410 void RecordBrowserOpenTabsDelta(const base::TimeDelta& delta) {
411 static bool is_first_call = true;
412 if (!is_first_call)
413 return;
414 is_first_call = false;
415
416 UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(UMA_HISTOGRAM_LONG_TIMES_100,
417 "Startup.BrowserOpenTabs", delta);
418 }
419
420 void RecordFirstWebContentsMainFrameLoad(const base::Time& time) {
421 static bool is_first_call = true;
422 if (!is_first_call || time.is_null())
423 return;
424 is_first_call = false;
425 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
426 return;
427
428 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
429 UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad2",
430 g_process_creation_time.Get(), time);
431 }
432
433 void RecordDeprecatedFirstWebContentsMainFrameLoad(const base::Time& time) {
434 static bool is_first_call = true;
435 if (!is_first_call || time.is_null())
436 return;
437 is_first_call = false;
438 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
439 return;
440
441 UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
442 UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.MainFrameLoad",
443 time - g_process_creation_time.Get());
444 }
445
446 void RecordFirstWebContentsNonEmptyPaint(const base::Time& time) {
447 static bool is_first_call = true;
448 if (!is_first_call || time.is_null())
449 return;
450 is_first_call = false;
451 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
452 return;
453
454 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
455 UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.NonEmptyPaint2",
456 g_process_creation_time.Get(), time);
457 }
458
459 void RecordDeprecatedFirstWebContentsNonEmptyPaint(const base::Time& time) {
460 static bool is_first_call = true;
461 if (!is_first_call || time.is_null())
462 return;
463 is_first_call = false;
464 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
465 return;
466
467 UMA_HISTOGRAM_WITH_STARTUP_TEMPERATURE(
468 UMA_HISTOGRAM_LONG_TIMES_100, "Startup.FirstWebContents.NonEmptyPaint",
469 time - g_process_creation_time.Get());
470 }
471
472 void RecordFirstWebContentsMainNavigationStart(const base::Time& time) {
473 static bool is_first_call = true;
474 if (!is_first_call || time.is_null())
475 return;
476 is_first_call = false;
477 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
478 return;
479
480 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
481 UMA_HISTOGRAM_LONG_TIMES_100,
482 "Startup.FirstWebContents.MainNavigationStart",
483 g_process_creation_time.Get(), time);
484 }
485
486 void RecordFirstWebContentsMainNavigationFinished(const base::Time& time) {
487 static bool is_first_call = true;
488 if (!is_first_call || time.is_null())
489 return;
490 is_first_call = false;
491 if (WasNonBrowserUIDisplayed() || g_process_creation_time.Get().is_null())
492 return;
493
494 UMA_HISTOGRAM_AND_TRACE_WITH_STARTUP_TEMPERATURE(
495 UMA_HISTOGRAM_LONG_TIMES_100,
496 "Startup.FirstWebContents.MainNavigationFinished",
497 g_process_creation_time.Get(), time);
498 }
499
500 base::Time MainEntryPointTime() {
501 return g_main_entry_point_time.Get();
502 }
503
504 StartupTemperature GetStartupTemperature() {
505 return g_startup_temperature;
506 }
507
508 } // namespace startup_metric_utils
OLDNEW
« no previous file with comments | « components/startup_metric_utils/startup_metric_utils.h ('k') | no next file » | no next file with comments »

Powered by Google App Engine
This is Rietveld 408576698