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