// Copyright (c) 2012 The Chromium Authors. All rights reserved.
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.
#include "chrome/browser/chromeos/boot_times_loader.h"
#include <vector>
#include "base/bind.h"
#include "base/command_line.h"
#include "base/file_util.h"
#include "base/files/file_path.h"
#include "base/lazy_instance.h"
#include "base/location.h"
#include "base/message_loop/message_loop.h"
#include "base/message_loop/message_loop_proxy.h"
#include "base/metrics/histogram.h"
#include "base/strings/string_number_conversions.h"
#include "base/strings/string_util.h"
#include "base/strings/stringprintf.h"
#include "base/threading/thread.h"
#include "base/threading/thread_restrictions.h"
#include "base/time/time.h"
#include "chrome/browser/browser_process.h"
#include "chrome/browser/chrome_notification_types.h"
#include "chrome/browser/chromeos/login/authentication_notification_details.h"
#include "chrome/browser/ui/browser.h"
#include "chrome/browser/ui/browser_iterator.h"
#include "chrome/browser/ui/tabs/tab_strip_model.h"
#include "chrome/common/chrome_switches.h"
#include "content/public/browser/browser_thread.h"
#include "content/public/browser/navigation_controller.h"
#include "content/public/browser/notification_service.h"
#include "content/public/browser/render_widget_host_view.h"
#include "content/public/browser/web_contents.h"
using content::BrowserThread;
using content::NavigationController;
using content::RenderWidgetHost;
using content::RenderWidgetHostView;
using content::WebContents;
namespace {
RenderWidgetHost* GetRenderWidgetHost(NavigationController* tab) {
WebContents* web_contents = tab->GetWebContents();
if (web_contents) {
RenderWidgetHostView* render_widget_host_view =
web_contents->GetRenderWidgetHostView();
if (render_widget_host_view)
return render_widget_host_view->GetRenderWidgetHost();
}
return NULL;
}
const std::string GetTabUrl(RenderWidgetHost* rwh) {
RenderWidgetHostView* rwhv = rwh->GetView();
for (chrome::BrowserIterator it; !it.done(); it.Next()) {
Browser* browser = *it;
for (int i = 0, tab_count = browser->tab_strip_model()->count();
i < tab_count;
++i) {
WebContents* tab = browser->tab_strip_model()->GetWebContentsAt(i);
if (tab->GetRenderWidgetHostView() == rwhv) {
return tab->GetLastCommittedURL().spec();
}
}
}
return std::string();
}
} // namespace
namespace chromeos {
#define FPL(value) FILE_PATH_LITERAL(value)
// Dir uptime & disk logs are located in.
static const base::FilePath::CharType kLogPath[] = FPL("/tmp");
// Dir log{in,out} logs are located in.
static const base::FilePath::CharType kLoginLogPath[] =
FPL("/home/chronos/user");
// Prefix for the time measurement files.
static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-");
// Prefix for the disk usage files.
static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-");
// Name of the time that Chrome's main() is called.
static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main");
// Delay in milliseconds before writing the login times to disk.
static const int64 kLoginTimeWriteDelayMs = 3000;
// Names of login stats files.
static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success");
static const base::FilePath::CharType kChromeFirstRender[] =
FPL("chrome-first-render");
// Names of login UMA values.
static const char kUmaLogin[] = "BootTime.Login";
static const char kUmaLoginPrefix[] = "BootTime.";
static const char kUmaLogout[] = "ShutdownTime.Logout";
static const char kUmaLogoutPrefix[] = "ShutdownTime.";
// Name of file collecting login times.
static const base::FilePath::CharType kLoginTimes[] = FPL("login-times");
// Name of file collecting logout times.
static const char kLogoutTimes[] = "logout-times";
static base::LazyInstance<BootTimesLoader> g_boot_times_loader =
LAZY_INSTANCE_INITIALIZER;
BootTimesLoader::BootTimesLoader()
: backend_(new Backend()),
have_registered_(false) {
login_time_markers_.reserve(30);
logout_time_markers_.reserve(30);
}
BootTimesLoader::~BootTimesLoader() {}
// static
BootTimesLoader* BootTimesLoader::Get() {
return g_boot_times_loader.Pointer();
}
// Appends the given buffer into the file. Returns the number of bytes
// written, or -1 on error.
// TODO(satorux): Move this to file_util.
static int AppendFile(const base::FilePath& file_path,
const char* data,
int size) {
FILE* file = base::OpenFile(file_path, "a");
if (!file) {
return -1;
}
const int num_bytes_written = fwrite(data, 1, size, file);
base::CloseFile(file);
return num_bytes_written;
}
static void RecordStatsDelayed(const base::FilePath::StringType& name,
const std::string& uptime,
const std::string& disk) {
const base::FilePath log_path(kLogPath);
const base::FilePath uptime_output =
log_path.Append(base::FilePath(kUptimePrefix + name));
const base::FilePath disk_output =
log_path.Append(base::FilePath(kDiskPrefix + name));
// Append numbers to the files.
AppendFile(uptime_output, uptime.data(), uptime.size());
AppendFile(disk_output, disk.data(), disk.size());
}
// static
void BootTimesLoader::WriteTimes(
const std::string base_name,
const std::string uma_name,
const std::string uma_prefix,
std::vector<TimeMarker> login_times) {
const int kMinTimeMillis = 1;
const int kMaxTimeMillis = 30000;
const int kNumBuckets = 100;
const base::FilePath log_path(kLoginLogPath);
// Need to sort by time since the entries may have been pushed onto the
// vector (on the UI thread) in a different order from which they were
// created (potentially on other threads).
std::sort(login_times.begin(), login_times.end());
base::Time first = login_times.front().time();
base::Time last = login_times.back().time();
base::TimeDelta total = last - first;
base::HistogramBase* total_hist = base::Histogram::FactoryTimeGet(
uma_name,
base::TimeDelta::FromMilliseconds(kMinTimeMillis),
base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
kNumBuckets,
base::HistogramBase::kUmaTargetedHistogramFlag);
total_hist->AddTime(total);
std::string output =
base::StringPrintf("%s: %.2f", uma_name.c_str(), total.InSecondsF());
base::Time prev = first;
for (unsigned int i = 0; i < login_times.size(); ++i) {
TimeMarker tm = login_times[i];
base::TimeDelta since_first = tm.time() - first;
base::TimeDelta since_prev = tm.time() - prev;
std::string name;
if (tm.send_to_uma()) {
name = uma_prefix + tm.name();
base::HistogramBase* prev_hist = base::Histogram::FactoryTimeGet(
name,
base::TimeDelta::FromMilliseconds(kMinTimeMillis),
base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
kNumBuckets,
base::HistogramBase::kUmaTargetedHistogramFlag);
prev_hist->AddTime(since_prev);
} else {
name = tm.name();
}
output +=
base::StringPrintf(
"\n%.2f +%.4f %s",
since_first.InSecondsF(),
since_prev.InSecondsF(),
name.data());
prev = tm.time();
}
output += '\n';
file_util::WriteFile(
log_path.Append(base_name), output.data(), output.size());
}
void BootTimesLoader::LoginDone() {
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
AddLoginTimeMarker("LoginDone", false);
RecordCurrentStats(kChromeFirstRender);
registrar_.Remove(this, content::NOTIFICATION_LOAD_START,
content::NotificationService::AllSources());
registrar_.Remove(this, content::NOTIFICATION_LOAD_STOP,
content::NotificationService::AllSources());
registrar_.Remove(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
content::NotificationService::AllSources());
registrar_.Remove(
this,
content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
content::NotificationService::AllSources());
// Don't swamp the FILE thread right away.
BrowserThread::PostDelayedTask(
BrowserThread::FILE, FROM_HERE,
base::Bind(&WriteTimes, kLoginTimes, kUmaLogin, kUmaLoginPrefix,
login_time_markers_),
base::TimeDelta::FromMilliseconds(kLoginTimeWriteDelayMs));
}
void BootTimesLoader::WriteLogoutTimes() {
// Either we're on the browser thread, or (more likely) Chrome is in the
// process of shutting down and we're on the main thread but the message loop
// has already been terminated.
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI) ||
!BrowserThread::IsMessageLoopValid(BrowserThread::UI));
WriteTimes(kLogoutTimes,
kUmaLogout,
kUmaLogoutPrefix,
logout_time_markers_);
}
void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
BrowserThread::PostTask(
BrowserThread::FILE, FROM_HERE,
base::Bind(&RecordStatsDelayed, name, stats.uptime, stats.disk));
}
BootTimesLoader::Stats BootTimesLoader::GetCurrentStats() {
const base::FilePath kProcUptime(FPL("/proc/uptime"));
const base::FilePath kDiskStat(FPL("/sys/block/sda/stat"));
Stats stats;
base::ThreadRestrictions::ScopedAllowIO allow_io;
base::ReadFileToString(kProcUptime, &stats.uptime);
base::ReadFileToString(kDiskStat, &stats.disk);
return stats;
}
void BootTimesLoader::RecordCurrentStats(const std::string& name) {
RecordStats(name, GetCurrentStats());
}
void BootTimesLoader::SaveChromeMainStats() {
chrome_main_stats_ = GetCurrentStats();
}
void BootTimesLoader::RecordChromeMainStats() {
RecordStats(kChromeMain, chrome_main_stats_);
}
void BootTimesLoader::RecordLoginAttempted() {
DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
login_time_markers_.clear();
AddLoginTimeMarker("LoginStarted", false);
if (!have_registered_) {
have_registered_ = true;
registrar_.Add(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
content::NotificationService::AllSources());
registrar_.Add(this, content::NOTIFICATION_LOAD_START,
content::NotificationService::AllSources());
registrar_.Add(this, content::NOTIFICATION_LOAD_STOP,
content::NotificationService::AllSources());
registrar_.Add(this, content::NOTIFICATION_WEB_CONTENTS_DESTROYED,
content::NotificationService::AllSources());
registrar_.Add(
this,
content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE,
content::NotificationService::AllSources());
}
}
void BootTimesLoader::AddLoginTimeMarker(
const std::string& marker_name, bool send_to_uma) {
AddMarker(&login_time_markers_, TimeMarker(marker_name, send_to_uma));
}
void BootTimesLoader::AddLogoutTimeMarker(
const std::string& marker_name, bool send_to_uma) {
AddMarker(&logout_time_markers_, TimeMarker(marker_name, send_to_uma));
}
// static
void BootTimesLoader::AddMarker(std::vector<TimeMarker>* vector,
TimeMarker marker)
{
// The marker vectors can only be safely manipulated on the main thread.
// If we're late in the process of shutting down (eg. as can be the case at
// logout), then we have to assume we're on the main thread already.
if (BrowserThread::CurrentlyOn(BrowserThread::UI) ||
!BrowserThread::IsMessageLoopValid(BrowserThread::UI)) {
vector->push_back(marker);
} else {
// Add the marker on the UI thread.
// Note that it's safe to use an unretained pointer to the vector because
// BootTimesLoader's lifetime exceeds that of the UI thread message loop.
BrowserThread::PostTask(
BrowserThread::UI, FROM_HERE,
base::Bind(&BootTimesLoader::AddMarker,
base::Unretained(vector),
marker));
}
}
void BootTimesLoader::Observe(
int type,
const content::NotificationSource& source,
const content::NotificationDetails& details) {
switch (type) {
case chrome::NOTIFICATION_LOGIN_AUTHENTICATION: {
content::Details<AuthenticationNotificationDetails> auth_details(details);
if (auth_details->success()) {
AddLoginTimeMarker("Authenticate", true);
RecordCurrentStats(kLoginSuccess);
registrar_.Remove(this, chrome::NOTIFICATION_LOGIN_AUTHENTICATION,
content::NotificationService::AllSources());
}
break;
}
case content::NOTIFICATION_LOAD_START: {
NavigationController* tab =
content::Source<NavigationController>(source).ptr();
RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
DCHECK(rwh);
AddLoginTimeMarker("TabLoad-Start: " + GetTabUrl(rwh), false);
render_widget_hosts_loading_.insert(rwh);
break;
}
case content::NOTIFICATION_LOAD_STOP: {
NavigationController* tab =
content::Source<NavigationController>(source).ptr();
RenderWidgetHost* rwh = GetRenderWidgetHost(tab);
if (render_widget_hosts_loading_.find(rwh) !=
render_widget_hosts_loading_.end()) {
AddLoginTimeMarker("TabLoad-End: " + GetTabUrl(rwh), false);
}
break;
}
case content::NOTIFICATION_RENDER_WIDGET_HOST_DID_UPDATE_BACKING_STORE: {
RenderWidgetHost* rwh = content::Source<RenderWidgetHost>(source).ptr();
if (render_widget_hosts_loading_.find(rwh) !=
render_widget_hosts_loading_.end()) {
AddLoginTimeMarker("TabPaint: " + GetTabUrl(rwh), false);
LoginDone();
}
break;
}
case content::NOTIFICATION_WEB_CONTENTS_DESTROYED: {
WebContents* web_contents = content::Source<WebContents>(source).ptr();
RenderWidgetHost* render_widget_host =
GetRenderWidgetHost(&web_contents->GetController());
render_widget_hosts_loading_.erase(render_widget_host);
break;
}
default:
break;
}
}
} // namespace chromeos