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