cros: Log per-process memory use on low memory events

We're seeing a lot of tab reloads caused by the tab discarder, but we're not sure yet where the memory is going.  Dump the per-process private and shared memory use (same as the Task Manager columns) for Chrome processes when we hit low memory, such that we can see it in the system logs when users send us a feedback report.  This adds tens of milliseconds to the delay between the low memory signal and the tab discard starting, but that isn't significant as we allow 750 ms for the discard to happen and the memory stats are collected asynchronously off of the UI thread.

Also refactor when we log UMA memory statistics - we used to do it every time we collected memory details, but with this change we need to be able to collect the details and skip additional UMA stats.

BUG=124038
TEST=browser_tests OomPriorityManagerTest, manual inspection of logs after triggering tab discard with about:discards


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

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

13 files changed, 120 insertions, 59 deletions

diff --git a/chrome/browser/automation/testing_automation_provider.cc b/chrome/browser/automation/testing_automation_provider.cc
index 1e24d4d..336d218 100644
--- a/chrome/browser/automation/testing_automation_provider.cc
+++ b/chrome/browser/automation/testing_automation_provider.cc
@@ -2955,7 +2955,8 @@ void TestingAutomationProvider::GetProcessInfo(
     IPC::Message* reply_message) {
   scoped_refptr<ProcessInfoObserver>
       proc_observer(new ProcessInfoObserver(this, reply_message));
-  proc_observer->StartFetch();
+  // TODO(jamescook): Maybe this shouldn't update UMA stats?
+  proc_observer->StartFetch(MemoryDetails::UPDATE_USER_METRICS);
 }
 
 // Sample json input: { "command": "GetNavigationInfo" }
diff --git a/chrome/browser/chromeos/system/syslogs_provider.cc b/chrome/browser/chromeos/system/syslogs_provider.cc
index 71836fe..418ae18 100644
--- a/chrome/browser/chromeos/system/syslogs_provider.cc
+++ b/chrome/browser/chromeos/system/syslogs_provider.cc
@@ -1,11 +1,9 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// 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/system/syslogs_provider.h"
 
-#include <functional>
-#include <set>
 
 #include "base/bind.h"
 #include "base/bind_helpers.h"
@@ -16,8 +14,6 @@
 #include "base/memory/scoped_ptr.h"
 #include "base/memory/singleton.h"
 #include "base/string_util.h"
-#include "base/stringprintf.h"
-#include "base/utf_string_conversions.h"
 #include "chrome/browser/memory_details.h"
 #include "chrome/common/chrome_switches.h"
 #include "content/public/browser/browser_thread.h"
@@ -252,41 +248,7 @@ class SyslogsMemoryHandler : public MemoryDetails {
   }
 
   virtual void OnDetailsAvailable() OVERRIDE {
-    const ProcessData& chrome = processes()[0];  // Chrome is the first entry.
-    // Process info, sorted by memory used (highest to lowest).
-    typedef std::pair<int, std::string> ProcInfo;
-    typedef std::set<ProcInfo, std::greater<ProcInfo> > ProcInfoSet;
-    ProcInfoSet process_info;
-    for (ProcessMemoryInformationList::const_iterator iter1 =
-             chrome.processes.begin();
-         iter1 != chrome.processes.end(); ++iter1) {
-      std::string process_string(
-          ProcessMemoryInformation::GetFullTypeNameInEnglish(
-              iter1->type, iter1->renderer_type));
-      if (!iter1->titles.empty()) {
-        std::string titles(" [");
-        for (std::vector<string16>::const_iterator iter2 =
-                 iter1->titles.begin();
-             iter2 != iter1->titles.end(); ++iter2) {
-          if (iter2 != iter1->titles.begin())
-            titles += "|";
-          titles += UTF16ToUTF8(*iter2);
-        }
-        titles += "]";
-        process_string += titles;
-      }
-      // Use private working set for memory used calculation.
-      int ws_mbytes = static_cast<int>(iter1->working_set.priv) / 1024;
-      process_info.insert(std::make_pair(ws_mbytes, process_string));
-    }
-    // Add one line for each reverse-sorted entry.
-    std::string mem_string;
-    for (ProcInfoSet::iterator iter = process_info.begin();
-         iter != process_info.end(); ++iter) {
-      mem_string +=
-          iter->second + base::StringPrintf(": %d MB", iter->first) + "\n";
-    }
-    (*logs_)["mem_usage"] = mem_string;
+    (*logs_)["mem_usage"] = ToLogString();
     // This will call the callback on the calling thread.
     request_->ForwardResult(logs_, zip_content_);
   }
