Home | History | Annotate | Download | only in chromeos 
      1 // Copyright (c) 2011 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/command_line.h"
     10 #include "base/file_path.h"
     11 #include "base/file_util.h"
     12 #include "base/lazy_instance.h"
     13 #include "base/message_loop.h"
     14 #include "base/metrics/histogram.h"
     15 #include "base/process_util.h"
     16 #include "base/string_number_conversions.h"
     17 #include "base/string_util.h"
     18 #include "base/stringprintf.h"
     19 #include "base/threading/thread.h"
     20 #include "base/threading/thread_restrictions.h"
     21 #include "base/time.h"
     22 #include "chrome/browser/browser_process.h"
     23 #include "chrome/browser/chromeos/login/authentication_notification_details.h"
     24 #include "chrome/browser/chromeos/login/user_manager.h"
     25 #include "chrome/browser/chromeos/network_state_notifier.h"
     26 #include "chrome/common/chrome_switches.h"
     27 #include "content/browser/browser_thread.h"
     28 #include "content/common/notification_service.h"
     29 
     30 namespace chromeos {
     31 
     32 #define FPL(value) FILE_PATH_LITERAL(value)
     33 
     34 // File uptime logs are located in.
     35 static const FilePath::CharType kLogPath[] = FPL("/tmp");
     36 // Prefix for the time measurement files.
     37 static const FilePath::CharType kUptimePrefix[] = FPL("uptime-");
     38 // Prefix for the disk usage files.
     39 static const FilePath::CharType kDiskPrefix[] = FPL("disk-");
     40 // Name of the time that Chrome's main() is called.
     41 static const FilePath::CharType kChromeMain[] = FPL("chrome-main");
     42 // Delay in milliseconds between file read attempts.
     43 static const int64 kReadAttemptDelayMs = 250;
     44 // Delay in milliseconds before writing the login times to disk.
     45 static const int64 kLoginTimeWriteDelayMs = 3000;
     46 
     47 // Names of login stats files.
     48 static const FilePath::CharType kLoginSuccess[] = FPL("login-success");
     49 static const FilePath::CharType kChromeFirstRender[] =
     50     FPL("chrome-first-render");
     51 
     52 // Names of login UMA values.
     53 static const char kUmaAuthenticate[] = "BootTime.Authenticate";
     54 static const char kUmaLogin[] = "BootTime.Login";
     55 static const char kUmaLoginPrefix[] = "BootTime.";
     56 static const char kUmaLogout[] = "ShutdownTime.Logout";
     57 static const char kUmaLogoutPrefix[] = "ShutdownTime.";
     58 
     59 // Name of file collecting login times.
     60 static const FilePath::CharType kLoginTimes[] = FPL("login-times-sent");
     61 
     62 // Name of file collecting logout times.
     63 static const char kLogoutTimes[] = "logout-times-sent";
     64 
     65 static base::LazyInstance<BootTimesLoader> g_boot_times_loader(
     66     base::LINKER_INITIALIZED);
     67 
     68 BootTimesLoader::BootTimesLoader()
     69     : backend_(new Backend()),
     70       have_registered_(false) {
     71   login_time_markers_.reserve(30);
     72   logout_time_markers_.reserve(30);
     73 }
     74 
     75 // static
     76 BootTimesLoader* BootTimesLoader::Get() {
     77   return g_boot_times_loader.Pointer();
     78 }
     79 
     80 BootTimesLoader::Handle BootTimesLoader::GetBootTimes(
     81     CancelableRequestConsumerBase* consumer,
     82     BootTimesLoader::GetBootTimesCallback* callback) {
     83   if (!g_browser_process->file_thread()) {
     84     // This should only happen if Chrome is shutting down, so we don't do
     85     // anything.
     86     return 0;
     87   }
     88 
     89   const CommandLine& command_line = *CommandLine::ForCurrentProcess();
     90   if (command_line.HasSwitch(switches::kTestType)) {
     91     // TODO(davemoore) This avoids boottimes for tests. This needs to be
     92     // replaced with a mock of BootTimesLoader.
     93     return 0;
     94   }
     95 
     96   scoped_refptr<CancelableRequest<GetBootTimesCallback> > request(
     97       new CancelableRequest<GetBootTimesCallback>(callback));
     98   AddRequest(request, consumer);
     99 
    100   BrowserThread::PostTask(
    101       BrowserThread::FILE,
    102       FROM_HERE,
    103       NewRunnableMethod(backend_.get(), &Backend::GetBootTimes, request));
    104   return request->handle();
    105 }
    106 
    107 // Extracts the uptime value from files located in /tmp, returning the
    108 // value as a double in value.
    109 static bool GetTime(const FilePath::StringType& log, double* value) {
    110   FilePath log_dir(kLogPath);
    111   FilePath log_file = log_dir.Append(log);
    112   std::string contents;
    113   *value = 0.0;
    114   if (file_util::ReadFileToString(log_file, &contents)) {
    115     size_t space_index = contents.find(' ');
    116     size_t chars_left =
    117         space_index != std::string::npos ? space_index : std::string::npos;
    118     std::string value_string = contents.substr(0, chars_left);
    119     return base::StringToDouble(value_string, value);
    120   }
    121   return false;
    122 }
    123 
    124 // Converts double seconds to a TimeDelta object.
    125 static base::TimeDelta SecondsToTimeDelta(double seconds) {
    126   double ms = seconds * base::Time::kMillisecondsPerSecond;
    127   return base::TimeDelta::FromMilliseconds(static_cast<int64>(ms));
    128 }
    129 
    130 // Reports the collected boot times to UMA if they haven't been
    131 // reported yet and if metrics collection is enabled.
    132 static void SendBootTimesToUMA(const BootTimesLoader::BootTimes& boot_times) {
    133   // Checks if the times for the most recent boot event have been
    134   // reported already to avoid sending boot time histogram samples
    135   // every time the user logs out.
    136   static const FilePath::CharType kBootTimesSent[] =
    137       FPL("/tmp/boot-times-sent");
    138   FilePath sent(kBootTimesSent);
    139   if (file_util::PathExists(sent))
    140     return;
    141 
    142   UMA_HISTOGRAM_TIMES("BootTime.Total",
    143                       SecondsToTimeDelta(boot_times.total));
    144   UMA_HISTOGRAM_TIMES("BootTime.Firmware",
    145                       SecondsToTimeDelta(boot_times.firmware));
    146   UMA_HISTOGRAM_TIMES("BootTime.Kernel",
    147                       SecondsToTimeDelta(boot_times.pre_startup));
    148   UMA_HISTOGRAM_TIMES("BootTime.System",
    149                       SecondsToTimeDelta(boot_times.system));
    150   if (boot_times.chrome > 0) {
    151     UMA_HISTOGRAM_TIMES("BootTime.Chrome",
    152                         SecondsToTimeDelta(boot_times.chrome));
    153   }
    154 
    155   // Stores the boot times to a file in /tmp to indicate that the
    156   // times for the most recent boot event have been reported
    157   // already. The file will be deleted at system shutdown/reboot.
    158   std::string boot_times_text = base::StringPrintf("total: %.2f\n"
    159                                                    "firmware: %.2f\n"
    160                                                    "kernel: %.2f\n"
    161                                                    "system: %.2f\n"
    162                                                    "chrome: %.2f\n",
    163                                                    boot_times.total,
    164                                                    boot_times.firmware,
    165                                                    boot_times.pre_startup,
    166                                                    boot_times.system,
    167                                                    boot_times.chrome);
    168   file_util::WriteFile(sent, boot_times_text.data(), boot_times_text.size());
    169   DCHECK(file_util::PathExists(sent));
    170 }
    171 
    172 void BootTimesLoader::Backend::GetBootTimes(
    173     scoped_refptr<GetBootTimesRequest> request) {
    174   const FilePath::CharType kFirmwareBootTime[] = FPL("firmware-boot-time");
    175   const FilePath::CharType kPreStartup[] = FPL("pre-startup");
    176   const FilePath::CharType kChromeExec[] = FPL("chrome-exec");
    177   const FilePath::CharType kChromeMain[] = FPL("chrome-main");
    178   const FilePath::CharType kXStarted[] = FPL("x-started");
    179   const FilePath::CharType kLoginPromptReady[] = FPL("login-prompt-ready");
    180   const FilePath::StringType uptime_prefix = kUptimePrefix;
    181 
    182   if (request->canceled())
    183     return;
    184 
    185   // Wait until firmware-boot-time file exists by reposting.
    186   FilePath log_dir(kLogPath);
    187   FilePath log_file = log_dir.Append(kFirmwareBootTime);
    188   if (!file_util::PathExists(log_file)) {
    189     BrowserThread::PostDelayedTask(
    190         BrowserThread::FILE,
    191         FROM_HERE,
    192         NewRunnableMethod(this, &Backend::GetBootTimes, request),
    193         kReadAttemptDelayMs);
    194     return;
    195   }
    196 
    197   BootTimes boot_times;
    198 
    199   GetTime(kFirmwareBootTime, &boot_times.firmware);
    200   GetTime(uptime_prefix + kPreStartup, &boot_times.pre_startup);
    201   GetTime(uptime_prefix + kXStarted, &boot_times.x_started);
    202   GetTime(uptime_prefix + kChromeExec, &boot_times.chrome_exec);
    203   GetTime(uptime_prefix + kChromeMain, &boot_times.chrome_main);
    204   GetTime(uptime_prefix + kLoginPromptReady, &boot_times.login_prompt_ready);
    205 
    206   boot_times.total = boot_times.firmware + boot_times.login_prompt_ready;
    207   if (boot_times.chrome_exec > 0) {
    208     boot_times.system = boot_times.chrome_exec - boot_times.pre_startup;
    209     boot_times.chrome = boot_times.login_prompt_ready - boot_times.chrome_exec;
    210   } else {
    211     boot_times.system = boot_times.login_prompt_ready - boot_times.pre_startup;
    212   }
    213 
    214   SendBootTimesToUMA(boot_times);
    215 
    216   request->ForwardResult(
    217       GetBootTimesCallback::TupleType(request->handle(), boot_times));
    218 }
    219 
    220 // Appends the given buffer into the file. Returns the number of bytes
    221 // written, or -1 on error.
    222 // TODO(satorux): Move this to file_util.
    223 static int AppendFile(const FilePath& file_path,
    224                       const char* data,
    225                       int size) {
    226   FILE* file = file_util::OpenFile(file_path, "a");
    227   if (!file) {
    228     return -1;
    229   }
    230   const int num_bytes_written = fwrite(data, 1, size, file);
    231   file_util::CloseFile(file);
    232   return num_bytes_written;
    233 }
    234 
    235 static void RecordStatsDelayed(const FilePath::StringType& name,
    236                                const std::string& uptime,
    237                                const std::string& disk) {
    238   const FilePath log_path(kLogPath);
    239   const FilePath uptime_output =
    240       log_path.Append(FilePath(kUptimePrefix + name));
    241   const FilePath disk_output = log_path.Append(FilePath(kDiskPrefix + name));
    242 
    243   // Append numbers to the files.
    244   AppendFile(uptime_output, uptime.data(), uptime.size());
    245   AppendFile(disk_output, disk.data(), disk.size());
    246 }
    247 
    248 // static
    249 void BootTimesLoader::WriteTimes(
    250     const std::string base_name,
    251     const std::string uma_name,
    252     const std::string uma_prefix,
    253     const std::vector<TimeMarker> login_times) {
    254   const int kMinTimeMillis = 1;
    255   const int kMaxTimeMillis = 30000;
    256   const int kNumBuckets = 100;
    257   const FilePath log_path(kLogPath);
    258 
    259   base::Time first = login_times.front().time();
    260   base::Time last = login_times.back().time();
    261   base::TimeDelta total = last - first;
    262   base::Histogram* total_hist = base::Histogram::FactoryTimeGet(
    263       uma_name,
    264       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
    265       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
    266       kNumBuckets,
    267       base::Histogram::kUmaTargetedHistogramFlag);
    268   total_hist->AddTime(total);
    269   std::string output =
    270       base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
    271   base::Time prev = first;
    272   for (unsigned int i = 0; i < login_times.size(); ++i) {
    273     TimeMarker tm = login_times[i];
    274     base::TimeDelta since_first = tm.time() - first;
    275     base::TimeDelta since_prev = tm.time() - prev;
    276     std::string name;
    277 
    278     if (tm.send_to_uma()) {
    279       name = uma_prefix + tm.name();
    280       base::Histogram* prev_hist = base::Histogram::FactoryTimeGet(
    281           name,
    282           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
    283           base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
    284           kNumBuckets,
    285           base::Histogram::kUmaTargetedHistogramFlag);
    286       prev_hist->AddTime(since_prev);
    287     } else {
    288       name = tm.name();
    289     }
    290     output +=
    291         StringPrintf(
    292             "\n%.2f +%.2f %s",
    293             since_first.InSecondsF(),
    294             since_prev.InSecondsF(),
    295             name.data());
    296     prev = tm.time();
    297   }
    298   file_util::WriteFile(
    299       log_path.Append(base_name), output.data(), output.size());
    300 }
    301 
    302 void BootTimesLoader::WriteLogoutTimes() {
    303   WriteTimes(kLogoutTimes,
    304              kUmaLogout,
    305              kUmaLogoutPrefix,
    306              logout_time_markers_);
    307 }
    308 
    309 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
    310   BrowserThread::PostTask(
    311       BrowserThread::FILE, FROM_HERE,
    312       NewRunnableFunction(
    313           RecordStatsDelayed, name, stats.uptime, stats.disk));
    314 }
    315 
    316 BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
    317   const FilePath kProcUptime(FPL("/proc/uptime"));
    318   const FilePath kDiskStat(FPL("/sys/block/sda/stat"));
    319   Stats stats;
    320   base::ThreadRestrictions::ScopedAllowIO allow_io;
    321   file_util::ReadFileToString(kProcUptime, &stats.uptime);
    322   file_util::ReadFileToString(kDiskStat, &stats.disk);
    323   return stats;
    324 }
    325 
    326 void BootTimesLoader::RecordCurrentStats(const std::string& name) {
    327   RecordStats(name, GetCurrentStats());
    328 }
    329 
    330 void BootTimesLoader::SaveChromeMainStats() {
    331   chrome_main_stats_ = GetCurrentStats();
    332 }
    333 
    334 void BootTimesLoader::RecordChromeMainStats() {
    335   RecordStats(kChromeMain, chrome_main_stats_);
    336 }
    337 
    338 void BootTimesLoader::RecordLoginAttempted() {
    339   login_time_markers_.clear();
    340   AddLoginTimeMarker("LoginStarted", false);
    341   if (!have_registered_) {
    342     have_registered_ = true;
    343     registrar_.Add(this, NotificationType::LOAD_START,
    344                    NotificationService::AllSources());
    345     registrar_.Add(this, NotificationType::LOGIN_AUTHENTICATION,
    346                    NotificationService::AllSources());
    347   }
    348 }
    349 
    350 void BootTimesLoader::AddLoginTimeMarker(
    351     const std::string& marker_name, bool send_to_uma) {
    352   login_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
    353 }
    354 
    355 void BootTimesLoader::AddLogoutTimeMarker(
    356     const std::string& marker_name, bool send_to_uma) {
    357   logout_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
    358 }
    359 
    360 void BootTimesLoader::Observe(
    361     NotificationType type,
    362     const NotificationSource& source,
    363     const NotificationDetails& details) {
    364   if (type == NotificationType::LOGIN_AUTHENTICATION) {
    365     Details<AuthenticationNotificationDetails> auth_details(details);
    366     if (auth_details->success()) {
    367       AddLoginTimeMarker("Authenticate", true);
    368       RecordCurrentStats(kLoginSuccess);
    369       registrar_.Remove(this, NotificationType::LOGIN_AUTHENTICATION,
    370                         NotificationService::AllSources());
    371     }
    372   } else if (type == NotificationType::LOAD_START) {
    373     // Make sure it's not some page load initiated by OOBE/login screen.
    374     if (!UserManager::Get()->user_is_logged_in())
    375       return;
    376     // Only log for first tab to render.  Make sure this is only done once.
    377     // If the network isn't connected we'll get a second LOAD_START once it is
    378     // and the page is reloaded.
    379     if (NetworkStateNotifier::GetInstance()->is_connected()) {
    380       // Post difference between first tab and login success time.
    381       AddLoginTimeMarker("LoginDone", true);
    382       RecordCurrentStats(kChromeFirstRender);
    383       // Post chrome first render stat.
    384       registrar_.Remove(this, NotificationType::LOAD_START,
    385                         NotificationService::AllSources());
    386       // Don't swamp the FILE thread right away.
    387       BrowserThread::PostDelayedTask(
    388           BrowserThread::FILE, FROM_HERE,
    389           // This doesn't compile without std::string(...), as
    390           // NewRunnableFunction doesn't accept arrays.
    391           NewRunnableFunction(WriteTimes,
    392                               std::string(kLoginTimes),
    393                               std::string(kUmaLogin),
    394                               std::string(kUmaLoginPrefix),
    395                               login_time_markers_),
    396           kLoginTimeWriteDelayMs);
    397       have_registered_ = false;
    398     } else {
    399       AddLoginTimeMarker("LoginRenderNoNetwork", false);
    400     }
    401   }
    402 }
    403 
    404 }  // namespace chromeos
    405