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