Add DBusStatistics and DBusLogSource to log and show dbus stats

The intention of this is to provide low overhead detailed logging to ensure that dbus call counts remain reasonable as we migrate NetworkLibrary and other systtems from src/chrome to src/chromeos.

We already have UMA stats which provide high level numbers that we can watch, but this will make detailed debugging available for advanced users and in feedback reports.


BUG=159635
For chrome/chrome_browser_chromeos.gypi:
TBR=sky@chromium.org

Review URL: https://chromiumcodereview.appspot.com/11363173

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

5 files changed, 543 insertions, 2 deletions

diff --git a/dbus/dbus.gyp b/dbus/dbus.gyp
index be5f686..0ca5a2c 100644
--- a/dbus/dbus.gyp
+++ b/dbus/dbus.gyp
@@ -25,6 +25,8 @@
         'bus.cc',
         'bus.h',
         'dbus_export.h',
+        'dbus_statistics.cc',
+        'dbus_statistics.h',
         'exported_object.cc',
         'exported_object.h',
         'file_descriptor.cc',
@@ -91,6 +93,7 @@
       ],
       'sources': [
         'bus_unittest.cc',
+        'dbus_statistics_unittest.cc',
         'end_to_end_async_unittest.cc',
         'end_to_end_sync_unittest.cc',
         'message_unittest.cc',
diff --git a/dbus/dbus_statistics.cc b/dbus/dbus_statistics.cc
new file mode 100644
index 0000000..015e20e
--- /dev/null
+++ b/dbus/dbus_statistics.cc
@@ -0,0 +1,271 @@
+// 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 "dbus/dbus_statistics.h"
+
+#include <set>
+
+#include "base/logging.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/stl_util.h"
+#include "base/stringprintf.h"
+#include "base/time.h"
+
+namespace dbus {
+
+namespace {
+
+// Used to store dbus statistics sorted alphabetically by service, interface,
+// then method (using std::string <).
+struct Stat {
+  Stat(const std::string& service,
+       const std::string& interface,
+       const std::string& method)
+      : service(service),
+        interface(interface),
+        method(method),
+        sent_method_calls(0),
+        received_signals(0),
+        sent_blocking_method_calls(0) {
+  }
+  std::string service;
+  std::string interface;
+  std::string method;
+  int sent_method_calls;
+  int received_signals;
+  int sent_blocking_method_calls;
+
+  bool Compare(const Stat& other) const {
+    if (service != other.service)
+      return service < other.service;
+    if (interface != other.interface)
+      return interface < other.interface;
+    return method < other.method;
+  }
+
+  struct PtrCompare {
+    bool operator()(Stat* lhs, Stat* rhs) const {
+      DCHECK(lhs && rhs);
+      return lhs->Compare(*rhs);
+    }
+  };
+};
+
+typedef std::set<Stat*, Stat::PtrCompare> StatSet;
+
+//------------------------------------------------------------------------------
+// DBusStatistics
+
+// Simple class for gathering DBus usage statistics.
+class DBusStatistics {
+ public:
+  DBusStatistics() : start_time_(base::Time::Now()) {
+  }
+
+  ~DBusStatistics() {
+    STLDeleteContainerPointers(stats_.begin(), stats_.end());
+  }
+
+  // Enum to specify which field in Stat to increment in AddStat
+  enum StatType {
+    TYPE_SENT_METHOD_CALLS,
+    TYPE_RECEIVED_SIGNALS,
+    TYPE_SENT_BLOCKING_METHOD_CALLS
+  };
+
+  // Add a call to |method| for |interface|. See also MethodCall in message.h.
+  void AddStat(const std::string& service,
+               const std::string& interface,
+               const std::string& method,
+               StatType type) {
+    Stat* stat = GetStat(service, interface, method, true);
+    DCHECK(stat);
+    if (type == TYPE_SENT_METHOD_CALLS)
+      ++stat->sent_method_calls;
+    else if (type == TYPE_RECEIVED_SIGNALS)
+      ++stat->received_signals;
+    else if (type == TYPE_SENT_BLOCKING_METHOD_CALLS)
+      ++stat->sent_blocking_method_calls;
+    else
+      NOTREACHED();
+  }
+
+  // Look up the Stat entry in |stats_|. If |add_stat| is true, add a new entry
+  // if one does not already exist.
+  Stat* GetStat(const std::string& service,
+                const std::string& interface,
+                const std::string& method,
+                bool add_stat) {
+    scoped_ptr<Stat> stat(new Stat(service, interface, method));
+    StatSet::iterator found = stats_.find(stat.get());
+    if (found != stats_.end())
+      return *found;
+    if (!add_stat)
+      return NULL;
+    found = stats_.insert(stat.release()).first;
+    return *found;
+  }
+
+  StatSet& stats() { return stats_; }
+  base::Time start_time() { return start_time_; }
+
+ private:
+  StatSet stats_;
+  base::Time start_time_;
+
+  DISALLOW_COPY_AND_ASSIGN(DBusStatistics);
+};
+
+DBusStatistics* g_dbus_statistics = NULL;
+
+}  // namespace
+
+//------------------------------------------------------------------------------
+
+namespace statistics {
+
+void Initialize() {
+  if (g_dbus_statistics)
+    delete g_dbus_statistics;  // reset statistics
+  g_dbus_statistics = new DBusStatistics();
+}
+
+void Shutdown() {
+  delete g_dbus_statistics;
+  g_dbus_statistics = NULL;
+}
+
+void AddSentMethodCall(const std::string& service,
+                       const std::string& interface,
+                       const std::string& method) {
+  if (!g_dbus_statistics)
+    return;
+  g_dbus_statistics->AddStat(
+      service, interface, method, DBusStatistics::TYPE_SENT_METHOD_CALLS);
+}
+
+void AddReceivedSignal(const std::string& service,
+                       const std::string& interface,
+                       const std::string& method) {
+  if (!g_dbus_statistics)
+    return;
+  g_dbus_statistics->AddStat(
+      service, interface, method, DBusStatistics::TYPE_RECEIVED_SIGNALS);
+}
+
+void AddBlockingSentMethodCall(const std::string& service,
+                               const std::string& interface,
+                               const std::string& method) {
+  if (!g_dbus_statistics)
+    return;
+  g_dbus_statistics->AddStat(
+      service, interface, method,
+      DBusStatistics::TYPE_SENT_BLOCKING_METHOD_CALLS);
+}
+
+// NOTE: If the output format is changed, be certain to change the test
+// expectations as well.
+std::string GetAsString(ShowInString show, FormatString format) {
+  if (!g_dbus_statistics)
+    return "DBusStatistics not initialized.";
+
+  const StatSet& stats = g_dbus_statistics->stats();
+  if (stats.empty())
+    return "No DBus calls.";
+
+  base::TimeDelta dtime = base::Time::Now() - g_dbus_statistics->start_time();
+  int dminutes = dtime.InMinutes();
+  dminutes = std::max(dminutes, 1);
+
+  std::string result;
+  int sent = 0, received = 0, sent_blocking = 0;
+  // Stats are stored in order by service, then interface, then method.
+  for (StatSet::const_iterator iter = stats.begin(); iter != stats.end(); ) {
+    StatSet::const_iterator cur_iter = iter;
+    StatSet::const_iterator next_iter = ++iter;
+    const Stat* stat = *cur_iter;
+    sent += stat->sent_method_calls;
+    received += stat->received_signals;
+    sent_blocking += stat->sent_blocking_method_calls;
+    // If this is not the last stat, and if the next stat matches the current
+    // stat, continue.
+    if (next_iter != stats.end() &&
+        (*next_iter)->service == stat->service &&
+        (show < SHOW_INTERFACE || (*next_iter)->interface == stat->interface) &&
+        (show < SHOW_METHOD || (*next_iter)->method == stat->method))
+      continue;
+
+    if (!sent && !received && !sent_blocking)
+        continue;  // No stats collected for this line, skip it and continue.
+
+    // Add a line to the result and clear the counts.
+    std::string line;
+    if (show == SHOW_SERVICE) {
+      line += stat->service;
+    } else {
+      // The interface usually includes the service so don't show both.
+      line += stat->interface;
+      if (show >= SHOW_METHOD)
+        line += "." + stat->method;
+    }
+    line += StringPrintf(":");
+    if (sent_blocking) {
+      line += StringPrintf(" Sent (BLOCKING):");
+      if (format == FORMAT_TOTALS)
+        line += StringPrintf(" %d", sent_blocking);
+      else if (format == FORMAT_PER_MINUTE)
+        line += StringPrintf(" %d/min", sent_blocking / dminutes);
+      else if (format == FORMAT_ALL)
+        line += StringPrintf(" %d (%d/min)",
+                             sent_blocking, sent_blocking / dminutes);
+    }
+    if (sent) {
+      line += StringPrintf(" Sent:");
+      if (format == FORMAT_TOTALS)
+        line += StringPrintf(" %d", sent);
+      else if (format == FORMAT_PER_MINUTE)
+        line += StringPrintf(" %d/min", sent / dminutes);
+      else if (format == FORMAT_ALL)
+        line += StringPrintf(" %d (%d/min)", sent, sent / dminutes);
+    }
+    if (received) {
+      line += StringPrintf(" Received:");
+      if (format == FORMAT_TOTALS)
+        line += StringPrintf(" %d", received);
+      else if (format == FORMAT_PER_MINUTE)
+        line += StringPrintf(" %d/min", received / dminutes);
+      else if (format == FORMAT_ALL)
+        line += StringPrintf(" %d (%d/min)", received, received / dminutes);
+    }
+    result += line + "\n";
+    sent = 0;
+    sent_blocking = 0;
+    received = 0;
+  }
+  return result;
+}
+
+namespace testing {
+
+bool GetCalls(const std::string& service,
+              const std::string& interface,
+              const std::string& method,
+              int* sent,
+              int* received,
+              int* blocking) {
+  if (!g_dbus_statistics)
+    return false;
+  Stat* stat = g_dbus_statistics->GetStat(service, interface, method, false);
+  if (!stat)
+    return false;
+  *sent = stat->sent_method_calls;
+  *received = stat->received_signals;
+  *blocking = stat->sent_blocking_method_calls;
+  return true;
+}
+
+}  // namespace testing
+
+}  // namespace statistics
+}  // namespace dbus
diff --git a/dbus/dbus_statistics.h b/dbus/dbus_statistics.h
new file mode 100644
index 0000000..2bd9fd9
--- /dev/null
+++ b/dbus/dbus_statistics.h
@@ -0,0 +1,74 @@
+// 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.
+
+#ifndef DBUS_DBUS_STATISTICS_H_
+#define DBUS_DBUS_STATISTICS_H_
+
+#include <string>
+
+#include "dbus/dbus_export.h"
+
+namespace dbus {
+namespace statistics {
+
+// Enum to specify what level of detail to show in GetAsString
+enum ShowInString {
+  SHOW_SERVICE = 0,  // Service totals only
+  SHOW_INTERFACE = 1,  // Service + interface totals
+  SHOW_METHOD = 2,  // Service + interface + method totals
+};
+
+// Enum to specify how to format the display in GetAsString
+enum FormatString {
+  FORMAT_TOTALS = 0,  // Raw totals only
+  FORMAT_PER_MINUTE = 1,  // Per-minute only
+  FORMAT_ALL = 2  // Include all format details
+};
+
+// Initializes / shuts down dbus statistics gathering. Calling Initialize
+// more than once will reset the statistics.
+CHROME_DBUS_EXPORT void Initialize();
+CHROME_DBUS_EXPORT void Shutdown();
+
+// Add sent/received calls to the statistics gathering class. These methods
+// do nothing unless Initialize() was called.
+CHROME_DBUS_EXPORT void AddSentMethodCall(const std::string& service,
+                                          const std::string& interface,
+                                          const std::string& method);
+CHROME_DBUS_EXPORT void AddReceivedSignal(const std::string& service,
+                                          const std::string& interface,
+                                          const std::string& method);
+// Track synchronous calls independently since we want to highlight
+// (and remove) these.
+CHROME_DBUS_EXPORT void AddBlockingSentMethodCall(const std::string& service,
+                                                  const std::string& interface,
+                                                  const std::string& method);
+
+// Output the calls into a formatted string. |show| determines what level
+// of detail to show: one line per service, per interface, or per method.
+// If |show_per_minute| is true include per minute stats.
+// Example output for SHOW_METHOD, FORMAT_TOTALS:
+//   org.chromium.Mtpd.EnumerateStorage: Sent: 100
+//   org.chromium.Mtpd.MTPStorageSignal: Received: 20
+// Example output for SHOW_INTERFACE, FORMAT_ALL:
+//   org.chromium.Mtpd: Sent: 100 (10/min) Received: 20 (2/min)
+CHROME_DBUS_EXPORT std::string GetAsString(ShowInString show,
+                                           FormatString format);
+
+namespace testing {
+// Sets |sent| to the number of sent calls, |received| to the number of
+// received calls, and |blocking| to the number of sent blocking calls for
+// service+interface+method. Used in unittests.
+CHROME_DBUS_EXPORT bool GetCalls(const std::string& service,
+                                 const std::string& interface,
+                                 const std::string& method,
+                                 int* sent,
+                                 int* received,
+                                 int* blocking);
+}  // namespace testing
+
+}  // namespace statistics
+}  // namespace dbus
+
+#endif  // DBUS_DBUS_STATISTICS_H_
diff --git a/dbus/dbus_statistics_unittest.cc b/dbus/dbus_statistics_unittest.cc
new file mode 100644
index 0000000..9a2e2a1
--- /dev/null
+++ b/dbus/dbus_statistics_unittest.cc
@@ -0,0 +1,183 @@
+// 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 "dbus/dbus_statistics.h"
+
+#include "base/basictypes.h"
+#include "base/compiler_specific.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace dbus {
+
+class DBusStatisticsTest : public testing::Test {
+ public:
+  DBusStatisticsTest() {
+  }
+
+  virtual void SetUp() OVERRIDE {
+    statistics::Initialize();
+  }
+
+  virtual void TearDown() OVERRIDE {
+    statistics::Shutdown();
+  }
+
+ protected:
+  void AddTestMethodCalls() {
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method1");
+    statistics::AddReceivedSignal(
+        "service1", "service1.interface1", "method1");
+    statistics::AddBlockingSentMethodCall(
+        "service1", "service1.interface1", "method1");
+
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method2");
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method2");
+    statistics::AddReceivedSignal(
+        "service1", "service1.interface1", "method2");
+
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method3");
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method3");
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface1", "method3");
+
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface2", "method1");
+
+    statistics::AddSentMethodCall(
+        "service1", "service1.interface2", "method2");
+
+    statistics::AddSentMethodCall(
+        "service2", "service2.interface1", "method1");
+  }
+
+ private:
+  DISALLOW_COPY_AND_ASSIGN(DBusStatisticsTest);
+};
+
+TEST_F(DBusStatisticsTest, TestDBusStatsBasic) {
+  int sent = 0, received = 0, block = 0;
+
+  // Add a sent call
+  statistics::AddSentMethodCall("service1", "service1.interface1", "method1");
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(0, received);
+  EXPECT_EQ(0, block);
+
+  // Add a received call
+  statistics::AddReceivedSignal("service1", "service1.interface1", "method1");
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(1, received);
+  EXPECT_EQ(0, block);
+
+  // Add a block call
+  statistics::AddBlockingSentMethodCall(
+      "service1", "service1.interface1", "method1");
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(1, received);
+  EXPECT_EQ(1, block);
+}
+
+TEST_F(DBusStatisticsTest, TestDBusStatsMulti) {
+  int sent = 0, received = 0, block = 0;
+
+  // Add some more stats to exercise accessing multiple different stats.
+  AddTestMethodCalls();
+
+  // Make sure all entries can be found in the set and their counts were
+  // incremented correctly.
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(1, received);
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method2", &sent, &received, &block));
+  EXPECT_EQ(2, sent);
+  EXPECT_EQ(1, received);
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface1", "method3", &sent, &received, &block));
+  EXPECT_EQ(3, sent);
+  EXPECT_EQ(0, received);
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface2", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(0, received);
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service1", "service1.interface2", "method2", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(0, received);
+  ASSERT_TRUE(statistics::testing::GetCalls(
+      "service2", "service2.interface1", "method1", &sent, &received, &block));
+  EXPECT_EQ(1, sent);
+  EXPECT_EQ(0, received);
+
+  ASSERT_FALSE(statistics::testing::GetCalls(
+      "service1", "service1.interface3", "method2", &sent, &received, &block));
+}
+
+TEST_F(DBusStatisticsTest, TestGetAsString) {
+  std::string output_none = GetAsString(statistics::SHOW_SERVICE,
+                                        statistics::FORMAT_TOTALS);
+  EXPECT_EQ("No DBus calls.", output_none);
+
+  AddTestMethodCalls();
+
+  std::string output_service = GetAsString(statistics::SHOW_SERVICE,
+                                           statistics::FORMAT_TOTALS);
+  const std::string expected_output_service(
+      "service1: Sent (BLOCKING): 1 Sent: 8 Received: 2\n"
+      "service2: Sent: 1\n");
+  EXPECT_EQ(expected_output_service, output_service);
+
+  std::string output_interface = GetAsString(statistics::SHOW_INTERFACE,
+                                             statistics::FORMAT_TOTALS);
+  const std::string expected_output_interface(
+      "service1.interface1: Sent (BLOCKING): 1 Sent: 6 Received: 2\n"
+      "service1.interface2: Sent: 2\n"
+      "service2.interface1: Sent: 1\n");
+  EXPECT_EQ(expected_output_interface, output_interface);
+
+  std::string output_per_minute = GetAsString(statistics::SHOW_INTERFACE,
+                                              statistics::FORMAT_PER_MINUTE);
+  const std::string expected_output_per_minute(
+      "service1.interface1: Sent (BLOCKING): 1/min Sent: 6/min"
+      " Received: 2/min\n"
+      "service1.interface2: Sent: 2/min\n"
+      "service2.interface1: Sent: 1/min\n");
+  EXPECT_EQ(expected_output_per_minute, output_per_minute);
+
+  std::string output_all = GetAsString(statistics::SHOW_INTERFACE,
+                                       statistics::FORMAT_ALL);
+  const std::string expected_output_all(
+      "service1.interface1: Sent (BLOCKING): 1 (1/min) Sent: 6 (6/min)"
+      " Received: 2 (2/min)\n"
+      "service1.interface2: Sent: 2 (2/min)\n"
+      "service2.interface1: Sent: 1 (1/min)\n");
+  EXPECT_EQ(expected_output_all, output_all);
+
+
+  std::string output_method = GetAsString(statistics::SHOW_METHOD,
+                                          statistics::FORMAT_TOTALS);
+  const std::string expected_output_method(
+      "service1.interface1.method1: Sent (BLOCKING): 1 Sent: 1 Received: 1\n"
+      "service1.interface1.method2: Sent: 2 Received: 1\n"
+      "service1.interface1.method3: Sent: 3\n"
+      "service1.interface2.method1: Sent: 1\n"
+      "service1.interface2.method2: Sent: 1\n"
+      "service2.interface1.method1: Sent: 1\n");
+  EXPECT_EQ(expected_output_method, output_method);
+
+}
+
+}  // namespace dbus
diff --git a/dbus/object_proxy.cc b/dbus/object_proxy.cc
index 5e9bf5b..87950d1 100644
--- a/dbus/object_proxy.cc
+++ b/dbus/object_proxy.cc
@@ -12,6 +12,7 @@
 #include "base/stringprintf.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
