1dc0f95d653279beabeb9817299e2902918ba123eKristian Monsen// Copyright (c) 2011 The Chromium Authors. All rights reserved. 2c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Use of this source code is governed by a BSD-style license that can be 3c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// found in the LICENSE file. 4c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 5c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "chrome/browser/chromeos/boot_times_loader.h" 6c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 7c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include <vector> 8c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 9c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/command_line.h" 10c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/file_path.h" 11c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/file_util.h" 1221d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsen#include "base/lazy_instance.h" 13c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/message_loop.h" 14731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick#include "base/metrics/histogram.h" 15c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/process_util.h" 163345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick#include "base/string_number_conversions.h" 17c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/string_util.h" 183345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick#include "base/stringprintf.h" 193f50c38dc070f4bb515c1b64450dae14f316474eKristian Monsen#include "base/threading/thread.h" 203f50c38dc070f4bb515c1b64450dae14f316474eKristian Monsen#include "base/threading/thread_restrictions.h" 21c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "base/time.h" 22c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "chrome/browser/browser_process.h" 23c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "chrome/browser/chromeos/login/authentication_notification_details.h" 24201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch#include "chrome/browser/chromeos/login/user_manager.h" 25c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "chrome/browser/chromeos/network_state_notifier.h" 26c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch#include "chrome/common/chrome_switches.h" 27dc0f95d653279beabeb9817299e2902918ba123eKristian Monsen#include "content/browser/browser_thread.h" 28dc0f95d653279beabeb9817299e2902918ba123eKristian Monsen#include "content/common/notification_service.h" 29c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 30c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochnamespace chromeos { 31c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 32201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch#define FPL(value) FILE_PATH_LITERAL(value) 33201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch 34c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// File uptime logs are located in. 35201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kLogPath[] = FPL("/tmp"); 36c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Prefix for the time measurement files. 37201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kUptimePrefix[] = FPL("uptime-"); 38c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Prefix for the disk usage files. 39201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kDiskPrefix[] = FPL("disk-"); 40c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Name of the time that Chrome's main() is called. 41201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kChromeMain[] = FPL("chrome-main"); 42c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Delay in milliseconds between file read attempts. 43c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochstatic const int64 kReadAttemptDelayMs = 250; 44731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick// Delay in milliseconds before writing the login times to disk. 45731df977c0511bca2206b5f333555b1205ff1f43Iain Merrickstatic const int64 kLoginTimeWriteDelayMs = 3000; 46c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 47c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Names of login stats files. 48201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kLoginSuccess[] = FPL("login-success"); 49201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kChromeFirstRender[] = 50201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch FPL("chrome-first-render"); 51c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 52c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Names of login UMA values. 53c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochstatic const char kUmaAuthenticate[] = "BootTime.Authenticate"; 54c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochstatic const char kUmaLogin[] = "BootTime.Login"; 55201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const char kUmaLoginPrefix[] = "BootTime."; 56201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const char kUmaLogout[] = "ShutdownTime.Logout"; 57201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const char kUmaLogoutPrefix[] = "ShutdownTime."; 58c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 59c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Name of file collecting login times. 60201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const FilePath::CharType kLoginTimes[] = FPL("login-times-sent"); 61201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch 62201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch// Name of file collecting logout times. 63201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic const char kLogoutTimes[] = "logout-times-sent"; 64c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 6521d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsenstatic base::LazyInstance<BootTimesLoader> g_boot_times_loader( 6621d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsen base::LINKER_INITIALIZED); 6721d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsen 68c407dc5cd9bdc5668497f21b26b09d988ab439deBen MurdochBootTimesLoader::BootTimesLoader() 69c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch : backend_(new Backend()), 70c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch have_registered_(false) { 71731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick login_time_markers_.reserve(30); 72201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch logout_time_markers_.reserve(30); 73c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 74c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 75c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// static 76c407dc5cd9bdc5668497f21b26b09d988ab439deBen MurdochBootTimesLoader* BootTimesLoader::Get() { 7721d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsen return g_boot_times_loader.Pointer(); 78c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 79c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 80c407dc5cd9bdc5668497f21b26b09d988ab439deBen MurdochBootTimesLoader::Handle BootTimesLoader::GetBootTimes( 81c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch CancelableRequestConsumerBase* consumer, 82c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch BootTimesLoader::GetBootTimesCallback* callback) { 83c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (!g_browser_process->file_thread()) { 84c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // This should only happen if Chrome is shutting down, so we don't do 85c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // anything. 86c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return 0; 87c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 88c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 89c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const CommandLine& command_line = *CommandLine::ForCurrentProcess(); 90c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (command_line.HasSwitch(switches::kTestType)) { 91c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // TODO(davemoore) This avoids boottimes for tests. This needs to be 92c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // replaced with a mock of BootTimesLoader. 93c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return 0; 94c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 95c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 96c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch scoped_refptr<CancelableRequest<GetBootTimesCallback> > request( 97c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch new CancelableRequest<GetBootTimesCallback>(callback)); 98c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch AddRequest(request, consumer); 99c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 100731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::PostTask( 101731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::FILE, 102c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FROM_HERE, 103c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NewRunnableMethod(backend_.get(), &Backend::GetBootTimes, request)); 104c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return request->handle(); 105c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 106c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 107c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Extracts the uptime value from files located in /tmp, returning the 108c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// value as a double in value. 109201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic bool GetTime(const FilePath::StringType& log, double* value) { 110c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FilePath log_dir(kLogPath); 111c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FilePath log_file = log_dir.Append(log); 112c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch std::string contents; 113c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch *value = 0.0; 114c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (file_util::ReadFileToString(log_file, &contents)) { 115c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch size_t space_index = contents.find(' '); 116c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch size_t chars_left = 117c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch space_index != std::string::npos ? space_index : std::string::npos; 118c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch std::string value_string = contents.substr(0, chars_left); 1193345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick return base::StringToDouble(value_string, value); 120c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 121c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return false; 122c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 123c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 124c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Converts double seconds to a TimeDelta object. 125c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochstatic base::TimeDelta SecondsToTimeDelta(double seconds) { 126c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch double ms = seconds * base::Time::kMillisecondsPerSecond; 127c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return base::TimeDelta::FromMilliseconds(static_cast<int64>(ms)); 128c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 129c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 130c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// Reports the collected boot times to UMA if they haven't been 131c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch// reported yet and if metrics collection is enabled. 132c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochstatic void SendBootTimesToUMA(const BootTimesLoader::BootTimes& boot_times) { 133c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // Checks if the times for the most recent boot event have been 134c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // reported already to avoid sending boot time histogram samples 135c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // every time the user logs out. 136201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch static const FilePath::CharType kBootTimesSent[] = 137201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch FPL("/tmp/boot-times-sent"); 138c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FilePath sent(kBootTimesSent); 139c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (file_util::PathExists(sent)) 140c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return; 141c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 142c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch UMA_HISTOGRAM_TIMES("BootTime.Total", 143c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SecondsToTimeDelta(boot_times.total)); 144c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch UMA_HISTOGRAM_TIMES("BootTime.Firmware", 145c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SecondsToTimeDelta(boot_times.firmware)); 146c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch UMA_HISTOGRAM_TIMES("BootTime.Kernel", 147c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SecondsToTimeDelta(boot_times.pre_startup)); 148c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch UMA_HISTOGRAM_TIMES("BootTime.System", 149c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SecondsToTimeDelta(boot_times.system)); 150c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (boot_times.chrome > 0) { 151c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch UMA_HISTOGRAM_TIMES("BootTime.Chrome", 152c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SecondsToTimeDelta(boot_times.chrome)); 153c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 154c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 155c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // Stores the boot times to a file in /tmp to indicate that the 156c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // times for the most recent boot event have been reported 157c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // already. The file will be deleted at system shutdown/reboot. 1583345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick std::string boot_times_text = base::StringPrintf("total: %.2f\n" 1593345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick "firmware: %.2f\n" 1603345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick "kernel: %.2f\n" 1613345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick "system: %.2f\n" 1623345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick "chrome: %.2f\n", 1633345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick boot_times.total, 1643345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick boot_times.firmware, 1653345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick boot_times.pre_startup, 1663345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick boot_times.system, 1673345a6884c488ff3a535c2c9acdd33d74b37e311Iain Merrick boot_times.chrome); 168c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch file_util::WriteFile(sent, boot_times_text.data(), boot_times_text.size()); 169c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch DCHECK(file_util::PathExists(sent)); 170c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 171c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 172c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::Backend::GetBootTimes( 173c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch scoped_refptr<GetBootTimesRequest> request) { 174201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kFirmwareBootTime[] = FPL("firmware-boot-time"); 175201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kPreStartup[] = FPL("pre-startup"); 176201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kChromeExec[] = FPL("chrome-exec"); 177201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kChromeMain[] = FPL("chrome-main"); 178201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kXStarted[] = FPL("x-started"); 179201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::CharType kLoginPromptReady[] = FPL("login-prompt-ready"); 180201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath::StringType uptime_prefix = kUptimePrefix; 181c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 182c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (request->canceled()) 183c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return; 184c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 185201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch // Wait until firmware-boot-time file exists by reposting. 186c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FilePath log_dir(kLogPath); 187201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch FilePath log_file = log_dir.Append(kFirmwareBootTime); 188c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (!file_util::PathExists(log_file)) { 189731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::PostDelayedTask( 190731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::FILE, 191c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch FROM_HERE, 192c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NewRunnableMethod(this, &Backend::GetBootTimes, request), 193c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch kReadAttemptDelayMs); 194c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return; 195c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 196c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 197c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch BootTimes boot_times; 198c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 199c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(kFirmwareBootTime, &boot_times.firmware); 200c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(uptime_prefix + kPreStartup, &boot_times.pre_startup); 201c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(uptime_prefix + kXStarted, &boot_times.x_started); 202c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(uptime_prefix + kChromeExec, &boot_times.chrome_exec); 203c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(uptime_prefix + kChromeMain, &boot_times.chrome_main); 204c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetTime(uptime_prefix + kLoginPromptReady, &boot_times.login_prompt_ready); 205c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 206c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch boot_times.total = boot_times.firmware + boot_times.login_prompt_ready; 207c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (boot_times.chrome_exec > 0) { 208c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch boot_times.system = boot_times.chrome_exec - boot_times.pre_startup; 209c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch boot_times.chrome = boot_times.login_prompt_ready - boot_times.chrome_exec; 210c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } else { 211c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch boot_times.system = boot_times.login_prompt_ready - boot_times.pre_startup; 212c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 213c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 214c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch SendBootTimesToUMA(boot_times); 215c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 216c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch request->ForwardResult( 217c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch GetBootTimesCallback::TupleType(request->handle(), boot_times)); 218c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 219c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 220201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch// Appends the given buffer into the file. Returns the number of bytes 221201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch// written, or -1 on error. 222201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch// TODO(satorux): Move this to file_util. 223201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic int AppendFile(const FilePath& file_path, 224201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const char* data, 225201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch int size) { 226201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch FILE* file = file_util::OpenFile(file_path, "a"); 227201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch if (!file) { 228201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch return -1; 229201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch } 230201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const int num_bytes_written = fwrite(data, 1, size, file); 231201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch file_util::CloseFile(file); 232201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch return num_bytes_written; 233201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch} 234201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch 235201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochstatic void RecordStatsDelayed(const FilePath::StringType& name, 236201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string& uptime, 237201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string& disk) { 238c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const FilePath log_path(kLogPath); 239c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const FilePath uptime_output = 240c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch log_path.Append(FilePath(kUptimePrefix + name)); 241c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const FilePath disk_output = log_path.Append(FilePath(kDiskPrefix + name)); 242c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 243201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch // Append numbers to the files. 244201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch AppendFile(uptime_output, uptime.data(), uptime.size()); 245201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch AppendFile(disk_output, disk.data(), disk.size()); 246c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 247c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 248731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick// static 249201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochvoid BootTimesLoader::WriteTimes( 250201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string base_name, 251201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string uma_name, 252201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string uma_prefix, 253731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick const std::vector<TimeMarker> login_times) { 254731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick const int kMinTimeMillis = 1; 255513209b27ff55e2841eac0e4120199c23acce758Ben Murdoch const int kMaxTimeMillis = 30000; 256731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick const int kNumBuckets = 100; 257c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const FilePath log_path(kLogPath); 258731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick 259731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::Time first = login_times.front().time(); 260731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::Time last = login_times.back().time(); 261731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta total = last - first; 262ddb351dbec246cf1fab5ec20d2d5520909041de1Kristian Monsen base::Histogram* total_hist = base::Histogram::FactoryTimeGet( 263201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch uma_name, 264731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta::FromMilliseconds(kMinTimeMillis), 265731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta::FromMilliseconds(kMaxTimeMillis), 266731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick kNumBuckets, 267731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::Histogram::kUmaTargetedHistogramFlag); 268731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick total_hist->AddTime(total); 269c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch std::string output = 270201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF()); 271731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::Time prev = first; 272731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick for (unsigned int i = 0; i < login_times.size(); ++i) { 273731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick TimeMarker tm = login_times[i]; 274731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta since_first = tm.time() - first; 275731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta since_prev = tm.time() - prev; 276731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick std::string name; 277731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick 278731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick if (tm.send_to_uma()) { 279201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch name = uma_prefix + tm.name(); 280ddb351dbec246cf1fab5ec20d2d5520909041de1Kristian Monsen base::Histogram* prev_hist = base::Histogram::FactoryTimeGet( 281731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick name, 282731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta::FromMilliseconds(kMinTimeMillis), 283731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::TimeDelta::FromMilliseconds(kMaxTimeMillis), 284731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick kNumBuckets, 285731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick base::Histogram::kUmaTargetedHistogramFlag); 286731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick prev_hist->AddTime(since_prev); 287731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick } else { 288731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick name = tm.name(); 289731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick } 290731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick output += 291731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick StringPrintf( 292731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick "\n%.2f +%.2f %s", 293731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick since_first.InSecondsF(), 294731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick since_prev.InSecondsF(), 295731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick name.data()); 296731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick prev = tm.time(); 297731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick } 298c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch file_util::WriteFile( 299201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch log_path.Append(base_name), output.data(), output.size()); 300201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch} 301201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch 302201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochvoid BootTimesLoader::WriteLogoutTimes() { 303201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch WriteTimes(kLogoutTimes, 304201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch kUmaLogout, 305201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch kUmaLogoutPrefix, 306201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch logout_time_markers_); 307c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 308c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 309c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) { 310731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::PostTask( 311731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::FILE, FROM_HERE, 312c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NewRunnableFunction( 313c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch RecordStatsDelayed, name, stats.uptime, stats.disk)); 314c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 315c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 316c407dc5cd9bdc5668497f21b26b09d988ab439deBen MurdochBootTimesLoader::Stats BootTimesLoader::GetCurrentStats() { 317201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath kProcUptime(FPL("/proc/uptime")); 318201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const FilePath kDiskStat(FPL("/sys/block/sda/stat")); 319c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch Stats stats; 320513209b27ff55e2841eac0e4120199c23acce758Ben Murdoch base::ThreadRestrictions::ScopedAllowIO allow_io; 321c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch file_util::ReadFileToString(kProcUptime, &stats.uptime); 322c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch file_util::ReadFileToString(kDiskStat, &stats.disk); 323c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch return stats; 324c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 325c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 326c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::RecordCurrentStats(const std::string& name) { 327c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch RecordStats(name, GetCurrentStats()); 328c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 329c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 330c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::SaveChromeMainStats() { 331c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch chrome_main_stats_ = GetCurrentStats(); 332c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 333c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 334c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::RecordChromeMainStats() { 335c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch RecordStats(kChromeMain, chrome_main_stats_); 336c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 337c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 338c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::RecordLoginAttempted() { 339731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick login_time_markers_.clear(); 340731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick AddLoginTimeMarker("LoginStarted", false); 341c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (!have_registered_) { 342c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch have_registered_ = true; 343c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch registrar_.Add(this, NotificationType::LOAD_START, 344c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NotificationService::AllSources()); 345c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch registrar_.Add(this, NotificationType::LOGIN_AUTHENTICATION, 346c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NotificationService::AllSources()); 347c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 348c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 349c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 350731df977c0511bca2206b5f333555b1205ff1f43Iain Merrickvoid BootTimesLoader::AddLoginTimeMarker( 351731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick const std::string& marker_name, bool send_to_uma) { 352731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick login_time_markers_.push_back(TimeMarker(marker_name, send_to_uma)); 353731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick} 354731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick 355201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdochvoid BootTimesLoader::AddLogoutTimeMarker( 356201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch const std::string& marker_name, bool send_to_uma) { 357201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch logout_time_markers_.push_back(TimeMarker(marker_name, send_to_uma)); 358201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch} 359201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch 360c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdochvoid BootTimesLoader::Observe( 361c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NotificationType type, 362c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const NotificationSource& source, 363c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch const NotificationDetails& details) { 364c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch if (type == NotificationType::LOGIN_AUTHENTICATION) { 365c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch Details<AuthenticationNotificationDetails> auth_details(details); 366731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick if (auth_details->success()) { 367731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick AddLoginTimeMarker("Authenticate", true); 368c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch RecordCurrentStats(kLoginSuccess); 369c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch registrar_.Remove(this, NotificationType::LOGIN_AUTHENTICATION, 370c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NotificationService::AllSources()); 371c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 372c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } else if (type == NotificationType::LOAD_START) { 373201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch // Make sure it's not some page load initiated by OOBE/login screen. 374201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch if (!UserManager::Get()->user_is_logged_in()) 375201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch return; 376c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // Only log for first tab to render. Make sure this is only done once. 377c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // If the network isn't connected we'll get a second LOAD_START once it is 378c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // and the page is reloaded. 37921d179b334e59e9a3bfcaed4c4430bef1bc5759dKristian Monsen if (NetworkStateNotifier::GetInstance()->is_connected()) { 380c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // Post difference between first tab and login success time. 381513209b27ff55e2841eac0e4120199c23acce758Ben Murdoch AddLoginTimeMarker("LoginDone", true); 382c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch RecordCurrentStats(kChromeFirstRender); 383c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch // Post chrome first render stat. 384c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch registrar_.Remove(this, NotificationType::LOAD_START, 385c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch NotificationService::AllSources()); 386731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick // Don't swamp the FILE thread right away. 387731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::PostDelayedTask( 388731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick BrowserThread::FILE, FROM_HERE, 389201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch // This doesn't compile without std::string(...), as 390201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch // NewRunnableFunction doesn't accept arrays. 391201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch NewRunnableFunction(WriteTimes, 392201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch std::string(kLoginTimes), 393201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch std::string(kUmaLogin), 394201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch std::string(kUmaLoginPrefix), 395201ade2fbba22bfb27ae029f4d23fca6ded109a0Ben Murdoch login_time_markers_), 396731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick kLoginTimeWriteDelayMs); 397c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch have_registered_ = false; 398731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick } else { 399731df977c0511bca2206b5f333555b1205ff1f43Iain Merrick AddLoginTimeMarker("LoginRenderNoNetwork", false); 400c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 401c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch } 402c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} 403c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch 404c407dc5cd9bdc5668497f21b26b09d988ab439deBen Murdoch} // namespace chromeos 405