@@ -339,7 +301,8 @@ void SyslogsProviderImpl::ReadSyslogs(
   // request->ForwardResult(logs, zip_content).
   scoped_refptr<SyslogsMemoryHandler>
       handler(new SyslogsMemoryHandler(request, logs, zip_content));
-  handler->StartFetch();
+  // TODO(jamescook): Maybe we don't need to update histograms here?
+  handler->StartFetch(MemoryDetails::UPDATE_USER_METRICS);
 }
 
 void SyslogsProviderImpl::LoadCompressedLogs(const FilePath& zip_file,
diff --git a/chrome/browser/low_memory_observer.cc b/chrome/browser/low_memory_observer.cc
index b4e408d..8788f03 100644
--- a/chrome/browser/low_memory_observer.cc
+++ b/chrome/browser/low_memory_observer.cc
@@ -90,7 +90,7 @@ class LowMemoryObserverImpl
     static void DiscardTab() {
       CHECK(BrowserThread::CurrentlyOn(BrowserThread::UI));
       if (g_browser_process && g_browser_process->oom_priority_manager())
-        g_browser_process->oom_priority_manager()->DiscardTab();
+        g_browser_process->oom_priority_manager()->LogMemoryAndDiscardTab();
     }
    private:
     LowMemoryObserverImpl* owner_;
diff --git a/chrome/browser/memory_details.cc b/chrome/browser/memory_details.cc
index 64d3a87..2fab74b 100644
--- a/chrome/browser/memory_details.cc
+++ b/chrome/browser/memory_details.cc
@@ -9,6 +9,7 @@
 #include "base/metrics/histogram.h"
 #include "base/process_util.h"
 #include "base/string_util.h"
+#include "base/stringprintf.h"
 #include "base/utf_string_conversions.h"
 #include "chrome/browser/extensions/extension_process_manager.h"
 #include "chrome/browser/extensions/extension_service.h"
@@ -35,6 +36,7 @@
 #include "content/public/browser/zygote_host_linux.h"
 #endif
 
+using base::StringPrintf;
 using content::BrowserChildProcessHostIterator;
 using content::BrowserThread;
 using content::NavigationEntry;
@@ -115,10 +117,11 @@ ProcessData& ProcessData::operator=(const ProcessData& rhs) {
 // one task run for that long on the UI or IO threads.  So, we run the
 // expensive parts of this operation over on the file thread.
 //
-void MemoryDetails::StartFetch() {
+void MemoryDetails::StartFetch(UserMetricsMode user_metrics_mode) {
   // This might get called from the UI or FILE threads, but should not be
   // getting called from the IO thread.
   DCHECK(!BrowserThread::CurrentlyOn(BrowserThread::IO));
+  user_metrics_mode_ = user_metrics_mode;
 
   // In order to process this request, we need to use the plugin information.
   // However, plugin process information is only available from the IO thread.
@@ -129,6 +132,33 @@ void MemoryDetails::StartFetch() {
 
 MemoryDetails::~MemoryDetails() {}
 
+std::string MemoryDetails::ToLogString() {
+  std::string log;
+  log.reserve(4096);
+  const ProcessData& chrome = *ChromeBrowser();
+  for (ProcessMemoryInformationList::const_iterator iter1 =
+           chrome.processes.begin();
+       iter1 != chrome.processes.end(); ++iter1) {
+    log += ProcessMemoryInformation::GetFullTypeNameInEnglish(
+            iter1->type, iter1->renderer_type);
+    if (!iter1->titles.empty()) {
+      log += " [";
+      for (std::vector<string16>::const_iterator iter2 =
+               iter1->titles.begin();
+           iter2 != iter1->titles.end(); ++iter2) {
+        if (iter2 != iter1->titles.begin())
+          log += "|";
+        log += UTF16ToUTF8(*iter2);
+      }
+      log += "]";
+    }
+    log += StringPrintf(" %d MB private, %d MB shared\n",
+                        static_cast<int>(iter1->working_set.priv) / 1024,
+                        static_cast<int>(iter1->working_set.shared) / 1024);
+  }
+  return log;
+}
+
 void MemoryDetails::CollectChildInfoOnIOThread() {
   DCHECK(BrowserThread::CurrentlyOn(BrowserThread::IO));
 
@@ -322,7 +352,8 @@ void MemoryDetails::CollectChildInfoOnUIThread() {
     }
   }
 
-  UpdateHistograms();
+  if (user_metrics_mode_ == UPDATE_USER_METRICS)
+    UpdateHistograms();
 
   OnDetailsAvailable();
 }
diff --git a/chrome/browser/memory_details.h b/chrome/browser/memory_details.h
index 568f591..bdf032f 100644
--- a/chrome/browser/memory_details.h
+++ b/chrome/browser/memory_details.h
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// 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.
 
@@ -107,6 +107,11 @@ class ProcessInfoSnapshot;
 //    }
 class MemoryDetails : public base::RefCountedThreadSafe<MemoryDetails> {
  public:
+  enum UserMetricsMode {
+    UPDATE_USER_METRICS,  // Update UMA memory histograms with results.
+    SKIP_USER_METRICS
+  };
+
   // Constructor.
   MemoryDetails();
 
@@ -116,10 +121,15 @@ class MemoryDetails : public base::RefCountedThreadSafe<MemoryDetails> {
 
   // Initiate updating the current memory details.  These are fetched
   // asynchronously because data must be collected from multiple threads.
+  // Updates UMA memory histograms if |mode| is UPDATE_USER_METRICS.
   // OnDetailsAvailable will be called when this process is complete.
-  void StartFetch();
+  void StartFetch(UserMetricsMode user_metrics_mode);
 
-  virtual void OnDetailsAvailable() {}
+  virtual void OnDetailsAvailable() = 0;
+
+  // Returns a string summarizing memory usage of the Chrome browser process
+  // and all sub-processes, suitable for logging.
+  std::string ToLogString();
 
  protected:
   friend class base::RefCountedThreadSafe<MemoryDetails>;
@@ -156,8 +166,7 @@ class MemoryDetails : public base::RefCountedThreadSafe<MemoryDetails> {
   // renderer processes is only available there.
   void CollectChildInfoOnUIThread();
 
-  // Each time we take a memory sample, we do a little work to update
-  // the global histograms for tracking memory usage.
+  // Updates the global histograms for tracking memory usage.
   void UpdateHistograms();
 
   // Returns a pointer to the ProcessData structure for Chrome.
@@ -165,6 +174,8 @@ class MemoryDetails : public base::RefCountedThreadSafe<MemoryDetails> {
 
   std::vector<ProcessData> process_data_;
 
+  UserMetricsMode user_metrics_mode_;
+
   DISALLOW_COPY_AND_ASSIGN(MemoryDetails);
 };
 
diff --git a/chrome/browser/memory_details_android.cc b/chrome/browser/memory_details_android.cc
index 542b27d..049d4b1 100644
--- a/chrome/browser/memory_details_android.cc
+++ b/chrome/browser/memory_details_android.cc
@@ -91,7 +91,8 @@ void GetAllChildren(const std::vector<ProcessEntry>& processes,
 
 }  // namespace
 
-MemoryDetails::MemoryDetails() {
+MemoryDetails::MemoryDetails()
+    : user_metrics_mode_(UPDATE_USER_METRICS) {
 }
 
 ProcessData* MemoryDetails::ChromeBrowser() {
diff --git a/chrome/browser/memory_details_linux.cc b/chrome/browser/memory_details_linux.cc
index 0001d6f..4f86c4c7 100644
--- a/chrome/browser/memory_details_linux.cc
+++ b/chrome/browser/memory_details_linux.cc
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// 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.
 
@@ -67,7 +67,8 @@ static const struct {
   { "", MAX_BROWSERS },
 };
 
-MemoryDetails::MemoryDetails() {
+MemoryDetails::MemoryDetails()
+    : user_metrics_mode_(UPDATE_USER_METRICS) {
 }
 
 ProcessData* MemoryDetails::ChromeBrowser() {
diff --git a/chrome/browser/memory_details_mac.cc b/chrome/browser/memory_details_mac.cc
index 36f29f2..ab55c8b 100644
--- a/chrome/browser/memory_details_mac.cc
+++ b/chrome/browser/memory_details_mac.cc
@@ -48,7 +48,8 @@ enum BrowserType {
 } BrowserProcess;
 
 
-MemoryDetails::MemoryDetails() {
+MemoryDetails::MemoryDetails()
+    : user_metrics_mode_(UPDATE_USER_METRICS) {
   const std::string google_browser_name =
       l10n_util::GetStringUTF8(IDS_PRODUCT_NAME);
   // (Human and process) names of browsers; should match the ordering for
diff --git a/chrome/browser/memory_details_win.cc b/chrome/browser/memory_details_win.cc
index 92355c9..3c41a8f 100644
--- a/chrome/browser/memory_details_win.cc
+++ b/chrome/browser/memory_details_win.cc
@@ -1,4 +1,4 @@
-// Copyright (c) 2011 The Chromium Authors. All rights reserved.
+// 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.
 
@@ -35,7 +35,8 @@ enum {
   MAX_BROWSERS
 } BrowserProcess;
 
-MemoryDetails::MemoryDetails() {
+MemoryDetails::MemoryDetails()
+    : user_metrics_mode_(UPDATE_USER_METRICS) {
   static const std::wstring google_browser_name =
       UTF16ToWide(l10n_util::GetStringUTF16(IDS_PRODUCT_NAME));
   struct {
diff --git a/chrome/browser/metrics/metrics_service.cc b/chrome/browser/metrics/metrics_service.cc
index 92ee602..25d0af7 100644
--- a/chrome/browser/metrics/metrics_service.cc
+++ b/chrome/browser/metrics/metrics_service.cc
@@ -927,7 +927,7 @@ void MetricsService::StartFinalLogInfoCollection() {
 
   scoped_refptr<MetricsMemoryDetails> details(
       new MetricsMemoryDetails(callback));
-  details->StartFetch();
+  details->StartFetch(MemoryDetails::UPDATE_USER_METRICS);
 
   // Collect WebCore cache information to put into a histogram.
   for (content::RenderProcessHost::iterator i(
diff --git a/chrome/browser/oom_priority_manager.cc b/chrome/browser/oom_priority_manager.cc
index cff350c..429f817 100644
--- a/chrome/browser/oom_priority_manager.cc
+++ b/chrome/browser/oom_priority_manager.cc
@@ -20,7 +20,9 @@
 #include "base/timer.h"
 #include "base/utf_string_conversions.h"
 #include "build/build_config.h"
+#include "chrome/browser/browser_process.h"
 #include "chrome/browser/low_memory_observer.h"
+#include "chrome/browser/memory_details.h"
 #include "chrome/browser/tabs/tab_strip_model.h"
 #include "chrome/browser/ui/browser_list.h"
 #include "chrome/browser/ui/tab_contents/tab_contents_wrapper.h"
@@ -76,6 +78,43 @@ int64 IdFromTabContents(WebContents* web_contents) {
   return reinterpret_cast<int64>(web_contents);
 }
 
+////////////////////////////////////////////////////////////////////////////////
+// OomMemoryDetails logs details about all Chrome processes during an out-of-
+// memory event in an attempt to identify the culprit, then discards a tab and
+// deletes itself.
+class OomMemoryDetails : public MemoryDetails {
+ public:
+  OomMemoryDetails();
+
+  // MemoryDetails overrides:
+  virtual void OnDetailsAvailable() OVERRIDE;
+
+ private:
+  virtual ~OomMemoryDetails() {}
+
+  TimeTicks start_time_;
+
+  DISALLOW_COPY_AND_ASSIGN(OomMemoryDetails);
+};
+
+OomMemoryDetails::OomMemoryDetails() {
+  AddRef();  // Released in OnDetailsAvailable().
+  start_time_ = TimeTicks::Now();
+}
+
+void OomMemoryDetails::OnDetailsAvailable() {
+  TimeDelta delta = TimeTicks::Now() - start_time_;
+  // These logs are collected by user feedback reports.  We want them to help
+  // diagnose user-reported problems with frequently discarded tabs.
+  LOG(INFO) << "OOM details (" << delta.InMilliseconds() << " ms):\n"
+      << ToLogString();
+  if (g_browser_process && g_browser_process->oom_priority_manager())
+    g_browser_process->oom_priority_manager()->DiscardTab();
+  // Delete ourselves so we don't have to worry about OomPriorityManager
+  // deleting us when we're still working.
+  Release();
+}
+
 }  // namespace
 
 ////////////////////////////////////////////////////////////////////////////////
@@ -168,6 +207,12 @@ bool OomPriorityManager::DiscardTab() {
   return false;
 }
 
+void OomPriorityManager::LogMemoryAndDiscardTab() {
+  // Deletes itself upon completion.
+  OomMemoryDetails* details = new OomMemoryDetails();
+  details->StartFetch(MemoryDetails::SKIP_USER_METRICS);
+}
+
 bool OomPriorityManager::DiscardTabById(int64 target_web_contents_id) {
   for (BrowserList::const_iterator browser_iterator = BrowserList::begin();
        browser_iterator != BrowserList::end(); ++browser_iterator) {
diff --git a/chrome/browser/oom_priority_manager.h b/chrome/browser/oom_priority_manager.h
index 916e062..231de49 100644
--- a/chrome/browser/oom_priority_manager.h
+++ b/chrome/browser/oom_priority_manager.h
@@ -50,6 +50,11 @@ class OomPriorityManager : public content::NotificationObserver {
   // Returns true if it successfully found a tab and discarded it.
   bool DiscardTab();
 
+  // Log memory statistics for the running processes, then discards a tab.
+  // Tab discard happens sometime later, as collecting the statistics touches
+  // multiple threads and takes time.
+  void LogMemoryAndDiscardTab();
+
  private:
   FRIEND_TEST_ALL_PREFIXES(OomPriorityManagerTest, Comparator);
 
diff --git a/chrome/browser/ui/webui/about_ui.cc b/chrome/browser/ui/webui/about_ui.cc
index 84921a4..e6c3183 100644
--- a/chrome/browser/ui/webui/about_ui.cc
+++ b/chrome/browser/ui/webui/about_ui.cc
@@ -573,7 +573,7 @@ std::string AboutDiscardsRun() {
   output.append(StringPrintf("<meta http-equiv=\"refresh\" content=\"2;%s\">",
                              chrome::kChromeUIDiscardsURL));
   output.append(WrapWithTag("p", "Discarding a tab..."));
-  g_browser_process->oom_priority_manager()->DiscardTab();
+  g_browser_process->oom_priority_manager()->LogMemoryAndDiscardTab();
   AppendFooter(&output);
   return output;
 }
@@ -868,7 +868,8 @@ void FinishMemoryDataRequest(const std::string& path,
     // the refcount to be greater than 0.
     scoped_refptr<AboutMemoryHandler>
         handler(new AboutMemoryHandler(source, request_id));
-    handler->StartFetch();
+    // TODO(jamescook): Maybe this shouldn't update UMA?
+    handler->StartFetch(MemoryDetails::UPDATE_USER_METRICS);
   } else {
     source->FinishDataRequest(
         ResourceBundle::GetSharedInstance().GetRawDataResource(