Measure IPC latency for audio

With this patch there's totally 5 measurements for audio IPC
1. Total round trip time
   browser request a packet until it gets a packet
2. Browser receive latency
   time for a packet to arrive browser from renderer
3. Browser process time
   time for browser to process the packet
4. Renderer receive latency
   time for a packet to arrive renderer from browser
5. Renderer process time
   process time on a packet in renderer

They are all using low resolution timer with accuracy of ~1-15ms.
Since we have a budget of ~200ms (for now) without clicks, I think
the accuracy shouldn't be a big problem, unless for case 1 where
we want to measure exact amount of clicks.

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

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

chrome/browser/renderer_host/audio_renderer_host.cc

@@ -9,17 +9,29 @@
 #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
 
 //-----------------------------------------------------------------------------
@@ -152,7 +164,9 @@ void AudioRendererHost::IPCAudioSource::GetVolume() {
 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
+  base::Time tick_start = base::Time::Now();
+#endif
   {
     AutoLock auto_lock(lock_);
     // If we are ever stopped, don't ask for more audio packet from the
@@ -195,7 +209,12 @@ size_t AudioRendererHost::IPCAudioSource::OnMoreData(AudioOutputStream* stream,
 
   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;
 }
 
@@ -413,6 +432,14 @@ void AudioRendererHost::OnNotifyPacketReady(const IPC::Message& msg,
   } 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() {

chrome/renderer/audio_message_filter.cc

@@ -2,10 +2,28 @@
 // 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/message_loop.h"
+#include "chrome/common/ipc_logging.h"
 #include "chrome/common/render_messages.h"
 #include "chrome/renderer/audio_message_filter.h"
 
+namespace {
+
+void RecordReceiveLatency(base::TimeDelta latency) {
+  static ThreadSafeHistogram histogram("Audio.IPC_Renderer_ReceiveLatency",
+                                       1, 500, 100);
+  histogram.AddTime(latency);
+}
+
+void RecordProcessTime(base::TimeDelta latency) {
+  static ThreadSafeHistogram histogram("Audio.IPC_Renderer_ProcessTime",
+                                       1, 100, 100);
+  histogram.AddTime(latency);
+}
+
+}  // namespace
+
 AudioMessageFilter::AudioMessageFilter(int32 route_id)
     : channel_(NULL),
       route_id_(route_id),
@@ -55,14 +73,31 @@ void AudioMessageFilter::OnChannelClosing() {
   channel_ = NULL;
 }
 
-void AudioMessageFilter::OnRequestPacket(int stream_id) {
+void AudioMessageFilter::OnRequestPacket(const IPC::Message& msg,
+                                         int stream_id) {
   Delegate* delegate = delegates_.Lookup(stream_id);
   if (!delegate) {
     DLOG(WARNING) << "Got audio packet request for a non-existent or removed"
         " audio renderer.";
     return;
   }
+
+#ifdef IPC_MESSAGE_LOG_ENABLED
+  IPC::Logging* logger = IPC::Logging::current();
+  if (logger->Enabled()) {
+    RecordReceiveLatency(base::Time::FromInternalValue(msg.received_time()) -
+                         base::Time::FromInternalValue(msg.sent_time()));
+  }
+#endif
+
   delegate->OnRequestPacket();
+
+#ifdef IPC_MESSAGE_LOG_ENABLED
+  if (logger->Enabled()) {
+    RecordProcessTime(base::Time::Now() -
+                      base::Time::FromInternalValue(msg.received_time()));
+  }
+#endif
 }
 
 void AudioMessageFilter::OnStreamCreated(int stream_id,

chrome/renderer/audio_message_filter.h

@@ -55,7 +55,7 @@ class AudioMessageFilter : public IPC::ChannelProxy::MessageFilter {
   virtual void OnChannelClosing();
 
   // Received when browser process wants more audio packet.
-  void OnRequestPacket(int stream_id);
+  void OnRequestPacket(const IPC::Message& msg, int stream_id);
 
   // Received when browser process has created an audio output stream.
   void OnStreamCreated(int stream_id, base::SharedMemoryHandle handle,