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/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<BootTimesLoader> g_boot_times_loader =
 132     LAZY_INSTANCE_INITIALIZER;
 133
 134 // static
 135 BootTimesLoader::Stats BootTimesLoader::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 BootTimesLoader::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) << "BootTimesLoader::Stats::SerializeToString(): failed.";
 157     return std::string();
 158   }
 159
 160   return result;
 161 }
 162
 163 // static
 164 BootTimesLoader::Stats BootTimesLoader::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) << "BootTimesLoader::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         << "BootTimesLoader::Stats::DeserializeFromString(): format error: '"
 182         << source << "'";
 183     return Stats();
 184   }
 185
 186   return result;
 187 }
 188
 189 bool BootTimesLoader::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 BootTimesLoader::Stats::RecordStats(const std::string& name) const {
 204   BrowserThread::PostBlockingPoolTask(
 205       FROM_HERE,
 206       base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
 207                  base::Owned(new Stats(*this)),
 208                  name));
 209 }
 210
 211 void BootTimesLoader::Stats::RecordStatsWithCallback(
 212     const std::string& name,
 213     const base::Closure& callback) const {
 214   BrowserThread::PostBlockingPoolTaskAndReply(
 215       FROM_HERE,
 216       base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
 217                  base::Owned(new Stats(*this)),
 218                  name),
 219       callback);
 220 }
 221
 222 void BootTimesLoader::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 BootTimesLoader::BootTimesLoader()
 238     : backend_(new Backend()),
 239       have_registered_(false),
 240       login_done_(false),
 241       restart_requested_(false) {
 242   login_time_markers_.reserve(30);
 243   logout_time_markers_.reserve(30);
 244 }
 245
 246 BootTimesLoader::~BootTimesLoader() {
 247 }
 248
 249 // static
 250 BootTimesLoader* BootTimesLoader::Get() {
 251   return g_boot_times_loader.Pointer();
 252 }
 253
 254 // static
 255 void BootTimesLoader::WriteTimes(
 256     const std::string base_name,
 257     const std::string uma_name,
 258     const std::string uma_prefix,
 259     std::vector<TimeMarker> login_times) {
 260   const int kMinTimeMillis = 1;
 261   const int kMaxTimeMillis = 30000;
 262   const int kNumBuckets = 100;
 263   const base::FilePath log_path(kLoginLogPath);
 264
 265   // Need to sort by time since the entries may have been pushed onto the
 266   // vector (on the UI thread) in a different order from which they were
 267   // created (potentially on other threads).
 268   std::sort(login_times.begin(), login_times.end());
 269
 270   base::Time first = login_times.front().time();
 271   base::Time last = login_times.back().time();
 272   base::TimeDelta total = last - first;
 273   base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
 274       uma_name,
 275       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 276       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 277       kNumBuckets,
 278       base::HistogramBase::kUmaTargetedHistogramFlag);
 279   total_hist->AddTime(total);
 280   std::string output =
 281       base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
 282   base::Time prev = first;
 283   for (unsigned int i = 0; i < login_times.size(); ++i) {
 284     TimeMarker tm = login_times[i];
 285     base::TimeDelta since_first = tm.time() - first;
 286     base::TimeDelta since_prev = tm.time() - prev;
 287     std::string name;
 288
 289     if (tm.send_to_uma()) {
 290       name = uma_prefix + tm.name();
 291       base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
 292           name,
 293           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
 294           base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
 295           kNumBuckets,
 296           base::HistogramBase::kUmaTargetedHistogramFlag);
 297       prev_hist->AddTime(since_prev);
 298     } else {
 299       name = tm.name();
 300     }
 301     output +=
 302         base::StringPrintf(
 303             "\n%.2f +%.4f %s",
 304             since_first.InSecondsF(),
 305             since_prev.InSecondsF(),
 306             name.data());
 307     prev = tm.time();
 308   }
 309   output += '\n';
 310
 311   base::WriteFile(log_path.Append(base_name), output.data(), output.size());
 312 }
 313
 314 void BootTimesLoader::LoginDone(bool is_user_new) {
 315   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 316   if (login_done_)
 317     return;
 318
 319   login_done_ = true;
 320   AddLoginTimeMarker("LoginDone", false);
 321   RecordCurrentStats(kChromeFirstRender);
 322   if (have_registered_) {
 323     registrar_.Remove(this,
 324                       content::NOTIFICATION_LOAD_START,
 325                       content::NotificationService::AllSources());
 326     registrar_.Remove(this,
 327                       content::NOTIFICATION_LOAD_STOP,
 328                       content::NotificationService::AllSources());
 329     registrar_.Remove(this,
 330                       content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 331                       content::NotificationService::AllSources());
 332     registrar_.Remove(
 333         this,
 334         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 335         content::NotificationService::AllSources());
 336   }
 337   // Don't swamp the FILE thread right away.
 338   BrowserThread::PostDelayedTask(
 339       BrowserThread::FILE,
 340       FROM_HERE,
 341       base::Bind(&WriteTimes,
 342                  kLoginTimes,
 343                  (is_user_new ? kUmaLoginNewUser : kUmaLogin),
 344                  kUmaLoginPrefix,
 345                  login_time_markers_),
 346       base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
 347 }
 348
 349 void BootTimesLoader::WriteLogoutTimes() {
 350   // Either we're on the browser thread, or (more likely) Chrome is in the
 351   // process of shutting down and we're on the main thread but the message loop
 352   // has already been terminated.
 353   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 354          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
 355
 356   WriteTimes(kLogoutTimes,
 357              (restart_requested_ ? kUmaRestart : kUmaLogout),
 358              kUmaLogoutPrefix,
 359              logout_time_markers_);
 360 }
 361
 362 // static
 363 void BootTimesLoader::ClearLogoutStartedLastPreference() {
 364   PrefService* local_state = g_browser_process->local_state();
 365   local_state->ClearPref(prefs::kLogoutStartedLast);
 366 }
 367
 368 void BootTimesLoader::OnChromeProcessStart() {
 369   PrefService* local_state = g_browser_process->local_state();
 370   const std::string logout_started_last_str =
 371       local_state->GetString(prefs::kLogoutStartedLast);
 372   if (logout_started_last_str.empty())
 373     return;
 374
 375   // Note that kLogoutStartedLast is not cleared on format error to stay in
 376   // logs in case of other fatal system errors.
 377
 378   const Stats logout_started_last_stats =
 379       Stats::DeserializeFromString(logout_started_last_str);
 380   if (logout_started_last_stats.uptime().empty())
 381     return;
 382
 383   double logout_started_last;
 384   double uptime;
 385   if (!logout_started_last_stats.UptimeDouble(&logout_started_last) ||
 386       !Stats::GetCurrentStats().UptimeDouble(&uptime)) {
 387     return;
 388   }
 389
 390   if (logout_started_last >= uptime) {
 391     // Reboot happened.
 392     ClearLogoutStartedLastPreference();
 393     return;
 394   }
 395
 396   // Write /tmp/uptime-logout-started as well.
 397   const char kLogoutStarted[] = "logout-started";
 398   logout_started_last_stats.RecordStatsWithCallback(
 399       kLogoutStarted,
 400       base::Bind(&BootTimesLoader::ClearLogoutStartedLastPreference));
 401 }
 402
 403 void BootTimesLoader::OnLogoutStarted(PrefService* state) {
 404   const std::string uptime = Stats::GetCurrentStats().SerializeToString();
 405   if (!uptime.empty())
 406     state->SetString(prefs::kLogoutStartedLast, uptime);
 407 }
 408
 409 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
 410   Stats::GetCurrentStats().RecordStats(name);
 411 }
 412
 413 void BootTimesLoader::SaveChromeMainStats() {
 414   chrome_main_stats_ = Stats::GetCurrentStats();
 415 }
 416
 417 void BootTimesLoader::RecordChromeMainStats() {
 418   chrome_main_stats_.RecordStats(kChromeMain);
 419 }
 420
 421 void BootTimesLoader::RecordLoginAttempted() {
 422   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
 423   if (login_done_)
 424     return;
 425
 426   login_time_markers_.clear();
 427   AddLoginTimeMarker("LoginStarted", false);
 428   if (!have_registered_) {
 429     have_registered_ = true;
 430     registrar_.Add(this, content::NOTIFICATION_LOAD_START,
 431                    content::NotificationService::AllSources());
 432     registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
 433                    content::NotificationService::AllSources());
 434     registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
 435                    content::NotificationService::AllSources());
 436     registrar_.Add(
 437         this,
 438         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
 439         content::NotificationService::AllSources());
 440   }
 441 }
 442
 443 void BootTimesLoader::AddLoginTimeMarker(
 444     const std::string& marker_name, bool send_to_uma) {
 445   AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
 446 }
 447
 448 void BootTimesLoader::AddLogoutTimeMarker(
 449     const std::string& marker_name, bool send_to_uma) {
 450   AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
 451 }
 452
 453 // static
 454 void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
 455                                 TimeMarker marker)
 456 {
 457   // The marker vectors can only be safely manipulated on the main thread.
 458   // If we're late in the process of shutting down (eg. as can be the case at
 459   // logout), then we have to assume we're on the main thread already.
 460   if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
 461       !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
 462     vector->push_back(marker);
 463   } else {
 464     // Add the marker on the UI thread.
 465     // Note that it's safe to use an unretained pointer to the vector because
 466     // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
 467     BrowserThread::PostTask(
 468         BrowserThread::UI, FROM_HERE,
 469         base::Bind(&BootTimesLoader::AddMarker,
 470                    base::Unretained(vector),
 471                    marker));
 472   }
 473 }
 474
 475 void BootTimesLoader::RecordAuthenticationSuccess() {
 476   AddLoginTimeMarker("Authenticate", true);
 477   RecordCurrentStats(kLoginSuccess);
 478 }
 479
 480 void BootTimesLoader::RecordAuthenticationFailure() {
 481   // Do nothing for now.
 482 }
 483
 484 void BootTimesLoader::Observe(
 485     int type,
 486     const content::NotificationSource& source,
 487     const content::NotificationDetails& details) {
 488   switch (type) {
 489     case content::NOTIFICATION_LOAD_START: {
 490       NavigationController* tab =
 491           content::Source<NavigationController>(source).ptr();
 492       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 493       DCHECK(rwh);
 494       AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
 495       render_widget_hosts_loading_.insert(rwh);
 496       break;
 497     }
 498     case content::NOTIFICATION_LOAD_STOP: {
 499       NavigationController* tab =
 500           content::Source<NavigationController>(source).ptr();
 501       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
 502       if (render_widget_hosts_loading_.find(rwh) !=
 503           render_widget_hosts_loading_.end()) {
 504         AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
 505       }
 506       break;
 507     }
 508     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
 509       RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
 510       if (render_widget_hosts_loading_.find(rwh) !=
 511           render_widget_hosts_loading_.end()) {
 512         AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
 513         LoginDone(user_manager::UserManager::Get()->IsCurrentUserNew());
 514       }
 515       break;
 516     }
 517     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
 518       WebContents* web_contents = content::Source<WebContents>(source).ptr();
 519       RenderWidgetHost* render_widget_host =
 520           GetRenderWidgetHost(&web_contents->GetController());
 521       render_widget_hosts_loading_.erase(render_widget_host);
 522       break;
 523     }
 524     default:
 525       break;
 526   }
 527 }
 528
 529 }  // namespace chromeos