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