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
30namespace chromeos {
31
32#define FPL(value) FILE_PATH_LITERAL(value)
33
34// File uptime logs are located in.
35static const FilePath::CharType kLogPath[] = FPL("/tmp");
36// Prefix for the time measurement files.
37static const FilePath::CharType kUptimePrefix[] = FPL("uptime-");
38// Prefix for the disk usage files.
39static const FilePath::CharType kDiskPrefix[] = FPL("disk-");
40// Name of the time that Chrome's main() is called.
41static const FilePath::CharType kChromeMain[] = FPL("chrome-main");
42// Delay in milliseconds between file read attempts.
43static const int64 kReadAttemptDelayMs = 250;
44// Delay in milliseconds before writing the login times to disk.
45static const int64 kLoginTimeWriteDelayMs = 3000;
46
47// Names of login stats files.
48static const FilePath::CharType kLoginSuccess[] = FPL("login-success");
49static const FilePath::CharType kChromeFirstRender[] =
50    FPL("chrome-first-render");
51
52// Names of login UMA values.
53static const char kUmaAuthenticate[] = "BootTime.Authenticate";
54static const char kUmaLogin[] = "BootTime.Login";
55static const char kUmaLoginPrefix[] = "BootTime.";
56static const char kUmaLogout[] = "ShutdownTime.Logout";
57static const char kUmaLogoutPrefix[] = "ShutdownTime.";
58
59// Name of file collecting login times.
60static const FilePath::CharType kLoginTimes[] = FPL("login-times-sent");
61
62// Name of file collecting logout times.
63static const char kLogoutTimes[] = "logout-times-sent";
64
65static base::LazyInstance<BootTimesLoader> g_boot_times_loader(
66    base::LINKER_INITIALIZED);
67
68BootTimesLoader::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
76BootTimesLoader* BootTimesLoader::Get() {
77  return g_boot_times_loader.Pointer();
78}
79
80BootTimesLoader::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.
109static 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.
125static 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.
132static 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
172void 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.
223static 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
235static 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
249void 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
302void BootTimesLoader::WriteLogoutTimes() {
303  WriteTimes(kLogoutTimes,
304             kUmaLogout,
305             kUmaLogoutPrefix,
306             logout_time_markers_);
307}
308
309void 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
316BootTimesLoader::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
326void BootTimesLoader::RecordCurrentStats(const std::string& name) {
327  RecordStats(name, GetCurrentStats());
328}
329
330void BootTimesLoader::SaveChromeMainStats() {
331  chrome_main_stats_ = GetCurrentStats();
332}
333
334void BootTimesLoader::RecordChromeMainStats() {
335  RecordStats(kChromeMain, chrome_main_stats_);
336}
337
338void 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
350void 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
355void 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
360void 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