boot_times_loader.cc revision 7dbb3d5cf0c15f500944d211057644d6a2f37371 
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/lazy_instance.h"
14#include "base/location.h"
15#include "base/message_loop.h"
16#include "base/message_loop/message_loop_proxy.h"
17#include "base/metrics/histogram.h"
18#include "base/process_util.h"
19#include "base/strings/string_number_conversions.h"
20#include "base/strings/string_util.h"
21#include "base/strings/stringprintf.h"
22#include "base/threading/thread.h"
23#include "base/threading/thread_restrictions.h"
24#include "base/time/time.h"
25#include "chrome/browser/browser_process.h"
26#include "chrome/browser/chrome_notification_types.h"
27#include "chrome/browser/chromeos/login/authentication_notification_details.h"
28#include "chrome/browser/ui/browser.h"
29#include "chrome/browser/ui/browser_iterator.h"
30#include "chrome/browser/ui/tabs/tab_strip_model.h"
31#include "chrome/common/chrome_switches.h"
32#include "content/public/browser/browser_thread.h"
33#include "content/public/browser/navigation_controller.h"
34#include "content/public/browser/notification_service.h"
35#include "content/public/browser/render_widget_host_view.h"
36#include "content/public/browser/web_contents.h"
37
38using content::BrowserThread;
39using content::NavigationController;
40using content::RenderWidgetHost;
41using content::RenderWidgetHostView;
42using content::WebContents;
43
44namespace {
45
46RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
47  WebContents* web_contents = tab->GetWebContents();
48  if (web_contents) {
49    RenderWidgetHostView* render_widget_host_view =
50        web_contents->GetRenderWidgetHostView();
51    if (render_widget_host_view)
52      return render_widget_host_view->GetRenderWidgetHost();
53  }
54  return NULL;
55}
56
57const std::string GetTabUrl(RenderWidgetHost* rwh) {
58  RenderWidgetHostView* rwhv = rwh->GetView();
59  for (chrome::BrowserIterator it; !it.done(); it.Next()) {
60    Browser* browser = *it;
61    for (int i = 0, tab_count = browser->tab_strip_model()->count();
62         i < tab_count;
63         ++i) {
64      WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
65      if (tab->GetRenderWidgetHostView() == rwhv) {
66        return tab->GetURL().spec();
67      }
68    }
69  }
70  return std::string();
71}
72
73void PostCallbackIfNotCanceled(
74    const CancelableTaskTracker::IsCanceledCallback& is_canceled_cb,
75    base::TaskRunner* task_runner,
76    const chromeos::BootTimesLoader::GetBootTimesCallback& callback,
77    const chromeos::BootTimesLoader::BootTimes& boot_times) {
78  if (is_canceled_cb.Run())
79    return;
80  task_runner->PostTask(FROM_HERE, base::Bind(callback, boot_times));
81}
82
83}  // namespace
84
85namespace chromeos {
86
87#define FPL(value) FILE_PATH_LITERAL(value)
88
89// Dir uptime & disk logs are located in.
90static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
91// Dir log{in,out} logs are located in.
92static const base::FilePath::CharType kLoginLogPath[] =
93    FPL("/home/chronos/user");
94// Prefix for the time measurement files.
95static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
96// Prefix for the disk usage files.
97static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
98// Name of the time that Chrome's main() is called.
99static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
100// Delay in milliseconds between file read attempts.
101static const int64 kReadAttemptDelayMs = 250;
102// Delay in milliseconds before writing the login times to disk.
103static const int64 kLoginTimeWriteDelayMs = 3000;
104
105// Names of login stats files.
106static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
107static const base::FilePath::CharType kChromeFirstRender[] =
108    FPL("chrome-first-render");
109
110// Names of login UMA values.
111static const char kUmaLogin[] = "BootTime.Login";
112static const char kUmaLoginPrefix[] = "BootTime.";
113static const char kUmaLogout[] = "ShutdownTime.Logout";
114static const char kUmaLogoutPrefix[] = "ShutdownTime.";
115
116// Name of file collecting login times.
117static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
118
119// Name of file collecting logout times.
120static const char kLogoutTimes[] = "logout-times";
121
122static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
123    LAZY_INSTANCE_INITIALIZER;
124
125BootTimesLoader::BootTimesLoader()
126    : backend_(new Backend()),
127      have_registered_(false) {
128  login_time_markers_.reserve(30);
129  logout_time_markers_.reserve(30);
130}
131
132BootTimesLoader::~BootTimesLoader() {}
133
134// static
135BootTimesLoader* BootTimesLoader::Get() {
136  return g_boot_times_loader.Pointer();
137}
138
139CancelableTaskTracker::TaskId BootTimesLoader::GetBootTimes(
140      const GetBootTimesCallback& callback,
141      CancelableTaskTracker* tracker) {
142  if (!BrowserThread::IsMessageLoopValid(BrowserThread::FILE)) {
143    // This should only happen if Chrome is shutting down, so we don't do
144    // anything.
145    return CancelableTaskTracker::kBadTaskId;
146  }
147
148  const CommandLine& command_line = *CommandLine::ForCurrentProcess();
149  if (command_line.HasSwitch(switches::kTestType)) {
150    // TODO(davemoore) This avoids boottimes for tests. This needs to be
151    // replaced with a mock of BootTimesLoader.
152    return CancelableTaskTracker::kBadTaskId;
153  }
154
155  CancelableTaskTracker::IsCanceledCallback is_canceled;
156  CancelableTaskTracker::TaskId id = tracker->NewTrackedTaskId(&is_canceled);
157
158  GetBootTimesCallback callback_runner =
159      base::Bind(&PostCallbackIfNotCanceled,
160                 is_canceled, base::MessageLoopProxy::current(), callback);
161  BrowserThread::PostTask(
162      BrowserThread::FILE,
163      FROM_HERE,
164      base::Bind(&Backend::GetBootTimesAndRunCallback,
165                 backend_, is_canceled, callback_runner));
166  return id;
167}
168
169// Extracts the uptime value from files located in /tmp, returning the
170// value as a double in value.
171static bool GetTime(const base::FilePath::StringType& log, double* value) {
172  base::FilePath log_dir(kLogPath);
173  base::FilePath log_file = log_dir.Append(log);
174  std::string contents;
175  *value = 0.0;
176  if (file_util::ReadFileToString(log_file, &contents)) {
177    size_t space_index = contents.find(' ');
178    size_t chars_left =
179        space_index != std::string::npos ? space_index : std::string::npos;
180    std::string value_string = contents.substr(0, chars_left);
181    return base::StringToDouble(value_string, value);
182  }
183  return false;
184}
185
186// Converts double seconds to a TimeDelta object.
187static base::TimeDelta SecondsToTimeDelta(double seconds) {
188  double ms = seconds * base::Time::kMillisecondsPerSecond;
189  return base::TimeDelta::FromMilliseconds(static_cast<int64>(ms));
190}
191
192// Reports the collected boot times to UMA if they haven't been
193// reported yet and if metrics collection is enabled.
194static void SendBootTimesToUMA(const BootTimesLoader::BootTimes& boot_times) {
195  // Checks if the times for the most recent boot event have been
196  // reported already to avoid sending boot time histogram samples
197  // every time the user logs out.
198  static const base::FilePath::CharType kBootTimesSent[] =
199      FPL("/tmp/boot-times-sent");
200  base::FilePath sent(kBootTimesSent);
201  if (base::PathExists(sent))
202    return;
203
204  UMA_HISTOGRAM_TIMES("BootTime.Total",
205                      SecondsToTimeDelta(boot_times.total));
206  UMA_HISTOGRAM_TIMES("BootTime.Firmware",
207                      SecondsToTimeDelta(boot_times.firmware));
208  UMA_HISTOGRAM_TIMES("BootTime.Kernel",
209                      SecondsToTimeDelta(boot_times.pre_startup));
210  UMA_HISTOGRAM_TIMES("BootTime.System",
211                      SecondsToTimeDelta(boot_times.system));
212  if (boot_times.chrome > 0) {
213    UMA_HISTOGRAM_TIMES("BootTime.Chrome",
214                        SecondsToTimeDelta(boot_times.chrome));
215  }
216
217  // Stores the boot times to a file in /tmp to indicate that the
218  // times for the most recent boot event have been reported
219  // already. The file will be deleted at system shutdown/reboot.
220  std::string boot_times_text = base::StringPrintf("total: %.2f\n"
221                                                   "firmware: %.2f\n"
222                                                   "kernel: %.2f\n"
223                                                   "system: %.2f\n"
224                                                   "chrome: %.2f\n",
225                                                   boot_times.total,
226                                                   boot_times.firmware,
227                                                   boot_times.pre_startup,
228                                                   boot_times.system,
229                                                   boot_times.chrome);
230  file_util::WriteFile(sent, boot_times_text.data(), boot_times_text.size());
231  DCHECK(base::PathExists(sent));
232}
233
234void BootTimesLoader::Backend::GetBootTimesAndRunCallback(
235    const CancelableTaskTracker::IsCanceledCallback& is_canceled_cb,
236    const GetBootTimesCallback& callback) {
237  if (is_canceled_cb.Run())
238    return;
239
240  const base::FilePath::CharType kFirmwareBootTime[] =
241      FPL("firmware-boot-time");
242  const base::FilePath::CharType kPreStartup[] = FPL("pre-startup");
243  const base::FilePath::CharType kChromeExec[] = FPL("chrome-exec");
244  const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
245  const base::FilePath::CharType kXStarted[] = FPL("x-started");
246  const base::FilePath::CharType kLoginPromptReady[] =
247      FPL("login-prompt-ready");
248  const base::FilePath::StringType uptime_prefix = kUptimePrefix;
249
250  // Wait until firmware-boot-time file exists by reposting.
251  base::FilePath log_dir(kLogPath);
252  base::FilePath log_file = log_dir.Append(kFirmwareBootTime);
253  if (!base::PathExists(log_file)) {
254    BrowserThread::PostDelayedTask(
255        BrowserThread::FILE,
256        FROM_HERE,
257        base::Bind(&Backend::GetBootTimesAndRunCallback,
258                   this, is_canceled_cb, callback),
259        base::TimeDelta::FromMilliseconds(kReadAttemptDelayMs));
260    return;
261  }
262
263  BootTimes boot_times;
264
265  GetTime(kFirmwareBootTime, &boot_times.firmware);
266  GetTime(uptime_prefix + kPreStartup, &boot_times.pre_startup);
267  GetTime(uptime_prefix + kXStarted, &boot_times.x_started);
268  GetTime(uptime_prefix + kChromeExec, &boot_times.chrome_exec);
269  GetTime(uptime_prefix + kChromeMain, &boot_times.chrome_main);
270  GetTime(uptime_prefix + kLoginPromptReady, &boot_times.login_prompt_ready);
271
272  boot_times.total = boot_times.firmware + boot_times.login_prompt_ready;
273  if (boot_times.chrome_exec > 0) {
274    boot_times.system = boot_times.chrome_exec - boot_times.pre_startup;
275    boot_times.chrome = boot_times.login_prompt_ready - boot_times.chrome_exec;
276  } else {
277    boot_times.system = boot_times.login_prompt_ready - boot_times.pre_startup;
278  }
279
280  SendBootTimesToUMA(boot_times);
281
282  callback.Run(boot_times);
283}
284
285// Appends the given buffer into the file. Returns the number of bytes
286// written, or -1 on error.
287// TODO(satorux): Move this to file_util.
288static int AppendFile(const base::FilePath& file_path,
289                      const char* data,
290                      int size) {
291  FILE* file = file_util::OpenFile(file_path, "a");
292  if (!file) {
293    return -1;
294  }
295  const int num_bytes_written = fwrite(data, 1, size, file);
296  file_util::CloseFile(file);
297  return num_bytes_written;
298}
299
300static void RecordStatsDelayed(const base::FilePath::StringType& name,
301                               const std::string& uptime,
302                               const std::string& disk) {
303  const base::FilePath log_path(kLogPath);
304  const base::FilePath uptime_output =
305      log_path.Append(base::FilePath(kUptimePrefix + name));
306  const base::FilePath disk_output =
307      log_path.Append(base::FilePath(kDiskPrefix + name));
308
309  // Append numbers to the files.
310  AppendFile(uptime_output, uptime.data(), uptime.size());
311  AppendFile(disk_output, disk.data(), disk.size());
312}
313
314// static
315void BootTimesLoader::WriteTimes(
316    const std::string base_name,
317    const std::string uma_name,
318    const std::string uma_prefix,
319    std::vector<TimeMarker> login_times) {
320  const int kMinTimeMillis = 1;
321  const int kMaxTimeMillis = 30000;
322  const int kNumBuckets = 100;
323  const base::FilePath log_path(kLoginLogPath);
324
325  // Need to sort by time since the entries may have been pushed onto the
326  // vector (on the UI thread) in a different order from which they were
327  // created (potentially on other threads).
328  std::sort(login_times.begin(), login_times.end());
329
330  base::Time first = login_times.front().time();
331  base::Time last = login_times.back().time();
332  base::TimeDelta total = last - first;
333  base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
334      uma_name,
335      base::TimeDelta::FromMilliseconds(kMinTimeMillis),
336      base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
337      kNumBuckets,
338      base::HistogramBase::kUmaTargetedHistogramFlag);
339  total_hist->AddTime(total);
340  std::string output =
341      base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
342  base::Time prev = first;
343  for (unsigned int i = 0; i < login_times.size(); ++i) {
344    TimeMarker tm = login_times[i];
345    base::TimeDelta since_first = tm.time() - first;
346    base::TimeDelta since_prev = tm.time() - prev;
347    std::string name;
348
349    if (tm.send_to_uma()) {
350      name = uma_prefix + tm.name();
351      base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
352          name,
353          base::TimeDelta::FromMilliseconds(kMinTimeMillis),
354          base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
355          kNumBuckets,
356          base::HistogramBase::kUmaTargetedHistogramFlag);
357      prev_hist->AddTime(since_prev);
358    } else {
359      name = tm.name();
360    }
361    output +=
362        base::StringPrintf(
363            "\n%.2f +%.4f %s",
364            since_first.InSecondsF(),
365            since_prev.InSecondsF(),
366            name.data());
367    prev = tm.time();
368  }
369  output += '\n';
370
371  file_util::WriteFile(
372      log_path.Append(base_name), output.data(), output.size());
373}
374
375void BootTimesLoader::LoginDone() {
376  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
377  AddLoginTimeMarker("LoginDone", false);
378  RecordCurrentStats(kChromeFirstRender);
379  registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
380                    content::NotificationService::AllSources());
381  registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
382                    content::NotificationService::AllSources());
383  registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
384                    content::NotificationService::AllSources());
385  registrar_.Remove(
386      this,
387      content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
388      content::NotificationService::AllSources());
389  // Don't swamp the FILE thread right away.
390  BrowserThread::PostDelayedTask(
391      BrowserThread::FILE, FROM_HERE,
392      base::Bind(&WriteTimes, kLoginTimes, kUmaLogin, kUmaLoginPrefix,
393                 login_time_markers_),
394      base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
395}
396
397void BootTimesLoader::WriteLogoutTimes() {
398  // Either we're on the browser thread, or (more likely) Chrome is in the
399  // process of shutting down and we're on the main thread but the message loop
400  // has already been terminated.
401  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
402         !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
403
404  WriteTimes(kLogoutTimes,
405             kUmaLogout,
406             kUmaLogoutPrefix,
407             logout_time_markers_);
408}
409
410void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
411  BrowserThread::PostTask(
412      BrowserThread::FILE, FROM_HERE,
413      base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
414}
415
416BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
417  const base::FilePath kProcUptime(FPL("/proc/uptime"));
418  const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
419  Stats stats;
420  base::ThreadRestrictions::ScopedAllowIO allow_io;
421  file_util::ReadFileToString(kProcUptime, &stats.uptime);
422  file_util::ReadFileToString(kDiskStat, &stats.disk);
423  return stats;
424}
425
426void BootTimesLoader::RecordCurrentStats(const std::string& name) {
427  RecordStats(name, GetCurrentStats());
428}
429
430void BootTimesLoader::SaveChromeMainStats() {
431  chrome_main_stats_ = GetCurrentStats();
432}
433
434void BootTimesLoader::RecordChromeMainStats() {
435  RecordStats(kChromeMain, chrome_main_stats_);
436}
437
438void BootTimesLoader::RecordLoginAttempted() {
439  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
440  login_time_markers_.clear();
441  AddLoginTimeMarker("LoginStarted", false);
442  if (!have_registered_) {
443    have_registered_ = true;
444    registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
445                   content::NotificationService::AllSources());
446    registrar_.Add(this, content::NOTIFICATION_LOAD_START,
447                   content::NotificationService::AllSources());
448    registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
449                   content::NotificationService::AllSources());
450    registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
451                   content::NotificationService::AllSources());
452    registrar_.Add(
453        this,
454        content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
455        content::NotificationService::AllSources());
456  }
457}
458
459void BootTimesLoader::AddLoginTimeMarker(
460    const std::string& marker_name, bool send_to_uma) {
461  AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
462}
463
464void BootTimesLoader::AddLogoutTimeMarker(
465    const std::string& marker_name, bool send_to_uma) {
466  AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
467}
468
469// static
470void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
471                                TimeMarker marker)
472{
473  // The marker vectors can only be safely manipulated on the main thread.
474  // If we're late in the process of shutting down (eg. as can be the case at
475  // logout), then we have to assume we're on the main thread already.
476  if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
477      !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
478    vector->push_back(marker);
479  } else {
480    // Add the marker on the UI thread.
481    // Note that it's safe to use an unretained pointer to the vector because
482    // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
483    BrowserThread::PostTask(
484        BrowserThread::UI, FROM_HERE,
485        base::Bind(&BootTimesLoader::AddMarker,
486                   base::Unretained(vector),
487                   marker));
488  }
489}
490
491void BootTimesLoader::Observe(
492    int type,
493    const content::NotificationSource& source,
494    const content::NotificationDetails& details) {
495  switch (type) {
496    case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
497      content::Details<AuthenticationNotificationDetails> auth_details(details);
498      if (auth_details->success()) {
499        AddLoginTimeMarker("Authenticate", true);
500        RecordCurrentStats(kLoginSuccess);
501        registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
502                          content::NotificationService::AllSources());
503      }
504      break;
505    }
506    case content::NOTIFICATION_LOAD_START: {
507      NavigationController* tab =
508          content::Source<NavigationController>(source).ptr();
509      RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
510      DCHECK(rwh);
511      AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
512      render_widget_hosts_loading_.insert(rwh);
513      break;
514    }
515    case content::NOTIFICATION_LOAD_STOP: {
516      NavigationController* tab =
517          content::Source<NavigationController>(source).ptr();
518      RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
519      if (render_widget_hosts_loading_.find(rwh) !=
520          render_widget_hosts_loading_.end()) {
521        AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
522      }
523      break;
524    }
525    case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
526      RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
527      if (render_widget_hosts_loading_.find(rwh) !=
528          render_widget_hosts_loading_.end()) {
529        AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
530        LoginDone();
531      }
532      break;
533    }
534    case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
535      WebContents* web_contents = content::Source<WebContents>(source).ptr();
536      RenderWidgetHost* render_widget_host =
537          GetRenderWidgetHost(&web_contents->GetController());
538      render_widget_hosts_loading_.erase(render_widget_host);
539      break;
540    }
541    default:
542      break;
543  }
544}
545
546}  // namespace chromeos
547