1 // Copyright (c) 2011 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 "chrome/browser/chromeos/boot_times_loader.h"
6
7 #include <vector>
8
9 #include "base/command_line.h"
10 #include "base/file_path.h"
11 #include "base/file_util.h"
12 #include "base/lazy_instance.h"
13 #include "base/message_loop.h"
14 #include "base/metrics/histogram.h"
15 #include "base/process_util.h"
16 #include "base/string_number_conversions.h"
17 #include "base/string_util.h"
18 #include "base/stringprintf.h"
19 #include "base/threading/thread.h"
20 #include "base/threading/thread_restrictions.h"
21 #include "base/time.h"
22 #include "chrome/browser/browser_process.h"
23 #include "chrome/browser/chromeos/login/authentication_notification_details.h"
24 #include "chrome/browser/chromeos/login/user_manager.h"
25 #include "chrome/browser/chromeos/network_state_notifier.h"
26 #include "chrome/common/chrome_switches.h"
27 #include "content/browser/browser_thread.h"
28 #include "content/common/notification_service.h"
29
30 namespace chromeos {
31
32 #define FPL(value) FILE_PATH_LITERAL(value)
33
34 // File uptime logs are located in.
35 static const FilePath::CharType kLogPath[] = FPL("/tmp");
36 // Prefix for the time measurement files.
37 static const FilePath::CharType kUptimePrefix[] = FPL("uptime-");
38 // Prefix for the disk usage files.
39 static const FilePath::CharType kDiskPrefix[] = FPL("disk-");
40 // Name of the time that Chrome's main() is called.
41 static const FilePath::CharType kChromeMain[] = FPL("chrome-main");
42 // Delay in milliseconds between file read attempts.
43 static const int64 kReadAttemptDelayMs = 250;
44 // Delay in milliseconds before writing the login times to disk.
45 static const int64 kLoginTimeWriteDelayMs = 3000;
46
47 // Names of login stats files.
48 static const FilePath::CharType kLoginSuccess[] = FPL("login-success");
49 static const FilePath::CharType kChromeFirstRender[] =
50 FPL("chrome-first-render");
51
52 // Names of login UMA values.
53 static const char kUmaAuthenticate[] = "BootTime.Authenticate";
54 static const char kUmaLogin[] = "BootTime.Login";
55 static const char kUmaLoginPrefix[] = "BootTime.";
56 static const char kUmaLogout[] = "ShutdownTime.Logout";
57 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
58
59 // Name of file collecting login times.
60 static const FilePath::CharType kLoginTimes[] = FPL("login-times-sent");
61
62 // Name of file collecting logout times.
63 static const char kLogoutTimes[] = "logout-times-sent";
64
65 static base::LazyInstance<BootTimesLoader> g_boot_times_loader(
66 base::LINKER_INITIALIZED);
67
BootTimesLoader()68 BootTimesLoader::BootTimesLoader()
69 : backend_(new Backend()),
70 have_registered_(false) {
71 login_time_markers_.reserve(30);
72 logout_time_markers_.reserve(30);
73 }
74
75 // static
Get()76 BootTimesLoader* BootTimesLoader::Get() {
77 return g_boot_times_loader.Pointer();
78 }
79
GetBootTimes(CancelableRequestConsumerBase * consumer,BootTimesLoader::GetBootTimesCallback * callback)80 BootTimesLoader::Handle BootTimesLoader::GetBootTimes(
81 CancelableRequestConsumerBase* consumer,
82 BootTimesLoader::GetBootTimesCallback* callback) {
83 if (!g_browser_process->file_thread()) {
84 // This should only happen if Chrome is shutting down, so we don't do
85 // anything.
86 return 0;
87 }
88
89 const CommandLine& command_line = *CommandLine::ForCurrentProcess();
90 if (command_line.HasSwitch(switches::kTestType)) {
91 // TODO(davemoore) This avoids boottimes for tests. This needs to be
92 // replaced with a mock of BootTimesLoader.
93 return 0;
94 }
95
96 scoped_refptr<CancelableRequest<GetBootTimesCallback> > request(
97 new CancelableRequest<GetBootTimesCallback>(callback));
98 AddRequest(request, consumer);
99
100 BrowserThread::PostTask(
101 BrowserThread::FILE,
102 FROM_HERE,
103 NewRunnableMethod(backend_.get(), &Backend::GetBootTimes, request));
104 return request->handle();
105 }
106
107 // Extracts the uptime value from files located in /tmp, returning the
108 // value as a double in value.
GetTime(const FilePath::StringType & log,double * value)109 static bool GetTime(const FilePath::StringType& log, double* value) {
110 FilePath log_dir(kLogPath);
111 FilePath log_file = log_dir.Append(log);
112 std::string contents;
113 *value = 0.0;
114 if (file_util::ReadFileToString(log_file, &contents)) {
115 size_t space_index = contents.find(' ');
116 size_t chars_left =
117 space_index != std::string::npos ? space_index : std::string::npos;
118 std::string value_string = contents.substr(0, chars_left);
119 return base::StringToDouble(value_string, value);
120 }
121 return false;
122 }
123
124 // Converts double seconds to a TimeDelta object.
SecondsToTimeDelta(double seconds)125 static base::TimeDelta SecondsToTimeDelta(double seconds) {
126 double ms = seconds * base::Time::kMillisecondsPerSecond;
127 return base::TimeDelta::FromMilliseconds(static_cast<int64>(ms));
128 }
129
130 // Reports the collected boot times to UMA if they haven't been
131 // reported yet and if metrics collection is enabled.
SendBootTimesToUMA(const BootTimesLoader::BootTimes & boot_times)132 static void SendBootTimesToUMA(const BootTimesLoader::BootTimes& boot_times) {
133 // Checks if the times for the most recent boot event have been
134 // reported already to avoid sending boot time histogram samples
135 // every time the user logs out.
136 static const FilePath::CharType kBootTimesSent[] =
137 FPL("/tmp/boot-times-sent");
138 FilePath sent(kBootTimesSent);
139 if (file_util::PathExists(sent))
140 return;
141
142 UMA_HISTOGRAM_TIMES("BootTime.Total",
143 SecondsToTimeDelta(boot_times.total));
144 UMA_HISTOGRAM_TIMES("BootTime.Firmware",
145 SecondsToTimeDelta(boot_times.firmware));
146 UMA_HISTOGRAM_TIMES("BootTime.Kernel",
147 SecondsToTimeDelta(boot_times.pre_startup));
148 UMA_HISTOGRAM_TIMES("BootTime.System",
149 SecondsToTimeDelta(boot_times.system));
150 if (boot_times.chrome > 0) {
151 UMA_HISTOGRAM_TIMES("BootTime.Chrome",
152 SecondsToTimeDelta(boot_times.chrome));
153 }
154
155 // Stores the boot times to a file in /tmp to indicate that the
156 // times for the most recent boot event have been reported
157 // already. The file will be deleted at system shutdown/reboot.
158 std::string boot_times_text = base::StringPrintf("total: %.2f\n"
159 "firmware: %.2f\n"
160 "kernel: %.2f\n"
161 "system: %.2f\n"
162 "chrome: %.2f\n",
163 boot_times.total,
164 boot_times.firmware,
165 boot_times.pre_startup,
166 boot_times.system,
167 boot_times.chrome);
168 file_util::WriteFile(sent, boot_times_text.data(), boot_times_text.size());
169 DCHECK(file_util::PathExists(sent));
170 }
171
GetBootTimes(scoped_refptr<GetBootTimesRequest> request)172 void BootTimesLoader::Backend::GetBootTimes(
173 scoped_refptr<GetBootTimesRequest> request) {
174 const FilePath::CharType kFirmwareBootTime[] = FPL("firmware-boot-time");
175 const FilePath::CharType kPreStartup[] = FPL("pre-startup");
176 const FilePath::CharType kChromeExec[] = FPL("chrome-exec");
177 const FilePath::CharType kChromeMain[] = FPL("chrome-main");
178 const FilePath::CharType kXStarted[] = FPL("x-started");
179 const FilePath::CharType kLoginPromptReady[] = FPL("login-prompt-ready");
180 const FilePath::StringType uptime_prefix = kUptimePrefix;
181
182 if (request->canceled())
183 return;
184
185 // Wait until firmware-boot-time file exists by reposting.
186 FilePath log_dir(kLogPath);
187 FilePath log_file = log_dir.Append(kFirmwareBootTime);
188 if (!file_util::PathExists(log_file)) {
189 BrowserThread::PostDelayedTask(
190 BrowserThread::FILE,
191 FROM_HERE,
192 NewRunnableMethod(this, &Backend::GetBootTimes, request),
193 kReadAttemptDelayMs);
194 return;
195 }
196
197 BootTimes boot_times;
198
199 GetTime(kFirmwareBootTime, &boot_times.firmware);
200 GetTime(uptime_prefix + kPreStartup, &boot_times.pre_startup);
201 GetTime(uptime_prefix + kXStarted, &boot_times.x_started);
202 GetTime(uptime_prefix + kChromeExec, &boot_times.chrome_exec);
203 GetTime(uptime_prefix + kChromeMain, &boot_times.chrome_main);
204 GetTime(uptime_prefix + kLoginPromptReady, &boot_times.login_prompt_ready);
205
206 boot_times.total = boot_times.firmware + boot_times.login_prompt_ready;
207 if (boot_times.chrome_exec > 0) {
208 boot_times.system = boot_times.chrome_exec - boot_times.pre_startup;
209 boot_times.chrome = boot_times.login_prompt_ready - boot_times.chrome_exec;
210 } else {
211 boot_times.system = boot_times.login_prompt_ready - boot_times.pre_startup;
212 }
213
214 SendBootTimesToUMA(boot_times);
215
216 request->ForwardResult(
217 GetBootTimesCallback::TupleType(request->handle(), boot_times));
218 }
219
220 // Appends the given buffer into the file. Returns the number of bytes
221 // written, or -1 on error.
222 // TODO(satorux): Move this to file_util.
AppendFile(const FilePath & file_path,const char * data,int size)223 static int AppendFile(const FilePath& file_path,
224 const char* data,
225 int size) {
226 FILE* file = file_util::OpenFile(file_path, "a");
227 if (!file) {
228 return -1;
229 }
230 const int num_bytes_written = fwrite(data, 1, size, file);
231 file_util::CloseFile(file);
232 return num_bytes_written;
233 }
234
RecordStatsDelayed(const FilePath::StringType & name,const std::string & uptime,const std::string & disk)235 static void RecordStatsDelayed(const FilePath::StringType& name,
236 const std::string& uptime,
237 const std::string& disk) {
238 const FilePath log_path(kLogPath);
239 const FilePath uptime_output =
240 log_path.Append(FilePath(kUptimePrefix + name));
241 const FilePath disk_output = log_path.Append(FilePath(kDiskPrefix + name));
242
243 // Append numbers to the files.
244 AppendFile(uptime_output, uptime.data(), uptime.size());
245 AppendFile(disk_output, disk.data(), disk.size());
246 }
247
248 // static
WriteTimes(const std::string base_name,const std::string uma_name,const std::string uma_prefix,const std::vector<TimeMarker> login_times)249 void BootTimesLoader::WriteTimes(
250 const std::string base_name,
251 const std::string uma_name,
252 const std::string uma_prefix,
253 const std::vector<TimeMarker> login_times) {
254 const int kMinTimeMillis = 1;
255 const int kMaxTimeMillis = 30000;
256 const int kNumBuckets = 100;
257 const FilePath log_path(kLogPath);
258
259 base::Time first = login_times.front().time();
260 base::Time last = login_times.back().time();
261 base::TimeDelta total = last - first;
262 base::Histogram* total_hist = base::Histogram::FactoryTimeGet(
263 uma_name,
264 base::TimeDelta::FromMilliseconds(kMinTimeMillis),
265 base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
266 kNumBuckets,
267 base::Histogram::kUmaTargetedHistogramFlag);
268 total_hist->AddTime(total);
269 std::string output =
270 base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
271 base::Time prev = first;
272 for (unsigned int i = 0; i < login_times.size(); ++i) {
273 TimeMarker tm = login_times[i];
274 base::TimeDelta since_first = tm.time() - first;
275 base::TimeDelta since_prev = tm.time() - prev;
276 std::string name;
277
278 if (tm.send_to_uma()) {
279 name = uma_prefix + tm.name();
280 base::Histogram* prev_hist = base::Histogram::FactoryTimeGet(
281 name,
282 base::TimeDelta::FromMilliseconds(kMinTimeMillis),
283 base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
284 kNumBuckets,
285 base::Histogram::kUmaTargetedHistogramFlag);
286 prev_hist->AddTime(since_prev);
287 } else {
288 name = tm.name();
289 }
290 output +=
291 StringPrintf(
292 "\n%.2f +%.2f %s",
293 since_first.InSecondsF(),
294 since_prev.InSecondsF(),
295 name.data());
296 prev = tm.time();
297 }
298 file_util::WriteFile(
299 log_path.Append(base_name), output.data(), output.size());
300 }
301
WriteLogoutTimes()302 void BootTimesLoader::WriteLogoutTimes() {
303 WriteTimes(kLogoutTimes,
304 kUmaLogout,
305 kUmaLogoutPrefix,
306 logout_time_markers_);
307 }
308
RecordStats(const std::string & name,const Stats & stats)309 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
310 BrowserThread::PostTask(
311 BrowserThread::FILE, FROM_HERE,
312 NewRunnableFunction(
313 RecordStatsDelayed, name, stats.uptime, stats.disk));
314 }
315
GetCurrentStats()316 BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
317 const FilePath kProcUptime(FPL("/proc/uptime"));
318 const FilePath kDiskStat(FPL("/sys/block/sda/stat"));
319 Stats stats;
320 base::ThreadRestrictions::ScopedAllowIO allow_io;
321 file_util::ReadFileToString(kProcUptime, &stats.uptime);
322 file_util::ReadFileToString(kDiskStat, &stats.disk);
323 return stats;
324 }
325
RecordCurrentStats(const std::string & name)326 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
327 RecordStats(name, GetCurrentStats());
328 }
329
SaveChromeMainStats()330 void BootTimesLoader::SaveChromeMainStats() {
331 chrome_main_stats_ = GetCurrentStats();
332 }
333
RecordChromeMainStats()334 void BootTimesLoader::RecordChromeMainStats() {
335 RecordStats(kChromeMain, chrome_main_stats_);
336 }
337
RecordLoginAttempted()338 void BootTimesLoader::RecordLoginAttempted() {
339 login_time_markers_.clear();
340 AddLoginTimeMarker("LoginStarted", false);
341 if (!have_registered_) {
342 have_registered_ = true;
343 registrar_.Add(this, NotificationType::LOAD_START,
344 NotificationService::AllSources());
345 registrar_.Add(this, NotificationType::LOGIN_AUTHENTICATION,
346 NotificationService::AllSources());
347 }
348 }
349
AddLoginTimeMarker(const std::string & marker_name,bool send_to_uma)350 void BootTimesLoader::AddLoginTimeMarker(
351 const std::string& marker_name, bool send_to_uma) {
352 login_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
353 }
354
AddLogoutTimeMarker(const std::string & marker_name,bool send_to_uma)355 void BootTimesLoader::AddLogoutTimeMarker(
356 const std::string& marker_name, bool send_to_uma) {
357 logout_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
358 }
359
Observe(NotificationType type,const NotificationSource & source,const NotificationDetails & details)360 void BootTimesLoader::Observe(
361 NotificationType type,
362 const NotificationSource& source,
363 const NotificationDetails& details) {
364 if (type == NotificationType::LOGIN_AUTHENTICATION) {
365 Details<AuthenticationNotificationDetails> auth_details(details);
366 if (auth_details->success()) {
367 AddLoginTimeMarker("Authenticate", true);
368 RecordCurrentStats(kLoginSuccess);
369 registrar_.Remove(this, NotificationType::LOGIN_AUTHENTICATION,
370 NotificationService::AllSources());
371 }
372 } else if (type == NotificationType::LOAD_START) {
373 // Make sure it's not some page load initiated by OOBE/login screen.
374 if (!UserManager::Get()->user_is_logged_in())
375 return;
376 // Only log for first tab to render. Make sure this is only done once.
377 // If the network isn't connected we'll get a second LOAD_START once it is
378 // and the page is reloaded.
379 if (NetworkStateNotifier::GetInstance()->is_connected()) {
380 // Post difference between first tab and login success time.
381 AddLoginTimeMarker("LoginDone", true);
382 RecordCurrentStats(kChromeFirstRender);
383 // Post chrome first render stat.
384 registrar_.Remove(this, NotificationType::LOAD_START,
385 NotificationService::AllSources());
386 // Don't swamp the FILE thread right away.
387 BrowserThread::PostDelayedTask(
388 BrowserThread::FILE, FROM_HERE,
389 // This doesn't compile without std::string(...), as
390 // NewRunnableFunction doesn't accept arrays.
391 NewRunnableFunction(WriteTimes,
392 std::string(kLoginTimes),
393 std::string(kUmaLogin),
394 std::string(kUmaLoginPrefix),
395 login_time_markers_),
396 kLoginTimeWriteDelayMs);
397 have_registered_ = false;
398 } else {
399 AddLoginTimeMarker("LoginRenderNoNetwork", false);
400 }
401 }
402 }
403
404 } // namespace chromeos
405