Add some histograms to the D-Bus library:

- DBus.SyncMethodCallTime: time spent to perform synchronos method calls
- DBus.AsyncMethodCallTime: time spent to perform asynchronos method calls
- DBus.SyncMethodCallSuccess: success ratio of synchronous method calls
- DBus.AsyncMethodCallSuccess: success ratio of asynchronous method calls
- DBus.ExportedMethodHandleTime: time spent to handle calls to export methods
- DBus.ExportedMethodHandleSuccess: success ratio of the exported method calls
- DBus.SignalHandleTime: time spent to handle signals
- DBus.SignalSendTime: time spent to send signals

BUG=chromium:90036
TEST=dbus_unittests

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

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

5 files changed, 90 insertions, 21 deletions

diff --git a/dbus/bus.cc b/dbus/bus.cc
index fe0826f..5238d51 100644
--- a/dbus/bus.cc
+++ b/dbus/bus.cc
@@ -4,7 +4,6 @@
 //
 // TODO(satorux):
 // - Handle "disconnected" signal.
-// - Collect metrics (ex. # of method calls, method call time, etc.)
 
 #include "dbus/bus.h"
 
diff --git a/dbus/exported_object.cc b/dbus/exported_object.cc
index 8d36d15..c4ebd3b 100644
--- a/dbus/exported_object.cc
+++ b/dbus/exported_object.cc
@@ -8,6 +8,7 @@
 #include "base/logging.h"
 #include "base/memory/ref_counted.h"
 #include "base/message_loop.h"
+#include "base/metrics/histogram.h"
 #include "base/threading/thread_restrictions.h"
 #include "base/time.h"
 #include "dbus/bus.h"
