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 between file read attempts.
     90 static const int64 kReadAttemptDelayMs = 250;
     91 // Delay in milliseconds before writing the login times to disk.
     92 static const int64 kLoginTimeWriteDelayMs = 3000;
     93 
     94 // Names of login stats files.
     95 static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
     96 static const base::FilePath::CharType kChromeFirstRender[] =
     97     FPL("chrome-first-render");
     98 
     99 // Names of login UMA values.
    100 static const char kUmaLogin[] = "BootTime.Login";
    101 static const char kUmaLoginPrefix[] = "BootTime.";
    102 static const char kUmaLogout[] = "ShutdownTime.Logout";
    103 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
    104 
    105 // Name of file collecting login times.
    106 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
    107 
    108 // Name of file collecting logout times.
    109 static const char kLogoutTimes[] = "logout-times";
    110 
    111 static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
    112     LAZY_INSTANCE_INITIALIZER;
    113 
    114 BootTimesLoader::BootTimesLoader()
    115     : backend_(new Backend()),
    116       have_registered_(false) {
    117   login_time_markers_.reserve(30);
    118   logout_time_markers_.reserve(30);
    119 }
    120 
    121 BootTimesLoader::~BootTimesLoader() {}
    122 
    123 // static
    124 BootTimesLoader* BootTimesLoader::Get() {
    125   return g_boot_times_loader.Pointer();
    126 }
    127 
    128 // Appends the given buffer into the file. Returns the number of bytes
    129 // written, or -1 on error.
    130 // TODO(satorux): Move this to file_util.
    131 static int AppendFile(const base::FilePath& file_path,
    132                       const char* data,
    133                       int size) {
    134   FILE* file = file_util::OpenFile(file_path, "a");
    135   if (!file) {
    136     return -1;
    137   }
    138   const int num_bytes_written = fwrite(data, 1, size, file);
    139   file_util::CloseFile(file);
    140   return num_bytes_written;
    141 }
    142 
    143 static void RecordStatsDelayed(const base::FilePath::StringType& name,
    144                                const std::string& uptime,
    145                                const std::string& disk) {
    146   const base::FilePath log_path(kLogPath);
    147   const base::FilePath uptime_output =
    148       log_path.Append(base::FilePath(kUptimePrefix + name));
    149   const base::FilePath disk_output =
    150       log_path.Append(base::FilePath(kDiskPrefix + name));
    151 
    152   // Append numbers to the files.
    153   AppendFile(uptime_output, uptime.data(), uptime.size());
    154   AppendFile(disk_output, disk.data(), disk.size());
    155 }
    156 
    157 // static
    158 void BootTimesLoader::WriteTimes(
    159     const std::string base_name,
    160     const std::string uma_name,
    161     const std::string uma_prefix,
    162     std::vector<TimeMarker> login_times) {
    163   const int kMinTimeMillis = 1;
    164   const int kMaxTimeMillis = 30000;
    165   const int kNumBuckets = 100;
    166   const base::FilePath log_path(kLoginLogPath);
    167 
    168   // Need to sort by time since the entries may have been pushed onto the
    169   // vector (on the UI thread) in a different order from which they were
    170   // created (potentially on other threads).
    171   std::sort(login_times.begin(), login_times.end());
    172 
    173   base::Time first = login_times.front().time();
    174   base::Time last = login_times.back().time();
    175   base::TimeDelta total = last - first;
    176   base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
    177       uma_name,
    178       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
    179       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
    180       kNumBuckets,
    181       base::HistogramBase::kUmaTargetedHistogramFlag);
    182   total_hist->AddTime(total);
    183   std::string output =
    184       base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
    185   base::Time prev = first;
    186   for (unsigned int i = 0; i < login_times.size(); ++i) {
    187     TimeMarker tm = login_times[i];
    188     base::TimeDelta since_first = tm.time() - first;
    189     base::TimeDelta since_prev = tm.time() - prev;
    190     std::string name;
    191 
    192     if (tm.send_to_uma()) {
    193       name = uma_prefix + tm.name();
    194       base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
    195           name,
    196           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
    197           base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
    198           kNumBuckets,
    199           base::HistogramBase::kUmaTargetedHistogramFlag);
    200       prev_hist->AddTime(since_prev);
    201     } else {
    202       name = tm.name();
    203     }
    204     output +=
    205         base::StringPrintf(
    206             "\n%.2f +%.4f %s",
    207             since_first.InSecondsF(),
    208             since_prev.InSecondsF(),
    209             name.data());
    210     prev = tm.time();
    211   }
    212   output += '\n';
    213 
    214   file_util::WriteFile(
    215       log_path.Append(base_name), output.data(), output.size());
    216 }
    217 
    218 void BootTimesLoader::LoginDone() {
    219   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    220   AddLoginTimeMarker("LoginDone", false);
    221   RecordCurrentStats(kChromeFirstRender);
    222   registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
    223                     content::NotificationService::AllSources());
    224   registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
    225                     content::NotificationService::AllSources());
    226   registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
    227                     content::NotificationService::AllSources());
    228   registrar_.Remove(
    229       this,
    230       content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
    231       content::NotificationService::AllSources());
    232   // Don't swamp the FILE thread right away.
    233   BrowserThread::PostDelayedTask(
    234       BrowserThread::FILE, FROM_HERE,
    235       base::Bind(&WriteTimes, kLoginTimes, kUmaLogin, kUmaLoginPrefix,
    236                  login_time_markers_),
    237       base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
    238 }
    239 
    240 void BootTimesLoader::WriteLogoutTimes() {
    241   // Either we're on the browser thread, or (more likely) Chrome is in the
    242   // process of shutting down and we're on the main thread but the message loop
    243   // has already been terminated.
    244   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
    245          !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
    246 
    247   WriteTimes(kLogoutTimes,
    248              kUmaLogout,
    249              kUmaLogoutPrefix,
    250              logout_time_markers_);
    251 }
    252 
    253 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
    254   BrowserThread::PostTask(
    255       BrowserThread::FILE, FROM_HERE,
    256       base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
    257 }
    258 
    259 BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
    260   const base::FilePath kProcUptime(FPL("/proc/uptime"));
    261   const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
    262   Stats stats;
    263   base::ThreadRestrictions::ScopedAllowIO allow_io;
    264   file_util::ReadFileToString(kProcUptime, &stats.uptime);
    265   file_util::ReadFileToString(kDiskStat, &stats.disk);
    266   return stats;
    267 }
    268 
    269 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
    270   RecordStats(name, GetCurrentStats());
    271 }
    272 
    273 void BootTimesLoader::SaveChromeMainStats() {
    274   chrome_main_stats_ = GetCurrentStats();
    275 }
    276 
    277 void BootTimesLoader::RecordChromeMainStats() {
    278   RecordStats(kChromeMain, chrome_main_stats_);
    279 }
    280 
    281 void BootTimesLoader::RecordLoginAttempted() {
    282   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
    283   login_time_markers_.clear();
    284   AddLoginTimeMarker("LoginStarted", false);
    285   if (!have_registered_) {
    286     have_registered_ = true;
    287     registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
    288                    content::NotificationService::AllSources());
    289     registrar_.Add(this, content::NOTIFICATION_LOAD_START,
    290                    content::NotificationService::AllSources());
    291     registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
    292                    content::NotificationService::AllSources());
    293     registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
    294                    content::NotificationService::AllSources());
    295     registrar_.Add(
    296         this,
    297         content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
    298         content::NotificationService::AllSources());
    299   }
    300 }
    301 
    302 void BootTimesLoader::AddLoginTimeMarker(
    303     const std::string& marker_name, bool send_to_uma) {
    304   AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
    305 }
    306 
    307 void BootTimesLoader::AddLogoutTimeMarker(
    308     const std::string& marker_name, bool send_to_uma) {
    309   AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
    310 }
    311 
    312 // static
    313 void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
    314                                 TimeMarker marker)
    315 {
    316   // The marker vectors can only be safely manipulated on the main thread.
    317   // If we're late in the process of shutting down (eg. as can be the case at
    318   // logout), then we have to assume we're on the main thread already.
    319   if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
    320       !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
    321     vector->push_back(marker);
    322   } else {
    323     // Add the marker on the UI thread.
    324     // Note that it's safe to use an unretained pointer to the vector because
    325     // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
    326     BrowserThread::PostTask(
    327         BrowserThread::UI, FROM_HERE,
    328         base::Bind(&BootTimesLoader::AddMarker,
    329                    base::Unretained(vector),
    330                    marker));
    331   }
    332 }
    333 
    334 void BootTimesLoader::Observe(
    335     int type,
    336     const content::NotificationSource& source,
    337     const content::NotificationDetails& details) {
    338   switch (type) {
    339     case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
    340       content::Details<AuthenticationNotificationDetails> auth_details(details);
    341       if (auth_details->success()) {
    342         AddLoginTimeMarker("Authenticate", true);
    343         RecordCurrentStats(kLoginSuccess);
    344         registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
    345                           content::NotificationService::AllSources());
    346       }
    347       break;
    348     }
    349     case content::NOTIFICATION_LOAD_START: {
    350       NavigationController* tab =
    351           content::Source<NavigationController>(source).ptr();
    352       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
    353       DCHECK(rwh);
    354       AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
    355       render_widget_hosts_loading_.insert(rwh);
    356       break;
    357     }
    358     case content::NOTIFICATION_LOAD_STOP: {
    359       NavigationController* tab =
    360           content::Source<NavigationController>(source).ptr();
    361       RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
    362       if (render_widget_hosts_loading_.find(rwh) !=
    363           render_widget_hosts_loading_.end()) {
    364         AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
    365       }
    366       break;
    367     }
    368     case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
    369       RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
    370       if (render_widget_hosts_loading_.find(rwh) !=
    371           render_widget_hosts_loading_.end()) {
    372         AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
    373         LoginDone();
    374       }
    375       break;
    376     }
    377     case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
    378       WebContents* web_contents = content::Source<WebContents>(source).ptr();
    379       RenderWidgetHost* render_widget_host =
    380           GetRenderWidgetHost(&web_contents->GetController());
    381       render_widget_hosts_loading_.erase(render_widget_host);
    382       break;
    383     }
    384     default:
    385       break;
    386   }
    387 }
    388 
    389 }  // namespace chromeos
    390