Add some histograms to the D-Bus library:

dbus/exported_object.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/exported_object.h"
 
 #include "base/bind.h"
 #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"
 #include "dbus/message.h"
 #include "dbus/scoped_dbus_error.h"
 
 namespace dbus {
 
 namespace {
 
@@ skipping 72 matching lines @@
   // For signals, the object path should be set to the path to the sender
   // object, which is this exported object here.
   signal->SetPath(object_path_);
 
   // Increment the reference count so we can safely reference the
   // underlying signal message until the signal sending is complete. This
   // will be unref'ed in SendSignalInternal().
   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)));
 }
 
 void ExportedObject::Unregister() {
   bus_->AssertOnDBusThread();
 
   if (!object_is_registered_)
     return;
 
   bus_->UnregisterObjectPath(object_path_);
@@ skipping 21 matching lines @@
 
 void ExportedObject::OnExported(OnExportedCallback on_exported_callback,
                                 const std::string& interface_name,
                                 const std::string& method_name,
                                 bool success) {
   bus_->AssertOnOriginThread();
 
   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() {
   bus_->AssertOnDBusThread();
 
   if (object_is_registered_)
     return true;
 
   ScopedDBusError error;
 
@@ skipping 23 matching lines @@
   // raw_message will be unrefed on exit of the function. Increment the
   // reference so we can use it in MethodCall.
   dbus_message_ref(raw_message);
   scoped_ptr<MethodCall> method_call(
       MethodCall::FromRawMessage(raw_message));
   const std::string interface = method_call->GetInterface();
   const std::string member = method_call->GetMember();
 
   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;
   }
 
   // Check if we know about the method.
   const std::string absolute_method_name = GetAbsoluteMethodName(
       interface, member);
   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;
     // Post a task to run the method in the origin thread.
     bus_->PostTaskToOriginThread(FROM_HERE,
                                  base::Bind(&ExportedObject::RunMethod,
                                             this,
                                             iter->second,
                                             method_call.get()));
     // Wait until the method call is done. Blocking is not desirable but we
@@ skipping 10 matching lines @@
       // infinitely in the origin thread. No way to stop it from here.
       CHECK(signaled) << "Method " << absolute_method_name << " not called";
     }
     response = response_from_method_;
   } 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.
     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, 2);

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

nit: What does the '2' refer to?

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

2 means this enumeration histogram takes values less than 2: 0 or 1. Any ideas
on how to make it clearer?

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

const int histogram_max_value = 2;
On the other hand, it's just a histogram, so '2' is probably fine.

[satorux1, 2011/09/06 17:32:04]

You were right that 2 was cryptic. Introduced kSuccessRateHistogramMaxValue = 2
with some comment.

 
   if (!response) {
     // Something bad happened in the method call.
     scoped_ptr<dbus::ErrorResponse> error_response(
         ErrorResponse::FromMethodCall(method_call.get(),
                                       DBUS_ERROR_FAILED,
                                       "error occurred in " + member));
     dbus_connection_send(connection, error_response->raw_message(), NULL);
     return DBUS_HANDLER_RESULT_HANDLED;
   }
 
   // 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;
 }
 
 void ExportedObject::RunMethod(MethodCallCallback method_call_callback,
                                MethodCall* method_call) {
   bus_->AssertOnOriginThread();
 
   response_from_method_ = method_call_callback.Run(method_call);
   on_method_is_called_.Signal();
@@ skipping 10 matching lines @@
   return self->HandleMessage(connection, raw_message);
 }
 
 void ExportedObject::OnUnregisteredThunk(DBusConnection *connection,
                                          void* user_data) {
   ExportedObject* self = reinterpret_cast<ExportedObject*>(user_data);
   return self->OnUnregistered(connection);
 }
 
 }  // namespace dbus