@@ -18,6 +19,9 @@ namespace dbus {
 
 namespace {
 
+// Used for success ratio histograms. 1 for success, 0 for failure.
+const int kSuccessRatioHistogramMaxValue = 2;
+
 // Gets the absolute method name by concatenating the interface name and
 // the method name. Used for building keys for method_table_ in
 // ExportedObject.
@@ -100,11 +104,13 @@ void ExportedObject::SendSignal(Signal* signal) {
   DBusMessage* signal_message = signal->raw_message();
   dbus_message_ref(signal_message);
 
+  const base::TimeTicks start_time = base::TimeTicks::Now();
   // Bind() won't compile if we pass signal_message. See the comment at
   // ObjectProxy::CallMethod() for details.
   bus_->PostTaskToDBusThread(FROM_HERE,
                              base::Bind(&ExportedObject::SendSignalInternal,
                                         this,
+                                        start_time,
                                         static_cast<void*>(signal_message)));
 }
 
@@ -146,12 +152,18 @@ void ExportedObject::OnExported(OnExportedCallback on_exported_callback,
   on_exported_callback.Run(interface_name, method_name, success);
 }
 
-void ExportedObject::SendSignalInternal(void* in_signal_message) {
+void ExportedObject::SendSignalInternal(base::TimeTicks start_time,
+                                        void* in_signal_message) {
   DBusMessage* signal_message =
       static_cast<DBusMessage*>(in_signal_message);
   uint32 serial = 0;
   bus_->Send(signal_message, &serial);
   dbus_message_unref(signal_message);
+  // Record time spent to send the the signal. This is not accurate as the
+  // signal will actually be sent from the next run of the message loop,
+  // but we can at least tell the number of signals sent.
+  UMA_HISTOGRAM_TIMES("DBus.SignalSendTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 bool ExportedObject::Register() {
@@ -195,6 +207,7 @@ DBusHandlerResult ExportedObject::HandleMessage(
 
   if (interface.empty()) {
     // We don't support method calls without interface.
+    LOG(WARNING) << "Interface is missing: " << method_call->ToString();
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
   }
 
@@ -204,9 +217,11 @@ DBusHandlerResult ExportedObject::HandleMessage(
   MethodTable::const_iterator iter = method_table_.find(absolute_method_name);
   if (iter == method_table_.end()) {
     // Don't know about the method.
+    LOG(WARNING) << "Unknown method: " << method_call->ToString();
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
   }
 
+  const base::TimeTicks start_time = base::TimeTicks::Now();
   Response* response = NULL;
   if (bus_->HasDBusThread()) {
     response_from_method_ = NULL;
@@ -237,6 +252,10 @@ DBusHandlerResult ExportedObject::HandleMessage(
     // complete.
     response = iter->second.Run(method_call.get());
   }
+  // Record if the method call is successful, or not. 1 if successful.
+  UMA_HISTOGRAM_ENUMERATION("DBus.ExportedMethodHandleSuccess",
+                            response ? 1 : 0,
+                            kSuccessRatioHistogramMaxValue);
 
   if (!response) {
     // Something bad happened in the method call.
@@ -251,6 +270,9 @@ DBusHandlerResult ExportedObject::HandleMessage(
   // The method call was successful.
   dbus_connection_send(connection, response->raw_message(), NULL);
   delete response;
+  // Record time spent to handle the the method call. Don't include failures.
+  UMA_HISTOGRAM_TIMES("DBus.ExportedMethodHandleTime",
+                      base::TimeTicks::Now() - start_time);
 
   return DBUS_HANDLER_RESULT_HANDLED;
 }
diff --git a/dbus/exported_object.h b/dbus/exported_object.h
index d9cda57..41e8eec 100644
--- a/dbus/exported_object.h
+++ b/dbus/exported_object.h
@@ -16,6 +16,7 @@
 #include "base/memory/ref_counted.h"
 #include "base/synchronization/waitable_event.h"
 #include "base/threading/platform_thread.h"
+#include "base/time.h"
 
 class MessageLoop;
 
@@ -106,7 +107,8 @@ class ExportedObject : public base::RefCountedThreadSafe<ExportedObject> {
                   bool success);
 
   // Helper function for SendSignal().
-  void SendSignalInternal(void* signal_message);
+  void SendSignalInternal(base::TimeTicks start_time,
+                          void* signal_message);
 
   // Registers this object to the bus.
   // Returns true on success, or the object is already registered.
diff --git a/dbus/object_proxy.cc b/dbus/object_proxy.cc
index fdb7b27..faeee0e 100644
--- a/dbus/object_proxy.cc
+++ b/dbus/object_proxy.cc
@@ -7,6 +7,7 @@
 #include "base/bind.h"
 #include "base/logging.h"
 #include "base/message_loop.h"
+#include "base/metrics/histogram.h"
 #include "base/stringprintf.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
@@ -16,6 +17,9 @@
 
 namespace {
 
+// Used for success ratio histograms. 1 for success, 0 for failure.
+const int kSuccessRatioHistogramMaxValue = 2;
+
 // Gets the absolute signal name by concatenating the interface name and
 // the signal name. Used for building keys for method_table_ in
 // ObjectProxy.
@@ -58,14 +62,22 @@ Response* ObjectProxy::CallMethodAndBlock(MethodCall* method_call,
   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);
 
   if (!response_message) {
     LOG(ERROR) << "Failed to call method: "
                << (error.is_set() ? error.message() : "");
     return NULL;
   }
+  // Record time spent for the method call. Don't include failures.
+  UMA_HISTOGRAM_TIMES("DBus.SyncMethodCallTime",
+                      base::TimeTicks::Now() - start_time);
 
   return Response::FromRawMessage(response_message);
 }
@@ -86,11 +98,13 @@ void ObjectProxy::CallMethod(MethodCall* method_call,
   // Bind() won't compile if we pass request_message as-is since
   // DBusMessage is an opaque struct which Bind() cannot handle.
   // Hence we cast it to void* to workaround the issue.
+  const base::TimeTicks start_time = base::TimeTicks::Now();
   base::Closure task = base::Bind(&ObjectProxy::StartAsyncMethodCall,
                                   this,
                                   timeout_ms,
                                   static_cast<void*>(request_message),
-                                  callback);
+                                  callback,
+                                  start_time);
   // Wait for the response in the D-Bus thread.
   bus_->PostTaskToDBusThread(FROM_HERE, task);
 }
@@ -128,9 +142,11 @@ void ObjectProxy::Detach() {
 
 ObjectProxy::OnPendingCallIsCompleteData::OnPendingCallIsCompleteData(
     ObjectProxy* in_object_proxy,
-    ResponseCallback in_response_callback)
+    ResponseCallback in_response_callback,
+    base::TimeTicks in_start_time)
     : object_proxy(in_object_proxy),
-      response_callback(in_response_callback) {
+      response_callback(in_response_callback),
+      start_time(in_start_time) {
 }
 
 ObjectProxy::OnPendingCallIsCompleteData::~OnPendingCallIsCompleteData() {
@@ -138,7 +154,8 @@ ObjectProxy::OnPendingCallIsCompleteData::~OnPendingCallIsCompleteData() {
 
 void ObjectProxy::StartAsyncMethodCall(int timeout_ms,
                                        void* in_request_message,
-                                       ResponseCallback response_callback) {
+                                       ResponseCallback response_callback,
+                                       base::TimeTicks start_time) {
   bus_->AssertOnDBusThread();
 
   if (!bus_->Connect() || !bus_->SetUpAsyncOperations()) {
@@ -148,6 +165,7 @@ void ObjectProxy::StartAsyncMethodCall(int timeout_ms,
     base::Closure task = base::Bind(&ObjectProxy::RunResponseCallback,
                                     this,
                                     response_callback,
+                                    start_time,
                                     response);
     bus_->PostTaskToOriginThread(FROM_HERE, task);
     return;
@@ -162,7 +180,7 @@ void ObjectProxy::StartAsyncMethodCall(int timeout_ms,
   // Prepare the data we'll be passing to OnPendingCallIsCompleteThunk().
   // The data will be deleted in OnPendingCallIsCompleteThunk().
   OnPendingCallIsCompleteData* data =
-      new OnPendingCallIsCompleteData(this, response_callback);
+      new OnPendingCallIsCompleteData(this, response_callback, start_time);
 
   // This returns false only when unable to allocate memory.
   const bool success = dbus_pending_call_set_notify(
@@ -178,7 +196,8 @@ void ObjectProxy::StartAsyncMethodCall(int timeout_ms,
 }
 
 void ObjectProxy::OnPendingCallIsComplete(DBusPendingCall* pending_call,
-                                          ResponseCallback response_callback) {
+                                          ResponseCallback response_callback,
+                                          base::TimeTicks start_time) {
   bus_->AssertOnDBusThread();
 
   DBusMessage* response_message = dbus_pending_call_steal_reply(pending_call);
@@ -188,16 +207,19 @@ void ObjectProxy::OnPendingCallIsComplete(DBusPendingCall* pending_call,
   base::Closure task = base::Bind(&ObjectProxy::RunResponseCallback,
                                   this,
                                   response_callback,
+                                  start_time,
                                   static_cast<void*>(response_message));
   bus_->PostTaskToOriginThread(FROM_HERE, task);
 }
 
 void ObjectProxy::RunResponseCallback(ResponseCallback response_callback,
+                                      base::TimeTicks start_time,
                                       void* in_response_message) {
   bus_->AssertOnOriginThread();
   DBusMessage* response_message =
       static_cast<DBusMessage*>(in_response_message);
 
+  bool response_callback_called = false;
   if (!response_message) {
     // The response is not received.
     response_callback.Run(NULL);
@@ -220,7 +242,15 @@ void ObjectProxy::RunResponseCallback(ResponseCallback response_callback,
         dbus::Response::FromRawMessage(response_message));
     // The response is successfully received.
     response_callback.Run(response.get());
+    response_callback_called = true;
+    // Record time spent for the method call. Don't include failures.
+    UMA_HISTOGRAM_TIMES("DBus.AsyncMethodCallTime",
+                        base::TimeTicks::Now() - start_time);
   }
+  // Record if the method call is successful, or not. 1 if successful.
+  UMA_HISTOGRAM_ENUMERATION("DBus.AsyncMethodCallSuccess",
+                            response_callback_called,
+                            kSuccessRatioHistogramMaxValue);
 }
 
 void ObjectProxy::OnPendingCallIsCompleteThunk(DBusPendingCall* pending_call,
@@ -229,7 +259,8 @@ void ObjectProxy::OnPendingCallIsCompleteThunk(DBusPendingCall* pending_call,
       reinterpret_cast<OnPendingCallIsCompleteData*>(user_data);
   ObjectProxy* self = data->object_proxy;
   self->OnPendingCallIsComplete(pending_call,
-                                data->response_callback);
+                                data->response_callback,
+                                data->start_time);
   delete data;
 }
 
@@ -317,15 +348,16 @@ DBusHandlerResult ObjectProxy::HandleMessage(
   const std::string interface = signal->GetInterface();
   const std::string member = signal->GetMember();
 
-  // Check if we know about the method.
+  // 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 method.
+    // Don't know about the signal.
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
   }
 
+  const base::TimeTicks start_time = base::TimeTicks::Now();
   if (bus_->HasDBusThread()) {
     // Post a task to run the method in the origin thread.
     // Transfer the ownership of |signal| to RunMethod().
@@ -334,24 +366,30 @@ DBusHandlerResult ObjectProxy::HandleMessage(
     bus_->PostTaskToOriginThread(FROM_HERE,
                                  base::Bind(&ObjectProxy::RunMethod,
                                             this,
+                                            start_time,
                                             iter->second,
                                             released_signal));
   } else {
-    // If the D-Bus thread is not used, just call the method directly. We
-    // don't need the complicated logic to wait for the method call to be
-    // complete.
-    iter->second.Run(signal.get());
+    const base::TimeTicks start_time = base::TimeTicks::Now();
+    // If the D-Bus thread is not used, just call the callback on the
+    // current thread. Transfer the ownership of |signal| to RunMethod().
+    Signal* released_signal = signal.release();
+    RunMethod(start_time, iter->second, released_signal);
   }
 
   return DBUS_HANDLER_RESULT_HANDLED;
 }
 
-void ObjectProxy::RunMethod(SignalCallback signal_callback,
+void ObjectProxy::RunMethod(base::TimeTicks start_time,
+                            SignalCallback signal_callback,
                             Signal* signal) {
   bus_->AssertOnOriginThread();
 
   signal_callback.Run(signal);
   delete signal;
+  // Record time spent for handling the signal.
+  UMA_HISTOGRAM_TIMES("DBus.SignalHandleTime",
+                      base::TimeTicks::Now() - start_time);
 }
 
 DBusHandlerResult ObjectProxy::HandleMessageThunk(
diff --git a/dbus/object_proxy.h b/dbus/object_proxy.h
index f75e330..ffd59c2 100644
--- a/dbus/object_proxy.h
+++ b/dbus/object_proxy.h
@@ -13,6 +13,7 @@
 
 #include "base/callback.h"
 #include "base/memory/ref_counted.h"
+#include "base/time.h"
 
 class MessageLoop;
 
@@ -116,25 +117,30 @@ class ObjectProxy : public base::RefCountedThreadSafe<ObjectProxy> {
   // OnPendingCallIsCompleteThunk().
   struct OnPendingCallIsCompleteData {
     OnPendingCallIsCompleteData(ObjectProxy* in_object_proxy,
-                                ResponseCallback in_response_callback);
+                                ResponseCallback in_response_callback,
+                                base::TimeTicks start_time);
     ~OnPendingCallIsCompleteData();
 
     ObjectProxy* object_proxy;
     ResponseCallback response_callback;
+    base::TimeTicks start_time;
   };
 
   // Starts the async method call. This is a helper function to implement
   // CallMethod().
   void StartAsyncMethodCall(int timeout_ms,
                             void* request_message,
-                            ResponseCallback response_callback);
+                            ResponseCallback response_callback,
+                            base::TimeTicks start_time);
 
   // Called when the pending call is complete.
   void OnPendingCallIsComplete(DBusPendingCall* pending_call,
-                               ResponseCallback response_callback);
+                               ResponseCallback response_callback,
+                               base::TimeTicks start_time);
 
   // Runs the response callback with the given response object.
   void RunResponseCallback(ResponseCallback response_callback,
+                           base::TimeTicks start_time,
                            void* response_message);
 
   // Redirects the function call to OnPendingCallIsComplete().
@@ -160,7 +166,9 @@ class ObjectProxy : public base::RefCountedThreadSafe<ObjectProxy> {
                                   DBusMessage* raw_message);
 
   // Runs the method. Helper function for HandleMessage().
-  void RunMethod(SignalCallback signal_callback, Signal* signal);
+  void RunMethod(base::TimeTicks start_time,
+                 SignalCallback signal_callback,
+                 Signal* signal);
 
   // Redirects the function call to HandleMessage().
   static DBusHandlerResult HandleMessageThunk(DBusConnection* connection,