1 // Copyright (c) 2012 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/bind.h"
10 #include "base/command_line.h"
11 #include "base/file_util.h"
12 #include "base/files/file_path.h"
13 #include "base/json/json_reader.h"
14 #include "base/json/json_writer.h"
15 #include "base/lazy_instance.h"
16 #include "base/location.h"
17 #include "base/message_loop/message_loop.h"
18 #include "base/message_loop/message_loop_proxy.h"
19 #include "base/metrics/histogram.h"
20 #include "base/prefs/pref_service.h"
21 #include "base/strings/string_number_conversions.h"
22 #include "base/strings/string_util.h"
23 #include "base/strings/stringprintf.h"
24 #include "base/threading/thread.h"
25 #include "base/threading/thread_restrictions.h"
26 #include "base/time/time.h"
27 #include "chrome/browser/browser_process.h"
28 #include "chrome/browser/chrome_notification_types.h"
29 #include "chrome/browser/chromeos/login/auth/authentication_notification_details.h"
30 #include "chrome/browser/chromeos/login/users/user_manager.h"
31 #include "chrome/browser/ui/browser.h"
32 #include "chrome/browser/ui/browser_iterator.h"
33 #include "chrome/browser/ui/tabs/tab_strip_model.h"
34 #include "chrome/common/chrome_switches.h"
35 #include "chrome/common/pref_names.h"
36 #include "content/public/browser/browser_thread.h"
37 #include "content/public/browser/navigation_controller.h"
38 #include "content/public/browser/notification_service.h"
39 #include "content/public/browser/render_widget_host_view.h"
40 #include "content/public/browser/web_contents.h"
41
42 using content::BrowserThread;
43 using content::NavigationController;
44 using content::RenderWidgetHost;
45 using content::RenderWidgetHostView;
46 using content::WebContents;
47
48 namespace {
49
50 const char kUptime[] = "uptime";
51 const char kDisk[] = "disk";
52
GetRenderWidgetHost(NavigationController * tab)53 RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
54 WebContents* web_contents = tab->GetWebContents();
55 if (web_contents) {
56 RenderWidgetHostView* render_widget_host_view =
57 web_contents->GetRenderWidgetHostView();
58 if (render_widget_host_view)
59 return render_widget_host_view->GetRenderWidgetHost();
60 }
61 return NULL;
62 }
63
GetTabUrl(RenderWidgetHost * rwh)64 const std::string GetTabUrl(RenderWidgetHost* rwh) {
65 RenderWidgetHostView* rwhv = rwh->GetView();
66 for (chrome::BrowserIterator it; !it.done(); it.Next()) {
67 Browser* browser = *it;
68 for (int i = 0, tab_count = browser->tab_strip_model()->count();
69 i < tab_count;
70 ++i) {
71 WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
72 if (tab->GetRenderWidgetHostView() == rwhv) {
73 return tab->GetLastCommittedURL().spec();
74 }
75 }
76 }
77 return std::string();
78 }
79
80 // Appends the given buffer into the file. Returns the number of bytes
81 // written, or -1 on error.
82 // TODO(satorux): Move this to file_util.
AppendFile(const base::FilePath & file_path,const char * data,int size)83 int AppendFile(const base::FilePath& file_path, const char* data, int size) {
84 FILE* file = base::OpenFile(file_path, "a");
85 if (!file)
86 return -1;
87
88 const int num_bytes_written = fwrite(data, 1, size, file);
89 base::CloseFile(file);
90 return num_bytes_written;
91 }
92
93 } // namespace
94
95 namespace chromeos {
96
97 #define FPL(value) FILE_PATH_LITERAL(value)
98
99 // Dir uptime & disk logs are located in.
100 static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
101 // Dir log{in,out} logs are located in.
102 static const base::FilePath::CharType kLoginLogPath[] =
103 FPL("/home/chronos/user");
104 // Prefix for the time measurement files.
105 static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
106 // Prefix for the disk usage files.
107 static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
108 // Name of the time that Chrome's main() is called.
109 static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
110 // Delay in milliseconds before writing the login times to disk.
111 static const int64 kLoginTimeWriteDelayMs = 3000;
112
113 // Names of login stats files.
114 static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
115 static const base::FilePath::CharType kChromeFirstRender[] =
116 FPL("chrome-first-render");
117
118 // Names of login UMA values.
119 static const char kUmaLogin[] = "BootTime.Login";
120 static const char kUmaLoginNewUser[] = "BootTime.LoginNewUser";
121 static const char kUmaLoginPrefix[] = "BootTime.";
122 static const char kUmaLogout[] = "ShutdownTime.Logout";
123 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
124 static const char kUmaRestart[] = "ShutdownTime.Restart";
125
126 // Name of file collecting login times.
127 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
128
129 // Name of file collecting logout times.
130 static const char kLogoutTimes[] = "logout-times";
131
132 static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
133 LAZY_INSTANCE_INITIALIZER;
134
135 // static
GetCurrentStats()136 BootTimesLoader::Stats BootTimesLoader::Stats::GetCurrentStats() {
137 const base::FilePath kProcUptime(FPL("/proc/uptime"));
138 const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
139 Stats stats;
140 // Callers of this method expect synchronous behavior.
141 // It's safe to allow IO here, because only virtual FS are accessed.
142 base::ThreadRestrictions::ScopedAllowIO allow_io;
143 base::ReadFileToString(kProcUptime, &stats.uptime_);
144 base::ReadFileToString(kDiskStat, &stats.disk_);
145 return stats;
146 }
147
SerializeToString() const148 std::string BootTimesLoader::Stats::SerializeToString() const {
149 if (uptime_.empty() || disk_.empty())
150 return std::string();
151 base::DictionaryValue dictionary;
152 dictionary.SetString(kUptime, uptime_);
153 dictionary.SetString(kDisk, disk_);
154
155 std::string result;
156 if (!base::JSONWriter::Write(&dictionary, &result)) {
157 LOG(WARNING) << "BootTimesLoader::Stats::SerializeToString(): failed.";
158 return std::string();
159 }
160
161 return result;
162 }
163
164 // static
DeserializeFromString(const std::string & source)165 BootTimesLoader::Stats BootTimesLoader::Stats::DeserializeFromString(
166 const std::string& source) {
167 if (source.empty())
168 return Stats();
169
170 scoped_ptr<base::Value> value(base::JSONReader::Read(source));
171 base::DictionaryValue* dictionary;
172 if (!value || !value->GetAsDictionary(&dictionary)) {
173 LOG(ERROR) << "BootTimesLoader::Stats::DeserializeFromString(): not a "
174 "dictionary: '" << source << "'";
175 return Stats();
176 }
177
178 Stats result;
179 if (!dictionary->GetString(kUptime, &result.uptime_) ||
180 !dictionary->GetString(kDisk, &result.disk_)) {
181 LOG(ERROR)
182 << "BootTimesLoader::Stats::DeserializeFromString(): format error: '"
183 << source << "'";
184 return Stats();
185 }
186
187 return result;
188 }
189
UptimeDouble(double * result) const190 bool BootTimesLoader::Stats::UptimeDouble(double* result) const {
191 std::string uptime = uptime_;
192 const size_t space_at = uptime.find_first_of(' ');
193 if (space_at == std::string::npos)
194 return false;
195
196 uptime.resize(space_at);
197
198 if (base::StringToDouble(uptime, result))
199 return true;
200
201 return false;
202 }
203
RecordStats(const std::string & name) const204 void BootTimesLoader::Stats::RecordStats(const std::string& name) const {
205 BrowserThread::PostBlockingPoolTask(
206 FROM_HERE,
207 base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
208 base::Owned(new Stats(*this)),
209 name));
210 }
211
RecordStatsWithCallback(const std::string & name,const base::Closure & callback) const212 void BootTimesLoader::Stats::RecordStatsWithCallback(
213 const std::string& name,
214 const base::Closure& callback) const {
215 BrowserThread::PostBlockingPoolTaskAndReply(
216 FROM_HERE,
217 base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
218 base::Owned(new Stats(*this)),
219 name),
220 callback);
221 }
222
RecordStatsImpl(const base::FilePath::StringType & name) const223 void BootTimesLoader::Stats::RecordStatsImpl(
224 const base::FilePath::StringType& name) const {
225 DCHECK(content::BrowserThread::GetBlockingPool()->RunsTasksOnCurrentThread());
226
227 const base::FilePath log_path(kLogPath);
228 const base::FilePath uptime_output =
229 log_path.Append(base::FilePath(kUptimePrefix + name));
230 const base::FilePath disk_output =
231 log_path.Append(base::FilePath(kDiskPrefix + name));
232
233 // Append numbers to the files.
234 AppendFile(uptime_output, uptime_.data(), uptime_.size());
235 AppendFile(disk_output, disk_.data(), disk_.size());
236 }
237
BootTimesLoader()238 BootTimesLoader::BootTimesLoader()
239 : backend_(new Backend()),
240 have_registered_(false),
241 login_done_(false),
242 restart_requested_(false) {
243 login_time_markers_.reserve(30);
244 logout_time_markers_.reserve(30);
245 }
246
~BootTimesLoader()247 BootTimesLoader::~BootTimesLoader() {
248 }
249
250 // static
Get()251 BootTimesLoader* BootTimesLoader::Get() {
252 return g_boot_times_loader.Pointer();
253 }
254
255 // static
WriteTimes(const std::string base_name,const std::string uma_name,const std::string uma_prefix,std::vector<TimeMarker> login_times)256 void BootTimesLoader::WriteTimes(
257 const std::string base_name,
258 const std::string uma_name,
259 const std::string uma_prefix,
260 std::vector<TimeMarker> login_times) {
261 const int kMinTimeMillis = 1;
262 const int kMaxTimeMillis = 30000;
263 const int kNumBuckets = 100;
264 const base::FilePath log_path(kLoginLogPath);
265
266 // Need to sort by time since the entries may have been pushed onto the
267 // vector (on the UI thread) in a different order from which they were
268 // created (potentially on other threads).
269 std::sort(login_times.begin(), login_times.end());
270
271 base::Time first = login_times.front().time();
272 base::Time last = login_times.back().time();
273 base::TimeDelta total = last - first;
274 base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
275 uma_name,
276 base::TimeDelta::FromMilliseconds(kMinTimeMillis),
277 base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
278 kNumBuckets,
279 base::HistogramBase::kUmaTargetedHistogramFlag);
280 total_hist->AddTime(total);
281 std::string output =
282 base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
283 base::Time prev = first;
284 for (unsigned int i = 0; i < login_times.size(); ++i) {
285 TimeMarker tm = login_times[i];
286 base::TimeDelta since_first = tm.time() - first;
287 base::TimeDelta since_prev = tm.time() - prev;
288 std::string name;
289
290 if (tm.send_to_uma()) {
291 name = uma_prefix + tm.name();
292 base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
293 name,
294 base::TimeDelta::FromMilliseconds(kMinTimeMillis),
295 base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
296 kNumBuckets,
297 base::HistogramBase::kUmaTargetedHistogramFlag);
298 prev_hist->AddTime(since_prev);
299 } else {
300 name = tm.name();
301 }
302 output +=
303 base::StringPrintf(
304 "\n%.2f +%.4f %s",
305 since_first.InSecondsF(),
306 since_prev.InSecondsF(),
307 name.data());
308 prev = tm.time();
309 }
310 output += '\n';
311
312 base::WriteFile(log_path.Append(base_name), output.data(), output.size());
313 }
314
LoginDone(bool is_user_new)315 void BootTimesLoader::LoginDone(bool is_user_new) {
316 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
317 if (login_done_)
318 return;
319
320 login_done_ = true;
321 AddLoginTimeMarker("LoginDone", false);
322 RecordCurrentStats(kChromeFirstRender);
323 if (have_registered_) {
324 registrar_.Remove(this,
325 content::NOTIFICATION_LOAD_START,
326 content::NotificationService::AllSources());
327 registrar_.Remove(this,
328 content::NOTIFICATION_LOAD_STOP,
329 content::NotificationService::AllSources());
330 registrar_.Remove(this,
331 content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
332 content::NotificationService::AllSources());
333 registrar_.Remove(
334 this,
335 content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
336 content::NotificationService::AllSources());
337 }
338 // Don't swamp the FILE thread right away.
339 BrowserThread::PostDelayedTask(
340 BrowserThread::FILE,
341 FROM_HERE,
342 base::Bind(&WriteTimes,
343 kLoginTimes,
344 (is_user_new ? kUmaLoginNewUser : kUmaLogin),
345 kUmaLoginPrefix,
346 login_time_markers_),
347 base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
348 }
349
WriteLogoutTimes()350 void BootTimesLoader::WriteLogoutTimes() {
351 // Either we're on the browser thread, or (more likely) Chrome is in the
352 // process of shutting down and we're on the main thread but the message loop
353 // has already been terminated.
354 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
355 !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
356
357 WriteTimes(kLogoutTimes,
358 (restart_requested_ ? kUmaRestart : kUmaLogout),
359 kUmaLogoutPrefix,
360 logout_time_markers_);
361 }
362
363 // static
ClearLogoutStartedLastPreference()364 void BootTimesLoader::ClearLogoutStartedLastPreference() {
365 PrefService* local_state = g_browser_process->local_state();
366 local_state->ClearPref(prefs::kLogoutStartedLast);
367 }
368
OnChromeProcessStart()369 void BootTimesLoader::OnChromeProcessStart() {
370 PrefService* local_state = g_browser_process->local_state();
371 const std::string logout_started_last_str =
372 local_state->GetString(prefs::kLogoutStartedLast);
373 if (logout_started_last_str.empty())
374 return;
375
376 // Note that kLogoutStartedLast is not cleared on format error to stay in
377 // logs in case of other fatal system errors.
378
379 const Stats logout_started_last_stats =
380 Stats::DeserializeFromString(logout_started_last_str);
381 if (logout_started_last_stats.uptime().empty())
382 return;
383
384 double logout_started_last;
385 double uptime;
386 if (!logout_started_last_stats.UptimeDouble(&logout_started_last) ||
387 !Stats::GetCurrentStats().UptimeDouble(&uptime)) {
388 return;
389 }
390
391 if (logout_started_last >= uptime) {
392 // Reboot happened.
393 ClearLogoutStartedLastPreference();
394 return;
395 }
396
397 // Write /tmp/uptime-logout-started as well.
398 const char kLogoutStarted[] = "logout-started";
399 logout_started_last_stats.RecordStatsWithCallback(
400 kLogoutStarted,
401 base::Bind(&BootTimesLoader::ClearLogoutStartedLastPreference));
402 }
403
OnLogoutStarted(PrefService * state)404 void BootTimesLoader::OnLogoutStarted(PrefService* state) {
405 const std::string uptime = Stats::GetCurrentStats().SerializeToString();
406 if (!uptime.empty())
407 state->SetString(prefs::kLogoutStartedLast, uptime);
408 }
409
RecordCurrentStats(const std::string & name)410 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
411 Stats::GetCurrentStats().RecordStats(name);
412 }
413
SaveChromeMainStats()414 void BootTimesLoader::SaveChromeMainStats() {
415 chrome_main_stats_ = Stats::GetCurrentStats();
416 }
417
RecordChromeMainStats()418 void BootTimesLoader::RecordChromeMainStats() {
419 chrome_main_stats_.RecordStats(kChromeMain);
420 }
421
RecordLoginAttempted()422 void BootTimesLoader::RecordLoginAttempted() {
423 DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
424 if (login_done_)
425 return;
426
427 login_time_markers_.clear();
428 AddLoginTimeMarker("LoginStarted", false);
429 if (!have_registered_) {
430 have_registered_ = true;
431 registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
432 content::NotificationService::AllSources());
433 registrar_.Add(this, content::NOTIFICATION_LOAD_START,
434 content::NotificationService::AllSources());
435 registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
436 content::NotificationService::AllSources());
437 registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
438 content::NotificationService::AllSources());
439 registrar_.Add(
440 this,
441 content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
442 content::NotificationService::AllSources());
443 }
444 }
445
AddLoginTimeMarker(const std::string & marker_name,bool send_to_uma)446 void BootTimesLoader::AddLoginTimeMarker(
447 const std::string& marker_name, bool send_to_uma) {
448 AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
449 }
450
AddLogoutTimeMarker(const std::string & marker_name,bool send_to_uma)451 void BootTimesLoader::AddLogoutTimeMarker(
452 const std::string& marker_name, bool send_to_uma) {
453 AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
454 }
455
456 // static
AddMarker(std::vector<TimeMarker> * vector,TimeMarker marker)457 void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
458 TimeMarker marker)
459 {
460 // The marker vectors can only be safely manipulated on the main thread.
461 // If we're late in the process of shutting down (eg. as can be the case at
462 // logout), then we have to assume we're on the main thread already.
463 if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
464 !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
465 vector->push_back(marker);
466 } else {
467 // Add the marker on the UI thread.
468 // Note that it's safe to use an unretained pointer to the vector because
469 // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
470 BrowserThread::PostTask(
471 BrowserThread::UI, FROM_HERE,
472 base::Bind(&BootTimesLoader::AddMarker,
473 base::Unretained(vector),
474 marker));
475 }
476 }
477
Observe(int type,const content::NotificationSource & source,const content::NotificationDetails & details)478 void BootTimesLoader::Observe(
479 int type,
480 const content::NotificationSource& source,
481 const content::NotificationDetails& details) {
482 switch (type) {
483 case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
484 content::Details<AuthenticationNotificationDetails> auth_details(details);
485 if (auth_details->success()) {
486 AddLoginTimeMarker("Authenticate", true);
487 RecordCurrentStats(kLoginSuccess);
488 registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
489 content::NotificationService::AllSources());
490 }
491 break;
492 }
493 case content::NOTIFICATION_LOAD_START: {
494 NavigationController* tab =
495 content::Source<NavigationController>(source).ptr();
496 RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
497 DCHECK(rwh);
498 AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
499 render_widget_hosts_loading_.insert(rwh);
500 break;
501 }
502 case content::NOTIFICATION_LOAD_STOP: {
503 NavigationController* tab =
504 content::Source<NavigationController>(source).ptr();
505 RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
506 if (render_widget_hosts_loading_.find(rwh) !=
507 render_widget_hosts_loading_.end()) {
508 AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
509 }
510 break;
511 }
512 case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
513 RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
514 if (render_widget_hosts_loading_.find(rwh) !=
515 render_widget_hosts_loading_.end()) {
516 AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
517 LoginDone(UserManager::Get()->IsCurrentUserNew());
518 }
519 break;
520 }
521 case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
522 WebContents* web_contents = content::Source<WebContents>(source).ptr();
523 RenderWidgetHost* render_widget_host =
524 GetRenderWidgetHost(&web_contents->GetController());
525 render_widget_hosts_loading_.erase(render_widget_host);
526 break;
527 }
528 default:
529 break;
530 }
531 }
532
533 } // namespace chromeos
534