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

1 files changed, 32 insertions, 5 deletions

diff --git a/chrome/browser/renderer_host/audio_renderer_host.cc b/chrome/browser/renderer_host/audio_renderer_host.cc
index 71bcff5..1a35be3 100644
--- a/chrome/browser/renderer_host/audio_renderer_host.cc
+++ b/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() {