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 37 using content::BrowserThread; 38 using content::NavigationController; 39 using content::RenderWidgetHost; 40 using content::RenderWidgetHostView; 41 using content::WebContents; 42 43 namespace { 44 45 RenderWidgetHost* 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 56 const 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 74 namespace chromeos { 75 76 #define FPL(value) FILE_PATH_LITERAL(value) 77 78 // Dir uptime & disk logs are located in. 79 static const base::FilePath::CharType kLogPath[] = FPL("/tmp"); 80 // Dir log{in,out} logs are located in. 81 static const base::FilePath::CharType kLoginLogPath[] = 82 FPL("/home/chronos/user"); 83 // Prefix for the time measurement files. 84 static const base::FilePath::CharType kUptimePrefix[] = FPL("uptime-"); 85 // Prefix for the disk usage files. 86 static const base::FilePath::CharType kDiskPrefix[] = FPL("disk-"); 87 // Name of the time that Chrome's main() is called. 88 static const base::FilePath::CharType kChromeMain[] = FPL("chrome-main"); 89 // Delay in milliseconds between file read attempts. 90 static const int64 kReadAttemptDelayMs = 250; 91 // Delay in milliseconds before writing the login times to disk. 92 static const int64 kLoginTimeWriteDelayMs = 3000; 93 94 // Names of login stats files. 95 static const base::FilePath::CharType kLoginSuccess[] = FPL("login-success"); 96 static const base::FilePath::CharType kChromeFirstRender[] = 97 FPL("chrome-first-render"); 98 99 // Names of login UMA values. 100 static const char kUmaLogin[] = "BootTime.Login"; 101 static const char kUmaLoginPrefix[] = "BootTime."; 102 static const char kUmaLogout[] = "ShutdownTime.Logout"; 103 static const char kUmaLogoutPrefix[] = "ShutdownTime."; 104 105 // Name of file collecting login times. 106 static const base::FilePath::CharType kLoginTimes[] = FPL("login-times"); 107 108 // Name of file collecting logout times. 109 static const char kLogoutTimes[] = "logout-times"; 110 111 static base::LazyInstance<BootTimesLoader> g_boot_times_loader = 112 LAZY_INSTANCE_INITIALIZER; 113 114 BootTimesLoader::BootTimesLoader() 115 : backend_(new Backend()), 116 have_registered_(false) { 117 login_time_markers_.reserve(30); 118 logout_time_markers_.reserve(30); 119 } 120 121 BootTimesLoader::~BootTimesLoader() {} 122 123 // static 124 BootTimesLoader* 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. 131 static 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 143 static 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 158 void 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 218 void 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 240 void 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 253 void 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 259 BootTimesLoader::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 269 void BootTimesLoader::RecordCurrentStats(const std::string& name) { 270 RecordStats(name, GetCurrentStats()); 271 } 272 273 void BootTimesLoader::SaveChromeMainStats() { 274 chrome_main_stats_ = GetCurrentStats(); 275 } 276 277 void BootTimesLoader::RecordChromeMainStats() { 278 RecordStats(kChromeMain, chrome_main_stats_); 279 } 280 281 void 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 302 void 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 307 void 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 313 void 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 334 void 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