Measure IPC latency for audio...

chrome/browser/renderer_host/audio_renderer_host.cc

 // Copyright (c) 2006-2009 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 "base/histogram.h"
 #include "base/lock.h"
 #include "base/message_loop.h"
 #include "base/process.h"
 #include "base/shared_memory.h"
 #include "base/waitable_event.h"
 #include "chrome/browser/renderer_host/audio_renderer_host.h"
+#include "chrome/common/ipc_logging.h"
 #include "chrome/common/render_messages.h"
 
 namespace {
 
-void RecordIPCAudioLatency(base::TimeDelta latency) {
-  // Create a histogram of minimum 1ms and maximum 1000ms with 100 buckets.
-  static ThreadSafeHistogram histogram("Audio.IPCTransportLatency",
+void RecordRoundTripLatency(base::TimeDelta latency) {
+  static ThreadSafeHistogram histogram("Audio.IPC_RoundTripLatency",
                                        1, 1000, 100);
   histogram.AddTime(latency);
 }
 
+void RecordReceiveLatency(base::TimeDelta latency) {
+  static ThreadSafeHistogram histogram("Audio.IPC_Browser_ReceiveLatency",
+                                       1, 500, 100);
+  histogram.AddTime(latency);
+}
+
+void RecordProcessTime(base::TimeDelta latency) {
+  static ThreadSafeHistogram histogram("Audio.IPC_Browser_ProcessTime",
+                                       1, 100, 100);
+  histogram.AddTime(latency);
+}
+
 }  // namespace
 
 //-----------------------------------------------------------------------------
 // AudioRendererHost::IPCAudioSource implementations.
 
 AudioRendererHost::IPCAudioSource::IPCAudioSource(
     AudioRendererHost* host,
     int process_id,
     int route_id,
     int stream_id,
@@ skipping 112 matching lines @@
     return;
   double left_channel, right_channel;
   stream_->GetVolume(&left_channel, &right_channel);
   host_->Send(new ViewMsg_NotifyAudioStreamVolume(route_id_, stream_id_,
                                                   left_channel, right_channel));
 }
 
 size_t AudioRendererHost::IPCAudioSource::OnMoreData(AudioOutputStream* stream,
                                                      void* dest,
                                                      size_t max_size) {
-  base::TimeTicks tick_start = base::TimeTicks::HighResNow();
+#ifdef IPC_MESSAGE_LOG_ENABLED

[scherkus (not reviewing), 2009/04/30 02:15:10]

do you know how we get this defined?

+  base::Time tick_start = base::Time::Now();

[scherkus (not reviewing), 2009/04/30 02:15:10]

curious... why not HighResNow?

+#endif
   {
     AutoLock auto_lock(lock_);
     // If we are ever stopped, don't ask for more audio packet from the
     // renderer.
     if (stop_providing_packets_)
       return 0;
   }
 
   // If we have an initial packet, use it immediately only in IO thread.
   // There's a case when IO thread is blocked and audio hardware thread can
@@ skipping 22 matching lines @@
   packet_read_event_.Wait();
 
   size_t last_packet_size = 0;
   {
      AutoLock auto_lock(lock_);
      last_packet_size = last_packet_size_;
   }
 
   size_t copied = SafeCopyBuffer(dest, max_size,
                                  shared_memory_.memory(), last_packet_size);
-  RecordIPCAudioLatency(base::TimeTicks::HighResNow() - tick_start);
+#ifdef IPC_MESSAGE_LOG_ENABLED
+  // The logging to round trip latency doesn't have dependency on IPC logging.
+  // But it's good we use IPC logging to trigger logging of total latency.
+  if (IPC::Logging::current()->Enabled())
+    RecordRoundTripLatency(base::Time::Now() - tick_start);
+#endif
   return copied;
 }
 
 void AudioRendererHost::IPCAudioSource::OnClose(AudioOutputStream* stream) {
   StopWaitingForPacket();
 }
 
 void AudioRendererHost::IPCAudioSource::OnError(AudioOutputStream* stream,
                                                 int code) {
   host_->SendErrorMessage(route_id_, stream_id_, code);
@@ skipping 197 matching lines @@
 
 void AudioRendererHost::OnNotifyPacketReady(const IPC::Message& msg,
                                             int stream_id, size_t packet_size) {
   DCHECK(MessageLoop::current() == io_loop_);
   IPCAudioSource* source = Lookup(msg.routing_id(), stream_id);
   if (source) {
     source->NotifyPacketReady(packet_size);
   } else {
     SendErrorMessage(msg.routing_id(), stream_id, 0);
   }
+#ifdef IPC_MESSAGE_LOG_ENABLED
+  if (IPC::Logging::current()->Enabled()) {
+    RecordReceiveLatency(base::Time::FromInternalValue(msg.received_time()) -
+                         base::Time::FromInternalValue(msg.sent_time()));
+    RecordProcessTime(base::Time::Now() -
+                      base::Time::FromInternalValue(msg.received_time()));
+  }
+#endif
 }
 
 void AudioRendererHost::OnInitialized() {
   DCHECK(MessageLoop::current() == io_loop_);
   // Increase the ref count of this object so it is active until we do
   // Release().
   AddRef();
 }
 
 void AudioRendererHost::OnDestroyed() {
@@ skipping 65 matching lines @@
   if (MessageLoop::current() == io_loop_) {
     OnDestroySource(source);
   } else {
     // TODO(hclam): make sure it's always safe to post a task to IO loop.
     // It is possible that IO message loop is destroyed but there's still some
     // dangling audio hardware threads that try to call this method.
     io_loop_->PostTask(FROM_HERE,
       NewRunnableMethod(this, &AudioRendererHost::OnDestroySource, source));
   }
 }