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   base::WriteFile(log_path.Append(base_name), output.data(), output.size());
 213 }
 214
 215 void BootTimesLoader::LoginDone() {
 216   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 217   AddLoginTimeMarker("LoginDone", false);
 218   RecordCurrentStats(kChromeFirstRender);
 219   registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
 220                     content::NotificationService::AllSources());
 221   registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
 222                     content::NotificationService::AllSources());
 223   registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 224                     content::NotificationService::AllSources());
 225   registrar_.Remove(
 226       this,
 227       content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 228       content::NotificationService::AllSources());
 229   // Don't swamp the FILE thread right away.
 230   BrowserThread::PostDelayedTask(
 231       BrowserThread::FILE, FROM_HERE,
 232       base::Bind(&WriteTimes, kLoginTimes, kUmaLogin, kUmaLoginPrefix,
 233                  login_time_markers_),
 234       base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
 235 }
 236
 237 void BootTimesLoader::WriteLogoutTimes() {
 238   // Either we're on the browser thread, or (more likely) Chrome is in the
 239   // process of shutting down and we're on the main thread but the message loop
 240   // has already been terminated.
 241   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 242          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
 243
 244   WriteTimes(kLogoutTimes,
 245              kUmaLogout,
 246              kUmaLogoutPrefix,
 247              logout_time_markers_);
 248 }
 249
 250 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
 251   BrowserThread::PostTask(
 252       BrowserThread::FILE, FROM_HERE,
 253       base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
 254 }
 255
 256 BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
 257   const base::FilePath kProcUptime(FPL("/proc/uptime"));
 258   const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
 259   Stats stats;
 260   base::ThreadRestrictions::ScopedAllowIO allow_io;
 261   base::ReadFileToString(kProcUptime, &stats.uptime);
 262   base::ReadFileToString(kDiskStat, &stats.disk);
 263   return stats;
 264 }
 265
 266 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
 267   RecordStats(name, GetCurrentStats());
 268 }
 269
 270 void BootTimesLoader::SaveChromeMainStats() {
 271   chrome_main_stats_ = GetCurrentStats();
 272 }
 273
 274 void BootTimesLoader::RecordChromeMainStats() {
 275   RecordStats(kChromeMain, chrome_main_stats_);
 276 }
 277
 278 void BootTimesLoader::RecordLoginAttempted() {
 279   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 280   login_time_markers_.clear();
 281   AddLoginTimeMarker("LoginStarted", false);
 282   if (!have_registered_) {
 283     have_registered_ = true;
 284     registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
 285                    content::NotificationService::AllSources());
 286     registrar_.Add(this, content::NOTIFICATION_LOAD_START,
 287                    content::NotificationService::AllSources());
 288     registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
 289                    content::NotificationService::AllSources());
 290     registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 291                    content::NotificationService::AllSources());
 292     registrar_.Add(
 293         this,
 294         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 295         content::NotificationService::AllSources());
 296   }
 297 }
 298
 299 void BootTimesLoader::AddLoginTimeMarker(
 300     const std::string& marker_name, bool send_to_uma) {
 301   AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
 302 }
 303
 304 void BootTimesLoader::AddLogoutTimeMarker(
 305     const std::string& marker_name, bool send_to_uma) {
 306   AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
 307 }
 308
 309 // static
 310 void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
 311                                 TimeMarker marker)
 312 {
 313   // The marker vectors can only be safely manipulated on the main thread.
 314   // If we're late in the process of shutting down (eg. as can be the case at
 315   // logout), then we have to assume we're on the main thread already.
 316   if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 317       !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
 318     vector->push_back(marker);
 319   } else {
 320     // Add the marker on the UI thread.
 321     // Note that it's safe to use an unretained pointer to the vector because
 322     // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
 323     BrowserThread::PostTask(
 324         BrowserThread::UI, FROM_HERE,
 325         base::Bind(&BootTimesLoader::AddMarker,
 326                    base::Unretained(vector),
 327                    marker));
 328   }
 329 }
 330
 331 void BootTimesLoader::Observe(
 332     int type,
 333     const content::NotificationSource& source,
 334     const content::NotificationDetails& details) {
 335   switch (type) {
 336     case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
 337       content::Details<AuthenticationNotificationDetails> auth_details(details);
 338       if (auth_details->success()) {
 339         AddLoginTimeMarker("Authenticate", true);
 340         RecordCurrentStats(kLoginSuccess);
 341         registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
 342                           content::NotificationService::AllSources());
 343       }
 344       break;
 345     }
 346     case content::NOTIFICATION_LOAD_START: {
 347       NavigationController* tab =
 348           content::Source<NavigationController>(source).ptr();
 349       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 350       DCHECK(rwh);
 351       AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
 352       render_widget_hosts_loading_.insert(rwh);
 353       break;
 354     }
 355     case content::NOTIFICATION_LOAD_STOP: {
 356       NavigationController* tab =
 357           content::Source<NavigationController>(source).ptr();
 358       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 359       if (render_widget_hosts_loading_.find(rwh) !=
 360           render_widget_hosts_loading_.end()) {
 361         AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
 362       }
 363       break;
 364     }
 365     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
 366       RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
 367       if (render_widget_hosts_loading_.find(rwh) !=
 368           render_widget_hosts_loading_.end()) {
 369         AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
 370         LoginDone();
 371       }
 372       break;
 373     }
 374     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
 375       WebContents* web_contents = content::Source<WebContents>(source).ptr();
 376       RenderWidgetHost* render_widget_host =
 377           GetRenderWidgetHost(&web_contents->GetController());
 378       render_widget_hosts_loading_.erase(render_widget_host);
 379       break;
 380     }
 381     default:
 382       break;
 383   }
 384 }
 385
 386 }  // namespace chromeos