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