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