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/files/file_path.h"
12#include "base/files/file_util.h"
13#include "base/json/json_reader.h"
14#include "base/json/json_writer.h"
15#include "base/lazy_instance.h"
16#include "base/location.h"
17#include "base/message_loop/message_loop.h"
18#include "base/message_loop/message_loop_proxy.h"
19#include "base/metrics/histogram.h"
20#include "base/prefs/pref_service.h"
21#include "base/strings/string_number_conversions.h"
22#include "base/strings/string_util.h"
23#include "base/strings/stringprintf.h"
24#include "base/threading/thread.h"
25#include "base/threading/thread_restrictions.h"
26#include "base/time/time.h"
27#include "chrome/browser/browser_process.h"
28#include "chrome/browser/chrome_notification_types.h"
29#include "chrome/browser/ui/browser.h"
30#include "chrome/browser/ui/browser_iterator.h"
31#include "chrome/browser/ui/tabs/tab_strip_model.h"
32#include "chrome/common/chrome_switches.h"
33#include "chrome/common/pref_names.h"
34#include "components/user_manager/user_manager.h"
35#include "content/public/browser/browser_thread.h"
36#include "content/public/browser/navigation_controller.h"
37#include "content/public/browser/notification_service.h"
38#include "content/public/browser/render_widget_host_view.h"
39#include "content/public/browser/web_contents.h"
40
41using content::BrowserThread;
42using content::NavigationController;
43using content::RenderWidgetHost;
44using content::RenderWidgetHostView;
45using content::WebContents;
46
47namespace {
48
49const char kUptime[] = "uptime";
50const char kDisk[] = "disk";
51
52RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
53  WebContents* web_contents = tab->GetWebContents();
54  if (web_contents) {
55    RenderWidgetHostView* render_widget_host_view =
56        web_contents->GetRenderWidgetHostView();
57    if (render_widget_host_view)
58      return render_widget_host_view->GetRenderWidgetHost();
59  }
60  return NULL;
61}
62
63const std::string GetTabUrl(RenderWidgetHost* rwh) {
64  RenderWidgetHostView* rwhv = rwh->GetView();
65  for (chrome::BrowserIterator it; !it.done(); it.Next()) {
66    Browser* browser = *it;
67    for (int i = 0, tab_count = browser->tab_strip_model()->count();
68         i < tab_count;
69         ++i) {
70      WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
71      if (tab->GetRenderWidgetHostView() == rwhv) {
72        return tab->GetLastCommittedURL().spec();
73      }
74    }
75  }
76  return std::string();
77}
78
79// Appends the given buffer into the file. Returns the number of bytes
80// written, or -1 on error.
81// TODO(satorux): Move this to file_util.
82int AppendFile(const base::FilePath& file_path, const char* data, int size) {
83  FILE* file = base::OpenFile(file_path, "a");
84  if (!file)
85    return -1;
86
87  const int num_bytes_written = fwrite(data, 1, size, file);
88  base::CloseFile(file);
89  return num_bytes_written;
90}
91
92}  // namespace
93
94namespace chromeos {
95
96#define FPL(value) FILE_PATH_LITERAL(value)
97
98// Dir uptime & disk logs are located in.
99static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
100// Dir log{in,out} logs are located in.
101static const base::FilePath::CharType kLoginLogPath[] =
102    FPL("/home/chronos/user");
103// Prefix for the time measurement files.
104static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
105// Prefix for the disk usage files.
106static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
107// Name of the time that Chrome's main() is called.
108static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
109// Delay in milliseconds before writing the login times to disk.
110static const int64 kLoginTimeWriteDelayMs = 3000;
111
112// Names of login stats files.
113static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
114static const base::FilePath::CharType kChromeFirstRender[] =
115    FPL("chrome-first-render");
116
117// Names of login UMA values.
118static const char kUmaLogin[] = "BootTime.Login";
119static const char kUmaLoginNewUser[] = "BootTime.LoginNewUser";
120static const char kUmaLoginPrefix[] = "BootTime.";
121static const char kUmaLogout[] = "ShutdownTime.Logout";
122static const char kUmaLogoutPrefix[] = "ShutdownTime.";
123static const char kUmaRestart[] = "ShutdownTime.Restart";
124
125// Name of file collecting login times.
126static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
127
128// Name of file collecting logout times.
129static const char kLogoutTimes[] = "logout-times";
130
131static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
132    LAZY_INSTANCE_INITIALIZER;
133
134// static
135BootTimesLoader::Stats BootTimesLoader::Stats::GetCurrentStats() {
136  const base::FilePath kProcUptime(FPL("/proc/uptime"));
137  const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
138  Stats stats;
139  // Callers of this method expect synchronous behavior.
140  // It's safe to allow IO here, because only virtual FS are accessed.
141  base::ThreadRestrictions::ScopedAllowIO allow_io;
142  base::ReadFileToString(kProcUptime, &stats.uptime_);
143  base::ReadFileToString(kDiskStat, &stats.disk_);
144  return stats;
145}
146
147std::string BootTimesLoader::Stats::SerializeToString() const {
148  if (uptime_.empty() && disk_.empty())
149    return std::string();
150  base::DictionaryValue dictionary;
151  dictionary.SetString(kUptime, uptime_);
152  dictionary.SetString(kDisk, disk_);
153
154  std::string result;
155  if (!base::JSONWriter::Write(&dictionary, &result)) {
156    LOG(WARNING) << "BootTimesLoader::Stats::SerializeToString(): failed.";
157    return std::string();
158  }
159
160  return result;
161}
162
163// static
164BootTimesLoader::Stats BootTimesLoader::Stats::DeserializeFromString(
165    const std::string& source) {
166  if (source.empty())
167    return Stats();
168
169  scoped_ptr<base::Value> value(base::JSONReader::Read(source));
170  base::DictionaryValue* dictionary;
171  if (!value || !value->GetAsDictionary(&dictionary)) {
172    LOG(ERROR) << "BootTimesLoader::Stats::DeserializeFromString(): not a "
173                  "dictionary: '" << source << "'";
174    return Stats();
175  }
176
177  Stats result;
178  if (!dictionary->GetString(kUptime, &result.uptime_) ||
179      !dictionary->GetString(kDisk, &result.disk_)) {
180    LOG(ERROR)
181        << "BootTimesLoader::Stats::DeserializeFromString(): format error: '"
182        << source << "'";
183    return Stats();
184  }
185
186  return result;
187}
188
189bool BootTimesLoader::Stats::UptimeDouble(double* result) const {
190  std::string uptime = uptime_;
191  const size_t space_at = uptime.find_first_of(' ');
192  if (space_at == std::string::npos)
193    return false;
194
195  uptime.resize(space_at);
196
197  if (base::StringToDouble(uptime, result))
198    return true;
199
200  return false;
201}
202
203void BootTimesLoader::Stats::RecordStats(const std::string& name) const {
204  BrowserThread::PostBlockingPoolTask(
205      FROM_HERE,
206      base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
207                 base::Owned(new Stats(*this)),
208                 name));
209}
210
211void BootTimesLoader::Stats::RecordStatsWithCallback(
212    const std::string& name,
213    const base::Closure& callback) const {
214  BrowserThread::PostBlockingPoolTaskAndReply(
215      FROM_HERE,
216      base::Bind(&BootTimesLoader::Stats::RecordStatsImpl,
217                 base::Owned(new Stats(*this)),
218                 name),
219      callback);
220}
221
222void BootTimesLoader::Stats::RecordStatsImpl(
223    const base::FilePath::StringType& name) const {
224  DCHECK(content::BrowserThread::GetBlockingPool()->RunsTasksOnCurrentThread());
225
226  const base::FilePath log_path(kLogPath);
227  const base::FilePath uptime_output =
228      log_path.Append(base::FilePath(kUptimePrefix + name));
229  const base::FilePath disk_output =
230      log_path.Append(base::FilePath(kDiskPrefix + name));
231
232  // Append numbers to the files.
233  AppendFile(uptime_output, uptime_.data(), uptime_.size());
234  AppendFile(disk_output, disk_.data(), disk_.size());
235}
236
237BootTimesLoader::BootTimesLoader()
238    : backend_(new Backend()),
239      have_registered_(false),
240      login_done_(false),
241      restart_requested_(false) {
242  login_time_markers_.reserve(30);
243  logout_time_markers_.reserve(30);
244}
245
246BootTimesLoader::~BootTimesLoader() {
247}
248
249// static
250BootTimesLoader* BootTimesLoader::Get() {
251  return g_boot_times_loader.Pointer();
252}
253
254// static
255void BootTimesLoader::WriteTimes(
256    const std::string base_name,
257    const std::string uma_name,
258    const std::string uma_prefix,
259    std::vector<TimeMarker> login_times) {
260  const int kMinTimeMillis = 1;
261  const int kMaxTimeMillis = 30000;
262  const int kNumBuckets = 100;
263  const base::FilePath log_path(kLoginLogPath);
264
265  // Need to sort by time since the entries may have been pushed onto the
266  // vector (on the UI thread) in a different order from which they were
267  // created (potentially on other threads).
268  std::sort(login_times.begin(), login_times.end());
269
270  base::Time first = login_times.front().time();
271  base::Time last = login_times.back().time();
272  base::TimeDelta total = last - first;
273  base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
274      uma_name,
275      base::TimeDelta::FromMilliseconds(kMinTimeMillis),
276      base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
277      kNumBuckets,
278      base::HistogramBase::kUmaTargetedHistogramFlag);
279  total_hist->AddTime(total);
280  std::string output =
281      base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
282  base::Time prev = first;
283  for (unsigned int i = 0; i < login_times.size(); ++i) {
284    TimeMarker tm = login_times[i];
285    base::TimeDelta since_first = tm.time() - first;
286    base::TimeDelta since_prev = tm.time() - prev;
287    std::string name;
288
289    if (tm.send_to_uma()) {
290      name = uma_prefix + tm.name();
291      base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
292          name,
293          base::TimeDelta::FromMilliseconds(kMinTimeMillis),
294          base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
295          kNumBuckets,
296          base::HistogramBase::kUmaTargetedHistogramFlag);
297      prev_hist->AddTime(since_prev);
298    } else {
299      name = tm.name();
300    }
301    output +=
302        base::StringPrintf(
303            "\n%.2f +%.4f %s",
304            since_first.InSecondsF(),
305            since_prev.InSecondsF(),
306            name.data());
307    prev = tm.time();
308  }
309  output += '\n';
310
311  base::WriteFile(log_path.Append(base_name), output.data(), output.size());
312}
313
314void BootTimesLoader::LoginDone(bool is_user_new) {
315  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
316  if (login_done_)
317    return;
318
319  login_done_ = true;
320  AddLoginTimeMarker("LoginDone", false);
321  RecordCurrentStats(kChromeFirstRender);
322  if (have_registered_) {
323    registrar_.Remove(this,
324                      content::NOTIFICATION_LOAD_START,
325                      content::NotificationService::AllSources());
326    registrar_.Remove(this,
327                      content::NOTIFICATION_LOAD_STOP,
328                      content::NotificationService::AllSources());
329    registrar_.Remove(this,
330                      content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
331                      content::NotificationService::AllSources());
332    registrar_.Remove(
333        this,
334        content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
335        content::NotificationService::AllSources());
336  }
337  // Don't swamp the FILE thread right away.
338  BrowserThread::PostDelayedTask(
339      BrowserThread::FILE,
340      FROM_HERE,
341      base::Bind(&WriteTimes,
342                 kLoginTimes,
343                 (is_user_new ? kUmaLoginNewUser : kUmaLogin),
344                 kUmaLoginPrefix,
345                 login_time_markers_),
346      base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
347}
348
349void BootTimesLoader::WriteLogoutTimes() {
350  // Either we're on the browser thread, or (more likely) Chrome is in the
351  // process of shutting down and we're on the main thread but the message loop
352  // has already been terminated.
353  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
354         !BrowserThread::IsMessageLoopValid(BrowserThread::UI));
355
356  WriteTimes(kLogoutTimes,
357             (restart_requested_ ? kUmaRestart : kUmaLogout),
358             kUmaLogoutPrefix,
359             logout_time_markers_);
360}
361
362// static
363void BootTimesLoader::ClearLogoutStartedLastPreference() {
364  PrefService* local_state = g_browser_process->local_state();
365  local_state->ClearPref(prefs::kLogoutStartedLast);
366}
367
368void BootTimesLoader::OnChromeProcessStart() {
369  PrefService* local_state = g_browser_process->local_state();
370  const std::string logout_started_last_str =
371      local_state->GetString(prefs::kLogoutStartedLast);
372  if (logout_started_last_str.empty())
373    return;
374
375  // Note that kLogoutStartedLast is not cleared on format error to stay in
376  // logs in case of other fatal system errors.
377
378  const Stats logout_started_last_stats =
379      Stats::DeserializeFromString(logout_started_last_str);
380  if (logout_started_last_stats.uptime().empty())
381    return;
382
383  double logout_started_last;
384  double uptime;
385  if (!logout_started_last_stats.UptimeDouble(&logout_started_last) ||
386      !Stats::GetCurrentStats().UptimeDouble(&uptime)) {
387    return;
388  }
389
390  if (logout_started_last >= uptime) {
391    // Reboot happened.
392    ClearLogoutStartedLastPreference();
393    return;
394  }
395
396  // Write /tmp/uptime-logout-started as well.
397  const char kLogoutStarted[] = "logout-started";
398  logout_started_last_stats.RecordStatsWithCallback(
399      kLogoutStarted,
400      base::Bind(&BootTimesLoader::ClearLogoutStartedLastPreference));
401}
402
403void BootTimesLoader::OnLogoutStarted(PrefService* state) {
404  const std::string uptime = Stats::GetCurrentStats().SerializeToString();
405  if (!uptime.empty())
406    state->SetString(prefs::kLogoutStartedLast, uptime);
407}
408
409void BootTimesLoader::RecordCurrentStats(const std::string& name) {
410  Stats::GetCurrentStats().RecordStats(name);
411}
412
413void BootTimesLoader::SaveChromeMainStats() {
414  chrome_main_stats_ = Stats::GetCurrentStats();
415}
416
417void BootTimesLoader::RecordChromeMainStats() {
418  chrome_main_stats_.RecordStats(kChromeMain);
419}
420
421void BootTimesLoader::RecordLoginAttempted() {
422  DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
423  if (login_done_)
424    return;
425
426  login_time_markers_.clear();
427  AddLoginTimeMarker("LoginStarted", false);
428  if (!have_registered_) {
429    have_registered_ = true;
430    registrar_.Add(this, content::NOTIFICATION_LOAD_START,
431                   content::NotificationService::AllSources());
432    registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
433                   content::NotificationService::AllSources());
434    registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
435                   content::NotificationService::AllSources());
436    registrar_.Add(
437        this,
438        content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
439        content::NotificationService::AllSources());
440  }
441}
442
443void BootTimesLoader::AddLoginTimeMarker(
444    const std::string& marker_name, bool send_to_uma) {
445  AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
446}
447
448void BootTimesLoader::AddLogoutTimeMarker(
449    const std::string& marker_name, bool send_to_uma) {
450  AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
451}
452
453// static
454void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
455                                TimeMarker marker)
456{
457  // The marker vectors can only be safely manipulated on the main thread.
458  // If we're late in the process of shutting down (eg. as can be the case at
459  // logout), then we have to assume we're on the main thread already.
460  if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
461      !BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
462    vector->push_back(marker);
463  } else {
464    // Add the marker on the UI thread.
465    // Note that it's safe to use an unretained pointer to the vector because
466    // BootTimesLoader's lifetime exceeds that of the UI thread message loop.
467    BrowserThread::PostTask(
468        BrowserThread::UI, FROM_HERE,
469        base::Bind(&BootTimesLoader::AddMarker,
470                   base::Unretained(vector),
471                   marker));
472  }
473}
474
475void BootTimesLoader::RecordAuthenticationSuccess() {
476  AddLoginTimeMarker("Authenticate", true);
477  RecordCurrentStats(kLoginSuccess);
478}
479
480void BootTimesLoader::RecordAuthenticationFailure() {
481  // Do nothing for now.
482}
483
484void BootTimesLoader::Observe(
485    int type,
486    const content::NotificationSource& source,
487    const content::NotificationDetails& details) {
488  switch (type) {
489    case content::NOTIFICATION_LOAD_START: {
490      NavigationController* tab =
491          content::Source<NavigationController>(source).ptr();
492      RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
493      DCHECK(rwh);
494      AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
495      render_widget_hosts_loading_.insert(rwh);
496      break;
497    }
498    case content::NOTIFICATION_LOAD_STOP: {
499      NavigationController* tab =
500          content::Source<NavigationController>(source).ptr();
501      RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
502      if (render_widget_hosts_loading_.find(rwh) !=
503          render_widget_hosts_loading_.end()) {
504        AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
505      }
506      break;
507    }
508    case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
509      RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
510      if (render_widget_hosts_loading_.find(rwh) !=
511          render_widget_hosts_loading_.end()) {
512        AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
513        LoginDone(user_manager::UserManager::Get()->IsCurrentUserNew());
514      }
515      break;
516    }
517    case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
518      WebContents* web_contents = content::Source<WebContents>(source).ptr();
519      RenderWidgetHost* render_widget_host =
520          GetRenderWidgetHost(&web_contents->GetController());
521      render_widget_hosts_loading_.erase(render_widget_host);
522      break;
523    }
524    default:
525      break;
526  }
527}
528
529}  // namespace chromeos
530