+#include "dbus/dbus_statistics.h"
 #include "dbus/message.h"
 #include "dbus/object_path.h"
 #include "dbus/object_proxy.h"
@@ -25,7 +26,7 @@ const char kErrorServiceUnknown[] = "org.freedesktop.DBus.Error.ServiceUnknown";
 const int kSuccessRatioHistogramMaxValue = 2;
 
 // The path of D-Bus Object sending NameOwnerChanged signal.
-const char kDbusSystemObjectPath[] = "/org/freedesktop/DBus";
+const char kDBusSystemObjectPath[] = "/org/freedesktop/DBus";
 
 // Gets the absolute signal name by concatenating the interface name and
 // the signal name. Used for building keys for method_table_ in
@@ -83,6 +84,9 @@ Response* ObjectProxy::CallMethodAndBlock(MethodCall* method_call,
   UMA_HISTOGRAM_ENUMERATION("DBus.SyncMethodCallSuccess",
                             response_message ? 1 : 0,
                             kSuccessRatioHistogramMaxValue);
+  statistics::AddBlockingSentMethodCall(service_name_,
+                                        method_call->GetInterface(),
+                                        method_call->GetMember());
 
   if (!response_message) {
     LogMethodCallFailure(method_call->GetInterface(),
@@ -144,6 +148,10 @@ void ObjectProxy::CallMethodWithErrorCallback(MethodCall* method_call,
                                   callback,
                                   error_callback,
                                   start_time);
+  statistics::AddSentMethodCall(service_name_,
+                                method_call->GetInterface(),
+                                method_call->GetMember());
+
   // Wait for the response in the D-Bus thread.
   bus_->PostTaskToDBusThread(FROM_HERE, task);
 }
@@ -433,7 +441,7 @@ DBusHandlerResult ObjectProxy::HandleMessage(
   // allow other object proxies to handle instead.
   const dbus::ObjectPath path = signal->GetPath();
   if (path != object_path_) {
-    if (path.value() == kDbusSystemObjectPath &&
+    if (path.value() == kDBusSystemObjectPath &&
         signal->GetMember() == "NameOwnerChanged") {
       // Handle NameOwnerChanged separately
       return HandleNameOwnerChanged(signal.Pass());
@@ -444,6 +452,8 @@ DBusHandlerResult ObjectProxy::HandleMessage(
   const std::string interface = signal->GetInterface();
   const std::string member = signal->GetMember();
 
+  statistics::AddReceivedSignal(service_name_, interface, member);
+
   // Check if we know about the signal.
   const std::string absolute_signal_name = GetAbsoluteSignalName(
       interface, member);