Add some histograms to the D-Bus library:

dbus/object_proxy.cc

 // Copyright (c) 2011 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/stringprintf.h"
 #include "base/threading/thread.h"
 #include "base/threading/thread_restrictions.h"
 #include "dbus/message.h"
 #include "dbus/object_proxy.h"
 #include "dbus/scoped_dbus_error.h"
 
 namespace {
 
 // Gets the absolute signal name by concatenating the interface name and
@@ skipping 31 matching lines @@
   if (!bus_->Connect())
     return NULL;
 
   method_call->SetDestination(service_name_);
   method_call->SetPath(object_path_);
   DBusMessage* request_message = method_call->raw_message();
 
   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, 2);

[stevenjb, 2011/09/02 20:43:26]

nit: 2?

[satorux1, 2011/09/02 21:57:11]

commented n the other file.

 
   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);
 }
 
 void ObjectProxy::CallMethod(MethodCall* method_call,
                              int timeout_ms,
                              ResponseCallback callback) {
   bus_->AssertOnOriginThread();
 
   method_call->SetDestination(service_name_);
   method_call->SetPath(object_path_);
   // Increment the reference count so we can safely reference the
   // underlying request message until the method call is complete. This
   // will be unref'ed in StartAsyncMethodCall().
   DBusMessage* request_message = method_call->raw_message();
   dbus_message_ref(request_message);
 
   // 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);
 }
 
 void ObjectProxy::ConnectToSignal(const std::string& interface_name,
                                   const std::string& signal_name,
                                   SignalCallback signal_callback,
                                   OnConnectedCallback on_connected_callback) {
   bus_->AssertOnOriginThread();
 
@@ skipping 17 matching lines @@
     bus_->RemoveMatch(match_rules_[i], error.get());
     if (error.is_set()) {
       // There is nothing we can do to recover, so just print the error.
       LOG(ERROR) << "Failed to remove match rule: " << match_rules_[i];
     }
   }
 }
 
 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() {
 }
 
 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()) {
     // In case of a failure, run the callback with NULL response, that
     // indicates a failure.
     Response* response = NULL;
     base::Closure task = base::Bind(&ObjectProxy::RunResponseCallback,
                                     this,
                                     response_callback,
+                                    start_time,

[stevenjb, 2011/09/02 20:43:26]

We seem to be doing a lot of passing along start_time. Would it make sense to
store it in response_callback?

[satorux1, 2011/09/02 21:57:11]

You are right that passing along start_time a lot is rather annoying, but
response_callback is supplied from the caller, so we cannot add start_time to
it. Instead, we could introduce a struct to group response_callback and
start_time, but it wouldn't make the code clearer.

[stevenjb, 2011/09/06 16:51:04]

RIght, right, I was somehow thinking ResponseCallback was a struct already. I
agree that making it a struct isn't worth it. Passing along the start time is
awkward, but it's fine. 

                                     response);
     bus_->PostTaskToOriginThread(FROM_HERE, task);
     return;
   }
 
   DBusMessage* request_message =
       static_cast<DBusMessage*>(in_request_message);
   DBusPendingCall* pending_call = NULL;
 
   bus_->SendWithReply(request_message, &pending_call, 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(
       pending_call,
       &ObjectProxy::OnPendingCallIsCompleteThunk,
       data,
       NULL);
   CHECK(success) << "Unable to allocate memory";
   dbus_pending_call_unref(pending_call);
 
   // It's now safe to unref the request message.
   dbus_message_unref(request_message);
 }
 
 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);
   // |response_message| will be unref'ed in RunResponseCallback().
   // Bind() won't compile if we pass response_message as-is.
   // See CallMethod() for details.
   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);
   } else if (dbus_message_get_type(response_message) ==
              DBUS_MESSAGE_TYPE_ERROR) {
     // This will take |response_message| and release (unref) it.
     scoped_ptr<dbus::ErrorResponse> error_response(
         dbus::ErrorResponse::FromRawMessage(response_message));
     // Error message may contain the error message as string.
     dbus::MessageReader reader(error_response.get());
     std::string error_message;
     reader.PopString(&error_message);
     LOG(ERROR) << "Failed to call method: " << error_response->GetErrorName()
                << ": " << error_message;
     // We don't give the error message to the callback.
     response_callback.Run(NULL);
   } else {
     // This will take |response_message| and release (unref) it.
     scoped_ptr<dbus::Response> response(
         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, 2);
 }
 
 void ObjectProxy::OnPendingCallIsCompleteThunk(DBusPendingCall* pending_call,
                                                void* user_data) {
   OnPendingCallIsCompleteData* data =
       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;
 }
 
 void ObjectProxy::ConnectToSignalInternal(
     const std::string& interface_name,
     const std::string& signal_name,
     SignalCallback signal_callback,
     OnConnectedCallback on_connected_callback) {
   bus_->AssertOnDBusThread();
 
@@ skipping 67 matching lines @@
   scoped_ptr<Signal> signal(
       Signal::FromRawMessage(raw_message));
 
   // The signal is not coming from the remote object we are attaching to.
   if (signal->GetPath() != object_path_)
     return DBUS_HANDLER_RESULT_NOT_YET_HANDLED;
 
   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().
     // |released_signal| will be deleted in RunMethod().
     Signal* released_signal = signal.release();
     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(
     DBusConnection* connection,
     DBusMessage* raw_message,
     void* user_data) {
   ObjectProxy* self = reinterpret_cast<ObjectProxy*>(user_data);
   return self->HandleMessage(connection, raw_message);
 }
 
 }  // namespace dbus