Record logout time stats for Chrome OS.

Record lougout time stats and dump it to /tmp/logout-times-sent.
ShutdownTime.Logout, ShutdownTime.UIMessageLoopEnded, and
ShutdownTime.BrowserDeleted will be sent to UMA, as well.

% cat /tmp/logout-times-sent
ShutdownTime.Logout: 0.39
0.00 +0.00 LogoutStarted
0.00 +0.00 ShutdownDetected
0.02 +0.02 StartedClosingWindows
0.27 +0.25 UIMessageLoopEnded
0.27 +0.00 BrowserShutdownStarted
0.39 +0.12 BrowserDeleted
0.39 +0.00 BrowserMainEnded

Along the way, change BootTimesLoader to append data to existing
/tmp/uptime-* files just like /sbin/bootstat does, so we can collect
numbers from 2nd login as well.

BUG=chromium-os:6847
TEST=confirmed that /tmp/login-times-sent and /tmp/logout-times-sent are written properly.

Review URL: http://codereview.chromium.org/4973002

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@66923 0039d316-1c4b-4281-b951-d872f2087c98

7 files changed, 113 insertions, 13 deletions

diff --git a/chrome/browser/browser_main.cc b/chrome/browser/browser_main.cc
index a92805e..e7afaff 100644
--- a/chrome/browser/browser_main.cc
+++ b/chrome/browser/browser_main.cc
@@ -510,6 +510,10 @@ void RunUIMessageLoop(BrowserProcess* browser_process) {
 #elif defined(OS_POSIX)
   MessageLoopForUI::current()->Run();
 #endif
+#if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("UIMessageLoopEnded",
+                                                        true);
+#endif
 
   TRACE_EVENT_END("BrowserMain:MESSAGE_LOOP", 0, "");
 }
@@ -1671,6 +1675,13 @@ int BrowserMain(const MainFunctionParams& parameters) {
   ignore_result(browser_process.release());
   browser_shutdown::Shutdown();
 
+#if defined(OS_CHROMEOS)
+  // To be precise, logout (browser shutdown) is not yet done, but the
+  // remaining work is negligible, hence we say LogoutDone here.
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("LogoutDone",
+                                                        false);
+  chromeos::BootTimesLoader::Get()->WriteLogoutTimes();
+#endif
   TRACE_EVENT_END("BrowserMain", 0, 0);
   return result_code;
 }
diff --git a/chrome/browser/browser_main_posix.cc b/chrome/browser/browser_main_posix.cc
index 9736c66..4659a34 100644
--- a/chrome/browser/browser_main_posix.cc
+++ b/chrome/browser/browser_main_posix.cc
@@ -16,6 +16,10 @@
 #include "chrome/browser/browser_thread.h"
 #include "chrome/common/chrome_switches.h"
 
