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