chrome/browser/chromeos/boot_times_loader.cc

   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
  36 using content::BrowserThread;
  37 using content::NavigationController;
  38 using content::RenderWidgetHost;
  39 using content::RenderWidgetHostView;
  40 using content::WebContents;
  41
  42 namespace {
  43
  44 RenderWidgetHost* 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
  55 const 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
  72 namespace chromeos {
  73
  74 #define FPL(value) FILE_PATH_LITERAL(value)
  75
  76 // Dir uptime & disk logs are located in.
  77 static const FilePath::CharType kLogPath[] = FPL("/tmp");
  78 // Dir log{in,out} logs are located in.
  79 static const FilePath::CharType kLoginLogPath[] = FPL("/home/chronos/user");
  80 // Prefix for the time measurement files.
  81 static const FilePath::CharType kUptimePrefix[] = FPL("uptime-");
  82 // Prefix for the disk usage files.
  83 static const FilePath::CharType kDiskPrefix[] = FPL("disk-");
  84 // Name of the time that Chrome's main() is called.
  85 static const FilePath::CharType kChromeMain[] = FPL("chrome-main");
  86 // Delay in milliseconds between file read attempts.
  87 static const int64 kReadAttemptDelayMs = 250;
  88 // Delay in milliseconds before writing the login times to disk.
  89 static const int64 kLoginTimeWriteDelayMs = 3000;
  90
  91 // Names of login stats files.
  92 static const FilePath::CharType kLoginSuccess[] = FPL("login-success");
  93 static const FilePath::CharType kChromeFirstRender[] =
  94     FPL("chrome-first-render");
  95
  96 // Names of login UMA values.
  97 static const char kUmaLogin[] = "BootTime.Login";
  98 static const char kUmaLoginPrefix[] = "BootTime.";
  99 static const char kUmaLogout[] = "ShutdownTime.Logout";
 100 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
 101
 102 // Name of file collecting login times.
 103 static const FilePath::CharType kLoginTimes[] = FPL("login-times");
 104
 105 // Name of file collecting logout times.
 106 static const char kLogoutTimes[] = "logout-times";
 107
 108 static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
 109     LAZY_INSTANCE_INITIALIZER;
 110
 111 BootTimesLoader::BootTimesLoader()
 112     : backend_(new Backend()),
 113       have_registered_(false) {
 114   login_time_markers_.reserve(30);
 115   logout_time_markers_.reserve(30);
 116 }
 117
 118 BootTimesLoader::~BootTimesLoader() {}
 119
 120 // static
 121 BootTimesLoader* BootTimesLoader::Get() {
 122   return g_boot_times_loader.Pointer();
 123 }
 124
 125 BootTimesLoader::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.
 154 static 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.
 170 static 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.
 177 static 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
 217 void 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.
 267 static 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
 279 static 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
 293 void 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
 353 void 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
 375 void 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
 388 void 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
 394 BootTimesLoader::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
 404 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
 405   RecordStats(name, GetCurrentStats());
 406 }
 407
 408 void BootTimesLoader::SaveChromeMainStats() {
 409   chrome_main_stats_ = GetCurrentStats();
 410 }
 411
 412 void BootTimesLoader::RecordChromeMainStats() {
 413   RecordStats(kChromeMain, chrome_main_stats_);
 414 }
 415
 416 void 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
 437 void 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
 442 void 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
 448 void 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
 469 void 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