+#if defined(OS_CHROMEOS)
+#include "chrome/browser/chromeos/boot_times_loader.h"
+#endif
+
 namespace {
 
 // See comment in |PreEarlyInitialization()|, where sigaction is called.
@@ -109,6 +113,10 @@ void ShutdownDetector::ThreadMain() {
   } while (bytes_read < sizeof(signal));
 
   VLOG(1) << "Handling shutdown for signal " << signal << ".";
+#if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("ShutdownDetected",
+                                                        false);
+#endif
 
   if (!BrowserThread::PostTask(
       BrowserThread::UI, FROM_HERE,
diff --git a/chrome/browser/browser_shutdown.cc b/chrome/browser/browser_shutdown.cc
index 8f1fb80..e136ef8 100644
--- a/chrome/browser/browser_shutdown.cc
+++ b/chrome/browser/browser_shutdown.cc
@@ -43,6 +43,10 @@
 #include "chrome/browser/rlz/rlz.h"
 #endif
 
+#if defined(OS_CHROMEOS)
+#include "chrome/browser/chromeos/boot_times_loader.h"
+#endif
+
 using base::Time;
 using base::TimeDelta;
 
@@ -101,6 +105,10 @@ FilePath GetShutdownMsPath() {
 }
 
 void Shutdown() {
+#if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker(
+      "BrowserShutdownStarted", false);
+#endif
   // During shutdown we will end up some blocking operations.  But the
   // work needs to get done and we're going to wait for them no matter
   // what thread they're on, so don't worry about it slowing down
@@ -162,6 +170,10 @@ void Shutdown() {
   // before calling UninstallJankometer().
   delete g_browser_process;
   g_browser_process = NULL;
+#if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("BrowserDeleted",
+                                                        true);
+#endif
 
   // Uninstall Jank-O-Meter here after the IO thread is no longer running.
   UninstallJankometer();
diff --git a/chrome/browser/chromeos/boot_times_loader.cc b/chrome/browser/chromeos/boot_times_loader.cc
index 5fc7414..2fe76dd 100644
--- a/chrome/browser/chromeos/boot_times_loader.cc
+++ b/chrome/browser/chromeos/boot_times_loader.cc
@@ -48,14 +48,21 @@ static const char kChromeFirstRender[] = "chrome-first-render";
 // Names of login UMA values.
 static const char kUmaAuthenticate[] = "BootTime.Authenticate";
 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 char kLoginTimes[] = "login-times-sent";
 
+// Name of file collecting logout times.
+static const char kLogoutTimes[] = "logout-times-sent";
+
 BootTimesLoader::BootTimesLoader()
     : backend_(new Backend()),
       have_registered_(false) {
   login_time_markers_.reserve(30);
+  logout_time_markers_.reserve(30);
 }
 
 // static
@@ -202,6 +209,21 @@ void BootTimesLoader::Backend::GetBootTimes(
       GetBootTimesCallback::TupleType(request->handle(), boot_times));
 }
 
+// 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 FilePath& file_path,
+                      const char* data,
+                      int size) {
+  FILE* file = file_util::OpenFile(file_path, "a");
+  if (!file) {
+    return -1;
+  }
+  const int num_bytes_written = fwrite(data, 1, size, file);
+  file_util::CloseFile(file);
+  return num_bytes_written;
+}
+
 static void RecordStatsDelayed(
     const std::string& name,
     const std::string& uptime,
@@ -212,34 +234,34 @@ static void RecordStatsDelayed(
       log_path.Append(FilePath(kUptimePrefix + name));
   const FilePath disk_output = log_path.Append(FilePath(kDiskPrefix + name));
 
-  // Write out the files, ensuring that they don't exist already.
-  if (!file_util::PathExists(uptime_output))
-    file_util::WriteFile(uptime_output, uptime.data(), uptime.size());
-  if (!file_util::PathExists(disk_output))
-    file_util::WriteFile(disk_output, disk.data(), disk.size());
+  // Append numbers to the files.
+  AppendFile(uptime_output, uptime.data(), uptime.size());
+  AppendFile(disk_output, disk.data(), disk.size());
 }
 
 // static
-void BootTimesLoader::WriteLoginTimes(
+void BootTimesLoader::WriteTimes(
+    const std::string base_name,
+    const std::string uma_name,
+    const std::string uma_prefix,
     const std::vector<TimeMarker> login_times) {
   const int kMinTimeMillis = 1;
   const int kMaxTimeMillis = 30000;
   const int kNumBuckets = 100;
-  const char kUmaPrefix[] = "BootTime.";
   const FilePath log_path(kLogPath);
 
   base::Time first = login_times.front().time();
   base::Time last = login_times.back().time();
   base::TimeDelta total = last - first;
   scoped_refptr<base::Histogram>total_hist = base::Histogram::FactoryTimeGet(
-      kUmaLogin,
+      uma_name,
       base::TimeDelta::FromMilliseconds(kMinTimeMillis),
       base::TimeDelta::FromMilliseconds(kMaxTimeMillis),
       kNumBuckets,
       base::Histogram::kUmaTargetedHistogramFlag);
   total_hist->AddTime(total);
   std::string output =
-      base::StringPrintf("%s: %.2f", kUmaLogin, total.InSecondsF());
+      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];
@@ -248,7 +270,7 @@ void BootTimesLoader::WriteLoginTimes(
     std::string name;
 
     if (tm.send_to_uma()) {
-      name = kUmaPrefix + tm.name();
+      name = uma_prefix + tm.name();
       scoped_refptr<base::Histogram>prev_hist = base::Histogram::FactoryTimeGet(
           name,
           base::TimeDelta::FromMilliseconds(kMinTimeMillis),
@@ -268,7 +290,14 @@ void BootTimesLoader::WriteLoginTimes(
     prev = tm.time();
   }
   file_util::WriteFile(
-      log_path.Append(kLoginTimes), output.data(), output.size());
+      log_path.Append(base_name), output.data(), output.size());
+}
+
+void BootTimesLoader::WriteLogoutTimes() {
+  WriteTimes(kLogoutTimes,
+             kUmaLogout,
+             kUmaLogoutPrefix,
+             logout_time_markers_);
 }
 
 void BootTimesLoader::RecordStats(const std::string& name, const Stats& stats) {
@@ -317,6 +346,11 @@ void BootTimesLoader::AddLoginTimeMarker(
   login_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
 }
 
+void BootTimesLoader::AddLogoutTimeMarker(
+    const std::string& marker_name, bool send_to_uma) {
+  logout_time_markers_.push_back(TimeMarker(marker_name, send_to_uma));
+}
+
 void BootTimesLoader::Observe(
     NotificationType type,
     const NotificationSource& source,
@@ -343,7 +377,13 @@ void BootTimesLoader::Observe(
       // Don't swamp the FILE thread right away.
       BrowserThread::PostDelayedTask(
           BrowserThread::FILE, FROM_HERE,
-          NewRunnableFunction(WriteLoginTimes, login_time_markers_),
+          // This doesn't compile without std::string(...), as
+          // NewRunnableFunction doesn't accept arrays.
+          NewRunnableFunction(WriteTimes,
+                              std::string(kLoginTimes),
+                              std::string(kUmaLogin),
+                              std::string(kUmaLoginPrefix),
+                              login_time_markers_),
           kLoginTimeWriteDelayMs);
       have_registered_ = false;
     } else {
diff --git a/chrome/browser/chromeos/boot_times_loader.h b/chrome/browser/chromeos/boot_times_loader.h
index d9f3010..d34f4d5 100644
--- a/chrome/browser/chromeos/boot_times_loader.h
+++ b/chrome/browser/chromeos/boot_times_loader.h
@@ -75,6 +75,12 @@ class BootTimesLoader
   // the identifier BootTime.|marker_name|.
   void AddLoginTimeMarker(const std::string& marker_name, bool send_to_uma);
 
+  // Add a time marker for logout. A timeline will be dumped to
+  // /tmp/logout-times-sent after logout is done. If |send_to_uma| is true
+  // the time between this marker and the last will be sent to UMA with
+  // the identifier ShutdownTime.|marker_name|.
+  void AddLogoutTimeMarker(const std::string& marker_name, bool send_to_uma);
+
   // Records current uptime and disk usage for metrics use.
   // Posts task to file thread.
   // name will be used as part of file names in /tmp.
@@ -98,6 +104,11 @@ class BootTimesLoader
                        const NotificationSource& source,
                        const NotificationDetails& details);
 
+  // Writes the logout times to a /tmp/logout-times-sent. Unlike login
+  // times, we manually call this function for logout times, as we cannot
+  // rely on notification service to tell when the logout is done.
+  void WriteLogoutTimes();
+
  private:
   // BootTimesLoader calls into the Backend on the file thread to load
   // the boot times.
@@ -141,7 +152,10 @@ class BootTimesLoader
   static void RecordStats(
       const std::string& name, const Stats& stats);
   static Stats GetCurrentStats();
-  static void WriteLoginTimes(const std::vector<TimeMarker> login_times);
+  static void WriteTimes(const std::string base_name,
+                         const std::string uma_name,
+                         const std::string uma_prefix,
+                         const std::vector<TimeMarker> login_times);
 
   // Used to hold the stats at main().
   Stats chrome_main_stats_;
@@ -153,6 +167,7 @@ class BootTimesLoader
   bool have_registered_;
 
   std::vector<TimeMarker> login_time_markers_;
+  std::vector<TimeMarker> logout_time_markers_;
 
   DISALLOW_COPY_AND_ASSIGN(BootTimesLoader);
 };
diff --git a/chrome/browser/ui/browser.cc b/chrome/browser/ui/browser.cc
index 1415035..cb6dd29 100644
--- a/chrome/browser/ui/browser.cc
+++ b/chrome/browser/ui/browser.cc
@@ -130,6 +130,7 @@
 
 #if defined(OS_CHROMEOS)
 #include <gdk/gdk.h>  // For GdkScreen
+#include "chrome/browser/chromeos/boot_times_loader.h"
 #include "chrome/browser/chromeos/cros/cros_library.h"
 #include "chrome/browser/chromeos/cros/login_library.h"
 #include "chrome/browser/chromeos/options/language_config_view.h"
@@ -1462,6 +1463,11 @@ void Browser::Search() {
 void Browser::Exit() {
   UserMetrics::RecordAction(UserMetricsAction("Exit"), profile_);
 #if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker("LogoutStarted", false);
+  // Write /tmp/uptime-logout-started as well.
+  const char kLogoutStarted[] = "logout-started";
+  chromeos::BootTimesLoader::Get()->RecordCurrentStats(kLogoutStarted);
+
   if (chromeos::CrosLibrary::Get()->EnsureLoaded()) {
     chromeos::CrosLibrary::Get()->GetLoginLibrary()->StopSession("");
     return;
diff --git a/chrome/browser/ui/browser_list.cc b/chrome/browser/ui/browser_list.cc
index b346244..f5965fb 100644
--- a/chrome/browser/ui/browser_list.cc
+++ b/chrome/browser/ui/browser_list.cc
@@ -22,6 +22,10 @@
 #include "chrome/browser/chrome_browser_application_mac.h"
 #endif
 
+#if defined(OS_CHROMEOS)
+#include "chrome/browser/chromeos/boot_times_loader.h"
+#endif
+
 namespace {
 
 // This object is instantiated when the first Browser object is added to the
@@ -260,6 +264,10 @@ void BrowserList::CloseAllBrowsers() {
     AllBrowsersClosedAndAppExiting();
     return;
   }
+#if defined(OS_CHROMEOS)
+  chromeos::BootTimesLoader::Get()->AddLogoutTimeMarker(
+      "StartedClosingWindows", false);
+#endif
   for (BrowserList::const_iterator i = BrowserList::begin();
        i != BrowserList::end();) {
     if (use_post) {