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