chrome/browser/chromeos/boot_times_recorder.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_recorder.h"
   6
   7 #include <vector>
   8
   9 #include "base/bind.h"
  10 #include "base/command_line.h"
  11 #include "base/files/file_path.h"
  12 #include "base/files/file_util.h"
  13 #include "base/json/json_reader.h"
  14 #include "base/json/json_writer.h"
  15 #include "base/lazy_instance.h"
  16 #include "base/location.h"
  17 #include "base/message_loop/message_loop.h"
  18 #include "base/message_loop/message_loop_proxy.h"
  19 #include "base/metrics/histogram.h"
  20 #include "base/prefs/pref_service.h"
  21 #include "base/strings/string_number_conversions.h"
  22 #include "base/strings/string_util.h"
  23 #include "base/strings/stringprintf.h"
  24 #include "base/threading/thread.h"
  25 #include "base/threading/thread_restrictions.h"
  26 #include "base/time/time.h"
  27 #include "chrome/browser/browser_process.h"
  28 #include "chrome/browser/chrome_notification_types.h"
  29 #include "chrome/browser/ui/browser.h"
  30 #include "chrome/browser/ui/browser_iterator.h"
  31 #include "chrome/browser/ui/tabs/tab_strip_model.h"
  32 #include "chrome/common/chrome_switches.h"
  33 #include "chrome/common/pref_names.h"
  34 #include "components/user_manager/user_manager.h"
  35 #include "content/public/browser/browser_thread.h"
  36 #include "content/public/browser/navigation_controller.h"
  37 #include "content/public/browser/notification_service.h"
  38 #include "content/public/browser/render_widget_host_view.h"
  39 #include "content/public/browser/web_contents.h"
  40
  41 using content::BrowserThread;
  42 using content::NavigationController;
  43 using content::RenderWidgetHost;
  44 using content::RenderWidgetHostView;
  45 using content::WebContents;
  46
  47 namespace {
  48
  49 const char kUptime[] = "uptime";
  50 const char kDisk[] = "disk";
  51
  52 RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
  53   WebContents* web_contents = tab->GetWebContents();
  54   if (web_contents) {
  55     RenderWidgetHostView* render_widget_host_view =
  56         web_contents->GetRenderWidgetHostView();
  57     if (render_widget_host_view)
  58       return render_widget_host_view->GetRenderWidgetHost();
  59   }
  60   return NULL;
  61 }
  62
  63 const std::string GetTabUrl(RenderWidgetHost* rwh) {
  64   RenderWidgetHostView* rwhv = rwh->GetView();
  65   for (chrome::BrowserIterator it; !it.done(); it.Next()) {
  66     Browser* browser = *it;
  67     for (int i = 0, tab_count = browser->tab_strip_model()->count();
  68          i < tab_count;
  69          ++i) {
  70       WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
  71       if (tab->GetRenderWidgetHostView() == rwhv) {
  72         return tab->GetLastCommittedURL().spec();
  73       }
  74     }
  75   }
  76   return std::string();
  77 }
  78
  79 // Appends the given buffer into the file. Returns the number of bytes
  80 // written, or -1 on error.
  81 // TODO(satorux): Move this to file_util.
  82 int AppendFile(const base::FilePath& file_path, const char* data, int size) {
  83   FILE* file = base::OpenFile(file_path, "a");
  84   if (!file)
  85     return -1;
  86
  87   const int num_bytes_written = fwrite(data, 1, size, file);
  88   base::CloseFile(file);
  89   return num_bytes_written;
  90 }
  91
  92 }  // namespace
  93
  94 namespace chromeos {
  95
  96 #define FPL(value) FILE_PATH_LITERAL(value)
  97
  98 // Dir uptime & disk logs are located in.
  99 static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
 100 // Dir log{in,out} logs are located in.
 101 static const base::FilePath::CharType kLoginLogPath[] =
 102     FPL("/home/chronos/user");
 103 // Prefix for the time measurement files.
 104 static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
 105 // Prefix for the disk usage files.
 106 static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
 107 // Name of the time that Chrome's main() is called.
 108 static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
 109 // Delay in milliseconds before writing the login times to disk.
 110 static const int64 kLoginTimeWriteDelayMs = 3000;
 111
 112 // Names of login stats files.
 113 static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
 114 static const base::FilePath::CharType kChromeFirstRender[] =
 115     FPL("chrome-first-render");
 116
 117 // Names of login UMA values.
 118 static const char kUmaLogin[] = "BootTime.Login";
 119 static const char kUmaLoginNewUser[] = "BootTime.LoginNewUser";
 120 static const char kUmaLoginPrefix[] = "BootTime.";
 121 static const char kUmaLogout[] = "ShutdownTime.Logout";
 122 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
 123 static const char kUmaRestart[] = "ShutdownTime.Restart";
 124
 125 // Name of file collecting login times.
 126 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
 127
 128 // Name of file collecting logout times.
 129 static const char kLogoutTimes[] = "logout-times";
 130
 131 static base::LazyInstance<BootTimesRecorder> g_boot_times_recorder =
 132     LAZY_INSTANCE_INITIALIZER;
 133
 134 // static
 135 BootTimesRecorder::Stats BootTimesRecorder::Stats::GetCurrentStats() {
 136   const base::FilePath kProcUptime(FPL("/proc/uptime"));
 137   const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
 138   Stats stats;
 139   // Callers of this method expect synchronous behavior.
 140   // It's safe to allow IO here, because only virtual FS are accessed.
 141   base::ThreadRestrictions::ScopedAllowIO allow_io;
 142   base::ReadFileToString(kProcUptime, &stats.uptime_);
 143   base::ReadFileToString(kDiskStat, &stats.disk_);
 144   return stats;
 145 }
 146
 147 std::string BootTimesRecorder::Stats::SerializeToString() const {
 148   if (uptime_.empty() && disk_.empty())
 149     return std::string();
 150   base::DictionaryValue dictionary;
 151   dictionary.SetString(kUptime, uptime_);
 152   dictionary.SetString(kDisk, disk_);
 153
 154   std::string result;
 155   if (!base::JSONWriter::Write(&dictionary, &result)) {
 156     LOG(WARNING) << "BootTimesRecorder::Stats::SerializeToString(): failed.";
 157     return std::string();
 158   }
 159
 160   return result;
 161 }
 162
 163 // static
 164 BootTimesRecorder::Stats BootTimesRecorder::Stats::DeserializeFromString(
 165     const std::string& source) {
 166   if (source.empty())
 167     return Stats();
 168
 169   scoped_ptr<base::Value> value(base::JSONReader::Read(source));
 170   base::DictionaryValue* dictionary;
 171   if (!value || !value->GetAsDictionary(&dictionary)) {
 172     LOG(ERROR) << "BootTimesRecorder::Stats::DeserializeFromString(): not a "
 173                   "dictionary: '" << source << "'";
 174     return Stats();
 175   }
 176
 177   Stats result;
 178   if (!dictionary->GetString(kUptime, &result.uptime_) ||
 179       !dictionary->GetString(kDisk, &result.disk_)) {
 180     LOG(ERROR)
 181         << "BootTimesRecorder::Stats::DeserializeFromString(): format error: '"
 182         << source << "'";
 183     return Stats();
 184   }
 185
 186   return result;
 187 }
 188
 189 bool BootTimesRecorder::Stats::UptimeDouble(double* result) const {
 190   std::string uptime = uptime_;
 191   const size_t space_at = uptime.find_first_of(' ');
 192   if (space_at == std::string::npos)
 193     return false;
 194
 195   uptime.resize(space_at);
 196
 197   if (base::StringToDouble(uptime, result))
 198     return true;
 199
 200   return false;
 201 }
 202
 203 void BootTimesRecorder::Stats::RecordStats(const std::string& name) const {
 204   BrowserThread::PostBlockingPoolTask(
 205       FROM_HERE,
 206       base::Bind(&BootTimesRecorder::Stats::RecordStatsImpl,
 207                  base::Owned(new Stats(*this)),
 208                  name));
 209 }
 210
 211 void BootTimesRecorder::Stats::RecordStatsWithCallback(
 212     const std::string& name,
 213     const base::Closure& callback) const {
 214   BrowserThread::PostBlockingPoolTaskAndReply(
 215       FROM_HERE,
 216       base::Bind(&BootTimesRecorder::Stats::RecordStatsImpl,
 217                  base::Owned(new Stats(*this)),
 218                  name),
 219       callback);
 220 }
 221
 222 void BootTimesRecorder::Stats::RecordStatsImpl(
 223     const base::FilePath::StringType& name) const {
 224   DCHECK(content::BrowserThread::GetBlockingPool()->RunsTasksOnCurrentThread());
 225
 226   const base::FilePath log_path(kLogPath);
 227   const base::FilePath uptime_output =
 228       log_path.Append(base::FilePath(kUptimePrefix + name));
 229   const base::FilePath disk_output =
 230       log_path.Append(base::FilePath(kDiskPrefix + name));
 231
 232   // Append numbers to the files.
 233   AppendFile(uptime_output, uptime_.data(), uptime_.size());
 234   AppendFile(disk_output, disk_.data(), disk_.size());
 235 }
 236
 237 BootTimesRecorder::BootTimesRecorder()
 238     : have_registered_(false),
 239       login_done_(false),
 240       restart_requested_(false) {
 241   login_time_markers_.reserve(30);
 242   logout_time_markers_.reserve(30);
 243 }
 244
 245 BootTimesRecorder::~BootTimesRecorder() {
 246 }
 247
 248 // static
 249 BootTimesRecorder* BootTimesRecorder::Get() {
 250   return g_boot_times_recorder.Pointer();
 251 }
 252
 253 // static
 254 void BootTimesRecorder::WriteTimes(const std::string base_name,
 255                                    const std::string uma_name,
 256                                    const std::string uma_prefix,
 257                                    std::vector<TimeMarker> login_times) {
 258   const int kMinTimeMillis = 1;
 259   const int kMaxTimeMillis = 30000;
 260   const int kNumBuckets = 100;
 261   const base::FilePath log_path(kLoginLogPath);
 262
 263   // Need to sort by time since the entries may have been pushed onto the
 264   // vector (on the UI thread) in a different order from which they were
 265   // created (potentially on other threads).
 266   std::sort(login_times.begin(), login_times.end());
 267
 268   base::Time first = login_times.front().time();
 269   base::Time last = login_times.back().time();
 270   base::TimeDelta total = last - first;
 271   base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
 272       uma_name,
 273       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 274       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 275       kNumBuckets,
 276       base::HistogramBase::kUmaTargetedHistogramFlag);
 277   total_hist->AddTime(total);
 278   std::string output =
 279       base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
 280   base::Time prev = first;
 281   for (unsigned int i = 0; i < login_times.size(); ++i) {
 282     TimeMarker tm = login_times[i];
 283     base::TimeDelta since_first = tm.time() - first;
 284     base::TimeDelta since_prev = tm.time() - prev;
 285     std::string name;
 286
 287     if (tm.send_to_uma()) {
 288       name = uma_prefix + tm.name();
 289       base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
 290           name,
 291           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 292           base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 293           kNumBuckets,
 294           base::HistogramBase::kUmaTargetedHistogramFlag);
 295       prev_hist->AddTime(since_prev);
 296     } else {
 297       name = tm.name();
 298     }
 299     output +=
 300         base::StringPrintf(
 301             "\n%.2f +%.4f %s",
 302             since_first.InSecondsF(),
 303             since_prev.InSecondsF(),
 304             name.data());
 305     prev = tm.time();
 306   }
 307   output += '\n';
 308
 309   base::WriteFile(log_path.Append(base_name), output.data(), output.size());
 310 }
 311
 312 void BootTimesRecorder::LoginDone(bool is_user_new) {
 313   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 314   if (login_done_)
 315     return;
 316
 317   login_done_ = true;
 318   AddLoginTimeMarker("LoginDone", false);
 319   RecordCurrentStats(kChromeFirstRender);
 320   if (have_registered_) {
 321     registrar_.Remove(this,
 322                       content::NOTIFICATION_LOAD_START,
 323                       content::NotificationService::AllSources());
 324     registrar_.Remove(this,
 325                       content::NOTIFICATION_LOAD_STOP,
 326                       content::NotificationService::AllSources());
 327     registrar_.Remove(this,
 328                       content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 329                       content::NotificationService::AllSources());
 330     registrar_.Remove(
 331         this,
 332         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 333         content::NotificationService::AllSources());
 334   }
 335   // Don't swamp the FILE thread right away.
 336   BrowserThread::PostDelayedTask(
 337       BrowserThread::FILE,
 338       FROM_HERE,
 339       base::Bind(&WriteTimes,
 340                  kLoginTimes,
 341                  (is_user_new ? kUmaLoginNewUser : kUmaLogin),
 342                  kUmaLoginPrefix,
 343                  login_time_markers_),
 344       base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
 345 }
 346
 347 void BootTimesRecorder::WriteLogoutTimes() {
 348   // Either we're on the browser thread, or (more likely) Chrome is in the
 349   // process of shutting down and we're on the main thread but the message loop
 350   // has already been terminated.
 351   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 352          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
 353
 354   WriteTimes(kLogoutTimes,
 355              (restart_requested_ ? kUmaRestart : kUmaLogout),
 356              kUmaLogoutPrefix,
 357              logout_time_markers_);
 358 }
 359
 360 // static
 361 void BootTimesRecorder::ClearLogoutStartedLastPreference() {
 362   PrefService* local_state = g_browser_process->local_state();
 363   local_state->ClearPref(prefs::kLogoutStartedLast);
 364 }
 365
 366 void BootTimesRecorder::OnChromeProcessStart() {
 367   PrefService* local_state = g_browser_process->local_state();
 368   const std::string logout_started_last_str =
 369       local_state->GetString(prefs::kLogoutStartedLast);
 370   if (logout_started_last_str.empty())
 371     return;
 372
 373   // Note that kLogoutStartedLast is not cleared on format error to stay in
 374   // logs in case of other fatal system errors.
 375
 376   const Stats logout_started_last_stats =
 377       Stats::DeserializeFromString(logout_started_last_str);
 378   if (logout_started_last_stats.uptime().empty())
 379     return;
 380
 381   double logout_started_last;
 382   double uptime;
 383   if (!logout_started_last_stats.UptimeDouble(&logout_started_last) ||
 384       !Stats::GetCurrentStats().UptimeDouble(&uptime)) {
 385     return;
 386   }
 387
 388   if (logout_started_last >= uptime) {
 389     // Reboot happened.
 390     ClearLogoutStartedLastPreference();
 391     return;
 392   }
 393
 394   // Write /tmp/uptime-logout-started as well.
 395   const char kLogoutStarted[] = "logout-started";
 396   logout_started_last_stats.RecordStatsWithCallback(
 397       kLogoutStarted,
 398       base::Bind(&BootTimesRecorder::ClearLogoutStartedLastPreference));
 399 }
 400
 401 void BootTimesRecorder::OnLogoutStarted(PrefService* state) {
 402   const std::string uptime = Stats::GetCurrentStats().SerializeToString();
 403   if (!uptime.empty())
 404     state->SetString(prefs::kLogoutStartedLast, uptime);
 405 }
 406
 407 void BootTimesRecorder::RecordCurrentStats(const std::string& name) {
 408   Stats::GetCurrentStats().RecordStats(name);
 409 }
 410
 411 void BootTimesRecorder::SaveChromeMainStats() {
 412   chrome_main_stats_ = Stats::GetCurrentStats();
 413 }
 414
 415 void BootTimesRecorder::RecordChromeMainStats() {
 416   chrome_main_stats_.RecordStats(kChromeMain);
 417 }
 418
 419 void BootTimesRecorder::RecordLoginAttempted() {
 420   DCHECK_CURRENTLY_ON(BrowserThread::UI);
 421   if (login_done_)
 422     return;
 423
 424   login_time_markers_.clear();
 425   AddLoginTimeMarker("LoginStarted", false);
 426   if (!have_registered_) {
 427     have_registered_ = true;
 428     registrar_.Add(this, content::NOTIFICATION_LOAD_START,
 429                    content::NotificationService::AllSources());
 430     registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
 431                    content::NotificationService::AllSources());
 432     registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 433                    content::NotificationService::AllSources());
 434     registrar_.Add(
 435         this,
 436         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 437         content::NotificationService::AllSources());
 438   }
 439 }
 440
 441 void BootTimesRecorder::AddLoginTimeMarker(const std::string& marker_name,
 442                                            bool send_to_uma) {
 443   AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
 444 }
 445
 446 void BootTimesRecorder::AddLogoutTimeMarker(const std::string& marker_name,
 447                                             bool send_to_uma) {
 448   AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
 449 }
 450
 451 // static
 452 void BootTimesRecorder::AddMarker(std::vector<TimeMarker>* vector,
 453                                   TimeMarker marker) {
 454   // The marker vectors can only be safely manipulated on the main thread.
 455   // If we're late in the process of shutting down (eg. as can be the case at
 456   // logout), then we have to assume we're on the main thread already.
 457   if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 458       !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
 459     vector->push_back(marker);
 460   } else {
 461     // Add the marker on the UI thread.
 462     // Note that it's safe to use an unretained pointer to the vector because
 463     // BootTimesRecorder's lifetime exceeds that of the UI thread message loop.
 464     BrowserThread::PostTask(
 465         BrowserThread::UI, FROM_HERE,
 466         base::Bind(&BootTimesRecorder::AddMarker,
 467                    base::Unretained(vector),
 468                    marker));
 469   }
 470 }
 471
 472 void BootTimesRecorder::RecordAuthenticationSuccess() {
 473   AddLoginTimeMarker("Authenticate", true);
 474   RecordCurrentStats(kLoginSuccess);
 475 }
 476
 477 void BootTimesRecorder::RecordAuthenticationFailure() {
 478   // Do nothing for now.
 479 }
 480
 481 void BootTimesRecorder::Observe(int type,
 482                                 const content::NotificationSource& source,
 483                                 const content::NotificationDetails& details) {
 484   switch (type) {
 485     case content::NOTIFICATION_LOAD_START: {
 486       NavigationController* tab =
 487           content::Source<NavigationController>(source).ptr();
 488       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 489       DCHECK(rwh);
 490       AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
 491       render_widget_hosts_loading_.insert(rwh);
 492       break;
 493     }
 494     case content::NOTIFICATION_LOAD_STOP: {
 495       NavigationController* tab =
 496           content::Source<NavigationController>(source).ptr();
 497       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 498       if (render_widget_hosts_loading_.find(rwh) !=
 499           render_widget_hosts_loading_.end()) {
 500         AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
 501       }
 502       break;
 503     }
 504     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
 505       RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
 506       if (render_widget_hosts_loading_.find(rwh) !=
 507           render_widget_hosts_loading_.end()) {
 508         AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
 509         LoginDone(user_manager::UserManager::Get()->IsCurrentUserNew());
 510       }
 511       break;
 512     }
 513     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
 514       WebContents* web_contents = content::Source<WebContents>(source).ptr();
 515       RenderWidgetHost* render_widget_host =
 516           GetRenderWidgetHost(&web_contents->GetController());
 517       render_widget_hosts_loading_.erase(render_widget_host);
 518       break;
 519     }
 520     default:
 521       break;
 522   }
 523 }
 524
 525 }  // namespace chromeos