Home | History | Annotate | Download | only in chromeos 
      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
    530