Add DBusStatistics and DBusLogSource to log and show dbus stats

dbus/object_proxy.cc

 // 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/bus.h"
 
 #include "base/bind.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
 #include "base/metrics/histogram.h"
 #include "base/string_piece.h"
 #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"
 #include "dbus/scoped_dbus_error.h"
 
 namespace {
 
 const char kErrorServiceUnknown[] = "org.freedesktop.DBus.Error.ServiceUnknown";
 
 // Used for success ratio histograms. 1 for success, 0 for failure.
 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
 // ObjectProxy.
 std::string GetAbsoluteSignalName(
     const std::string& interface_name,
     const std::string& signal_name) {
   return interface_name + "." + signal_name;
 }
 
@@ skipping 37 matching lines @@
   ScopedDBusError error;
 
   // Send the message synchronously.
   const base::TimeTicks start_time = base::TimeTicks::Now();
   DBusMessage* response_message =
       bus_->SendWithReplyAndBlock(request_message, timeout_ms, error.get());
   // Record if the method call is successful, or not. 1 if successful.
   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(),
                          method_call->GetMember(),
                          error.is_set() ? error.name() : "unknown error type",
                          error.is_set() ? error.message() : "");
     return NULL;
   }
   // Record time spent for the method call. Don't include failures.
   UMA_HISTOGRAM_TIMES("DBus.SyncMethodCallTime",
@@ skipping 41 matching lines @@
   DBusMessage* request_message = method_call->raw_message();
   dbus_message_ref(request_message);
 
   base::Closure task = base::Bind(&ObjectProxy::StartAsyncMethodCall,
                                   this,
                                   timeout_ms,
                                   request_message,
                                   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);
 }
 
 void ObjectProxy::ConnectToSignal(const std::string& interface_name,
                                   const std::string& signal_name,
                                   SignalCallback signal_callback,
                                   OnConnectedCallback on_connected_callback) {
   bus_->AssertOnOriginThread();
 
@@ skipping 263 matching lines @@
   // reference so we can use it in Signal.
   dbus_message_ref(raw_message);
   scoped_ptr<Signal> signal(
       Signal::FromRawMessage(raw_message));
 
   // Verify the signal comes from the object we're proxying for, this is
   // our last chance to return DBUS_HANDLER_RESULT_NOT_YET_HANDLED and
   // 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.get());
     }
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
   }
 
   const std::string interface = signal->GetInterface();
   const std::string member = signal->GetMember();
 
+  statistics::AddReceivedMethodCall(service_name_, interface, member);

[gauravsh, 2012/11/12 21:41:58]

HandleMessage only deals with signals, and doesn't handle method calls. So this
statistic will count the number of signals, not the number of received method
calls. 

[stevenjb, 2012/11/12 22:34:40]

Well, we don't really receive method calls, but this will (usually) result in a
method call. Still, I understand the potential confusion and will rename this to
ReceviedSignal. (I'd rather track the number of signals received than move this
lower and just track the ones that result in a method call).

+
   // Check if we know about the signal.
   const std::string absolute_signal_name = GetAbsoluteSignalName(
       interface, member);
   MethodTable::const_iterator iter = method_table_.find(absolute_signal_name);
   if (iter == method_table_.end()) {
     // Don't know about the signal.
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
   }
   VLOG(1) << "Signal received: " << signal->ToString();
 
@@ skipping 185 matching lines @@
       service_name_owner_ = new_owner;
       return DBUS_HANDLER_RESULT_HANDLED;
     }
   }
 
   // Untrusted or uninteresting signal
   return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
 }
 
 }  // namespace dbus