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_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/message_loop.h"
  16 #include "base/message_loop/message_loop_proxy.h"
  17 #include "base/metrics/histogram.h"
  18 #include "base/strings/string_number_conversions.h"
  19 #include "base/strings/string_util.h"
  20 #include "base/strings/stringprintf.h"
  21 #include "base/threading/thread.h"
  22 #include "base/threading/thread_restrictions.h"
  23 #include "base/time/time.h"
  24 #include "chrome/browser/browser_process.h"
  25 #include "chrome/browser/chrome_notification_types.h"
  26 #include "chrome/browser/chromeos/login/authentication_notification_details.h"
  27 #include "chrome/browser/ui/browser.h"
  28 #include "chrome/browser/ui/browser_iterator.h"
  29 #include "chrome/browser/ui/tabs/tab_strip_model.h"
  30 #include "chrome/common/chrome_switches.h"
  31 #include "content/public/browser/browser_thread.h"
  32 #include "content/public/browser/navigation_controller.h"
  33 #include "content/public/browser/notification_service.h"
  34 #include "content/public/browser/render_widget_host_view.h"
  35 #include "content/public/browser/web_contents.h"
  36
  37 using content::BrowserThread;
  38 using content::NavigationController;
  39 using content::RenderWidgetHost;
  40 using content::RenderWidgetHostView;
  41 using content::WebContents;
  42
  43 namespace {
  44
  45 RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
  46   WebContents* web_contents = tab->GetWebContents();
  47   if (web_contents) {
  48     RenderWidgetHostView* render_widget_host_view =
  49         web_contents->GetRenderWidgetHostView();
  50     if (render_widget_host_view)
  51       return render_widget_host_view->GetRenderWidgetHost();
  52   }
  53   return NULL;
  54 }
  55
  56 const std::string GetTabUrl(RenderWidgetHost* rwh) {
  57   RenderWidgetHostView* rwhv = rwh->GetView();
  58   for (chrome::BrowserIterator it; !it.done(); it.Next()) {
  59     Browser* browser = *it;
  60     for (int i = 0, tab_count = browser->tab_strip_model()->count();
  61          i < tab_count;
  62          ++i) {
  63       WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
  64       if (tab->GetRenderWidgetHostView() == rwhv) {
  65         return tab->GetLastCommittedURL().spec();
  66       }
  67     }
  68   }
  69   return std::string();
  70 }
  71
  72 }  // namespace
  73
  74 namespace chromeos {
  75
  76 #define FPL(value) FILE_PATH_LITERAL(value)
  77
  78 // Dir uptime & disk logs are located in.
  79 static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
  80 // Dir log{in,out} logs are located in.
  81 static const base::FilePath::CharType kLoginLogPath[] =
  82     FPL("/home/chronos/user");
  83 // Prefix for the time measurement files.
  84 static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
  85 // Prefix for the disk usage files.
  86 static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
  87 // Name of the time that Chrome's main() is called.
  88 static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
  89 // Delay in milliseconds before writing the login times to disk.
  90 static const int64 kLoginTimeWriteDelayMs = 3000;
  91
  92 // Names of login stats files.
  93 static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
  94 static const base::FilePath::CharType kChromeFirstRender[] =
  95     FPL("chrome-first-render");
  96
  97 // Names of login UMA values.
  98 static const char kUmaLogin[] = "BootTime.Login";
  99 static const char kUmaLoginPrefix[] = "BootTime.";
 100 static const char kUmaLogout[] = "ShutdownTime.Logout";
 101 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
 102
 103 // Name of file collecting login times.
 104 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
 105
 106 // Name of file collecting logout times.
 107 static const char kLogoutTimes[] = "logout-times";
 108
 109 static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
 110     LAZY_INSTANCE_INITIALIZER;
 111
 112 BootTimesLoader::BootTimesLoader()
 113     : backend_(new Backend()),
 114       have_registered_(false) {
 115   login_time_markers_.reserve(30);
 116   logout_time_markers_.reserve(30);
 117 }
 118
 119 BootTimesLoader::~BootTimesLoader() {}
 120
 121 // static
 122 BootTimesLoader* BootTimesLoader::Get() {
 123   return g_boot_times_loader.Pointer();
 124 }
 125
 126 // Appends the given buffer into the file. Returns the number of bytes
 127 // written, or -1 on error.
 128 // TODO(satorux): Move this to file_util.
 129 static int AppendFile(const base::FilePath& file_path,
 130                       const char* data,
 131                       int size) {
 132   FILE* file = base::OpenFile(file_path, "a");
 133   if (!file) {
 134     return -1;
 135   }
 136   const int num_bytes_written = fwrite(data, 1, size, file);
 137   base::CloseFile(file);
 138   return num_bytes_written;
 139 }
 140
 141 static void RecordStatsDelayed(const base::FilePath::StringType& name,
 142                                const std::string& uptime,
 143                                const std::string& disk) {
 144   const base::FilePath log_path(kLogPath);
 145   const base::FilePath uptime_output =
 146       log_path.Append(base::FilePath(kUptimePrefix + name));
 147   const base::FilePath disk_output =
 148       log_path.Append(base::FilePath(kDiskPrefix + name));
 149
 150   // Append numbers to the files.
 151   AppendFile(uptime_output, uptime.data(), uptime.size());
 152   AppendFile(disk_output, disk.data(), disk.size());
 153 }
 154
 155 // static
 156 void BootTimesLoader::WriteTimes(
 157     const std::string base_name,
 158     const std::string uma_name,
 159     const std::string uma_prefix,
 160     std::vector<TimeMarker> login_times) {
 161   const int kMinTimeMillis = 1;
 162   const int kMaxTimeMillis = 30000;
 163   const int kNumBuckets = 100;
 164   const base::FilePath log_path(kLoginLogPath);
 165
 166   // Need to sort by time since the entries may have been pushed onto the
 167   // vector (on the UI thread) in a different order from which they were
 168   // created (potentially on other threads).
 169   std::sort(login_times.begin(), login_times.end());
 170
 171   base::Time first = login_times.front().time();
 172   base::Time last = login_times.back().time();
 173   base::TimeDelta total = last - first;
 174   base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
 175       uma_name,
 176       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 177       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 178       kNumBuckets,
 179       base::HistogramBase::kUmaTargetedHistogramFlag);
 180   total_hist->AddTime(total);
 181   std::string output =
 182       base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
 183   base::Time prev = first;
 184   for (unsigned int i = 0; i < login_times.size(); ++i) {
 185     TimeMarker tm = login_times[i];
 186     base::TimeDelta since_first = tm.time() - first;
 187     base::TimeDelta since_prev = tm.time() - prev;
 188     std::string name;
 189
 190     if (tm.send_to_uma()) {
 191       name = uma_prefix + tm.name();
 192       base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
 193           name,
 194           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 195           base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 196           kNumBuckets,
 197           base::HistogramBase::kUmaTargetedHistogramFlag);
 198       prev_hist->AddTime(since_prev);
 199     } else {
 200       name = tm.name();
 201     }
 202     output +=
 203         base::StringPrintf(
 204             "\n%.2f +%.4f %s",
 205             since_first.InSecondsF(),
 206             since_prev.InSecondsF(),
 207             name.data());
 208     prev = tm.time();
 209   }
 210   output += '\n';
 211
 212   file_util::WriteFile(
 213       log_path.Append(base_name), output.data(), output.size());
 214 }
 215
 216 void BootTimesLoader::LoginDone() {
 217   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 218   AddLoginTimeMarker("LoginDone", false);
 219   RecordCurrentStats(kChromeFirstRender);
 220   registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
 221                     content::NotificationService::AllSources());
 222   registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
 223                     content::NotificationService::AllSources());
 224   registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 225                     content::NotificationService::AllSources());
 226   registrar_.Remove(
 227       this,
 228       content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 229       content::NotificationService::AllSources());
 230   // Don't swamp the FILE thread right away.
 231   BrowserThread::PostDelayedTask(
 232       BrowserThread::FILE, FROM_HERE,
 233       base::Bind(&WriteTimes, kLoginTimes, kUmaLogin, kUmaLoginPrefix,
 234                  login_time_markers_),
 235       base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
 236 }
 237
 238 void BootTimesLoader::WriteLogoutTimes() {
 239   // Either we're on the browser thread, or (more likely) Chrome is in the
 240   // process of shutting down and we're on the main thread but the message loop
 241   // has already been terminated.
 242   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 243          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
 244
 245   WriteTimes(kLogoutTimes,
 246              kUmaLogout,
 247              kUmaLogoutPrefix,
 248              logout_time_markers_);
 249 }
 250
 251 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
 252   BrowserThread::PostTask(
 253       BrowserThread::FILE, FROM_HERE,
 254       base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
 255 }
 256
 257 BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
 258   const base::FilePath kProcUptime(FPL("/proc/uptime"));
 259   const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
 260   Stats stats;
 261   base::ThreadRestrictions::ScopedAllowIO allow_io;
 262   base::ReadFileToString(kProcUptime, &stats.uptime);
 263   base::ReadFileToString(kDiskStat, &stats.disk);
 264   return stats;
 265 }
 266
 267 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
 268   RecordStats(name, GetCurrentStats());
 269 }
 270
 271 void BootTimesLoader::SaveChromeMainStats() {
 272   chrome_main_stats_ = GetCurrentStats();
 273 }
 274
 275 void BootTimesLoader::RecordChromeMainStats() {
 276   RecordStats(kChromeMain, chrome_main_stats_);
 277 }
 278
 279 void BootTimesLoader::RecordLoginAttempted() {
 280   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 281   login_time_markers_.clear();
 282   AddLoginTimeMarker("LoginStarted", false);
 283   if (!have_registered_) {
 284     have_registered_ = true;
 285     registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
 286                    content::NotificationService::AllSources());
 287     registrar_.Add(this, content::NOTIFICATION_LOAD_START,
 288                    content::NotificationService::AllSources());
 289     registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
 290                    content::NotificationService::AllSources());
 291     registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 292                    content::NotificationService::AllSources());
 293     registrar_.Add(
 294         this,
 295         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 296         content::NotificationService::AllSources());
 297   }
 298 }
 299
 300 void BootTimesLoader::AddLoginTimeMarker(
 301     const std::string& marker_name, bool send_to_uma) {
 302   AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
 303 }
 304
 305 void BootTimesLoader::AddLogoutTimeMarker(
 306     const std::string& marker_name, bool send_to_uma) {
 307   AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
 308 }
 309
 310 // static
 311 void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
 312                                 TimeMarker marker)
 313 {
 314   // The marker vectors can only be safely manipulated on the main thread.
 315   // If we're late in the process of shutting down (eg. as can be the case at
 316   // logout), then we have to assume we're on the main thread already.
 317   if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 318       !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
 319     vector->push_back(marker);
 320   } else {
 321     // Add the marker on the UI thread.
 322     // Note that it's safe to use an unretained pointer to the vector because
 323     // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
 324     BrowserThread::PostTask(
 325         BrowserThread::UI, FROM_HERE,
 326         base::Bind(&BootTimesLoader::AddMarker,
 327                    base::Unretained(vector),
 328                    marker));
 329   }
 330 }
 331
 332 void BootTimesLoader::Observe(
 333     int type,
 334     const content::NotificationSource& source,
 335     const content::NotificationDetails& details) {
 336   switch (type) {
 337     case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
 338       content::Details<AuthenticationNotificationDetails> auth_details(details);
 339       if (auth_details->success()) {
 340         AddLoginTimeMarker("Authenticate", true);
 341         RecordCurrentStats(kLoginSuccess);
 342         registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
 343                           content::NotificationService::AllSources());
 344       }
 345       break;
 346     }
 347     case content::NOTIFICATION_LOAD_START: {
 348       NavigationController* tab =
 349           content::Source<NavigationController>(source).ptr();
 350       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 351       DCHECK(rwh);
 352       AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
 353       render_widget_hosts_loading_.insert(rwh);
 354       break;
 355     }
 356     case content::NOTIFICATION_LOAD_STOP: {
 357       NavigationController* tab =
 358           content::Source<NavigationController>(source).ptr();
 359       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 360       if (render_widget_hosts_loading_.find(rwh) !=
 361           render_widget_hosts_loading_.end()) {
 362         AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
 363       }
 364       break;
 365     }
 366     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
 367       RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
 368       if (render_widget_hosts_loading_.find(rwh) !=
 369           render_widget_hosts_loading_.end()) {
 370         AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
 371         LoginDone();
 372       }
 373       break;
 374     }
 375     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
 376       WebContents* web_contents = content::Source<WebContents>(source).ptr();
 377       RenderWidgetHost* render_widget_host =
 378           GetRenderWidgetHost(&web_contents->GetController());
 379       render_widget_hosts_loading_.erase(render_widget_host);
 380       break;
 381     }
 382     default:
 383       break;
 384   }
 385 }
 386
 387 }  // namespace chromeos