| // 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/auth/authentication_notification_details.h" |
| #include "chrome/browser/chromeos/login/users/user_manager.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 kUmaLoginNewUser[] = "BootTime.LoginNewUser"; |
| static const char kUmaLoginPrefix[] = "BootTime."; |
| static const char kUmaLogout[] = "ShutdownTime.Logout"; |
| static const char kUmaLogoutPrefix[] = "ShutdownTime."; |
| static const char kUmaRestart[] = "ShutdownTime.Restart"; |
| |
| // 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_done_(false), |
| restart_requested_(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'; |
| |
| base::WriteFile(log_path.Append(base_name), output.data(), output.size()); |
| } |
| |
| void BootTimesLoader::LoginDone(bool is_user_new) { |
| DCHECK(BrowserThread::CurrentlyOn(BrowserThread::UI)); |
| if (login_done_) |
| return; |
| |
| login_done_ = true; |
| AddLoginTimeMarker("LoginDone", false); |
| RecordCurrentStats(kChromeFirstRender); |
| if (have_registered_) { |
| 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, |
| (is_user_new ? kUmaLoginNewUser : 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, |
| (restart_requested_ ? kUmaRestart : 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)); |
| if (login_done_) |
| return; |
| |
| 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(UserManager::Get()->IsCurrentUserNew()); |
| } |
| 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 |