chrome/browser/chromeos/boot_times_loader.cc

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