Measure stream creation times in Mojo audio IPC

Media.Audio.Render.[Input|Output]DeviceStreamCreationTime measures the
time from stream creation starting until the StreamCreated callback
gets triggered.

Bug: chromium:672469
Cq-Include-Trybots: luci.chromium.try:android_optional_gpu_tests_rel;luci.chromium.try:linux_optional_gpu_tests_rel;luci.chromium.try:mac_optional_gpu_tests_rel;master.tryserver.chromium.win:win_optional_gpu_tests_rel
Change-Id: I32f50b8cf19afea7b97ae415fce17308085567bf
Reviewed-on: https://chromium-review.googlesource.com/1000855Reviewed-by: Max Morin <maxmorin@chromium.org>
Reviewed-by: Olga Sharonova <olka@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Commit-Queue: Jonas Olsson <jonasolsson@chromium.org>
Cr-Commit-Position: refs/heads/master@{#550138}

content/renderer/media/mojo_audio_input_ipc.cc

@@ -7,6 +7,7 @@
 #include <utility>
 
 #include "base/bind_helpers.h"
+#include "base/metrics/histogram_macros.h"
 #include "media/audio/audio_device_description.h"
 #include "mojo/public/cpp/system/platform_handle.h"
 
@@ -39,6 +40,7 @@ void MojoAudioInputIPC::CreateStream(media::AudioInputIPCDelegate* delegate,
   factory_client_binding_.set_connection_error_handler(base::BindOnce(
       &media::AudioInputIPCDelegate::OnError, base::Unretained(delegate_)));
 
+  stream_creation_start_time_ = base::TimeTicks::Now();
   stream_creator_.Run(std::move(client), session_id, params,
                       automatic_gain_control, total_segments);
 }
@@ -75,6 +77,9 @@ void MojoAudioInputIPC::StreamCreated(
   DCHECK(!stream_);
   DCHECK(!stream_client_binding_.is_bound());
 
+  UMA_HISTOGRAM_TIMES("Media.Audio.Render.InputDeviceStreamCreationTime",
+                      base::TimeTicks::Now() - stream_creation_start_time_);
+
   stream_ = std::move(stream);
   stream_client_binding_.Bind(std::move(stream_client_request));
 

content/renderer/media/mojo_audio_input_ipc.h

@@ -11,6 +11,7 @@
 #include "base/macros.h"
 #include "base/memory/weak_ptr.h"
 #include "base/sequence_checker.h"
+#include "base/time/time.h"
 #include "content/common/content_export.h"
 #include "content/common/media/renderer_audio_input_stream_factory.mojom.h"
 #include "media/audio/audio_input_ipc.h"
@@ -68,6 +69,8 @@ class CONTENT_EXPORT MojoAudioInputIPC
   mojo::Binding<RendererAudioInputStreamFactoryClient> factory_client_binding_;
   media::AudioInputIPCDelegate* delegate_ = nullptr;
 
+  base::TimeTicks stream_creation_start_time_;
+
   base::WeakPtrFactory<MojoAudioInputIPC> weak_factory_;
 
   DISALLOW_COPY_AND_ASSIGN(MojoAudioInputIPC);

content/renderer/media/mojo_audio_output_ipc.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/metrics/histogram_macros.h"
 #include "media/audio/audio_device_description.h"
 #include "mojo/public/cpp/bindings/callback_helpers.h"
 #include "mojo/public/cpp/system/platform_handle.h"
@@ -80,6 +81,7 @@ void MojoAudioOutputIPC::CreateStream(media::AudioOutputIPCDelegate* delegate,
   DCHECK_EQ(delegate_, delegate);
   // Since the creation callback won't fire if the provider binding is gone
   // and |this| owns |stream_provider_|, unretained is safe.
+  stream_creation_start_time_ = base::TimeTicks::Now();
   media::mojom::AudioOutputStreamClientPtr client_ptr;
   binding_.Bind(mojo::MakeRequest(&client_ptr));
   stream_provider_->Acquire(mojo::MakeRequest(&stream_), std::move(client_ptr),
@@ -198,6 +200,9 @@ void MojoAudioOutputIPC::StreamCreated(
   DCHECK(io_task_runner_->RunsTasksInCurrentSequence());
   DCHECK(delegate_);
 
+  UMA_HISTOGRAM_TIMES("Media.Audio.Render.OutputDeviceStreamCreationTime",
+                      base::TimeTicks::Now() - stream_creation_start_time_);
+
   base::PlatformFile socket_handle;
   auto result =
       mojo::UnwrapPlatformFile(std::move(data_pipe->socket), &socket_handle);

content/renderer/media/mojo_audio_output_ipc.h

@@ -10,6 +10,7 @@
 #include "base/callback_helpers.h"
 #include "base/macros.h"
 #include "base/memory/weak_ptr.h"
+#include "base/time/time.h"
 #include "content/common/content_export.h"
 #include "content/common/media/renderer_audio_output_stream_factory.mojom.h"
 #include "media/audio/audio_output_ipc.h"
@@ -80,6 +81,8 @@ class CONTENT_EXPORT MojoAudioOutputIPC
   media::AudioOutputIPCDelegate* delegate_ = nullptr;
   scoped_refptr<base::SingleThreadTaskRunner> io_task_runner_;
 
+  base::TimeTicks stream_creation_start_time_;
+
   // To make sure we don't send an "authorization completed" callback for a
   // stream after it's closed, we use this weak factory.
   base::WeakPtrFactory<MojoAudioOutputIPC> weak_factory_;

tools/metrics/histograms/histograms.xml

@@ -35273,6 +35273,17 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Media.Audio.Render.InputDeviceStreamCreationTime" units="ms">
+  <owner>jonasolsson@chromium.org</owner>
+  <owner>maxmorin@chromium.org</owner>
+  <owner>olka@chromium.org</owner>
+  <summary>
+    The time delta between the moment a MojoAudioInputIPC instance on the
+    renderer process requests a new stream from the browser to the moment it
+    receives a response.
+  </summary>
+</histogram>
+
 <histogram name="Media.Audio.Render.LargestGlitchMs" units="ms">
   <owner>tommi@chromium.org</owner>
   <summary>
@@ -35323,6 +35334,17 @@ http://cs/file:chrome/histograms.xml - but prefer this file for new entries.
   </summary>
 </histogram>
 
+<histogram name="Media.Audio.Render.OutputDeviceStreamCreationTime" units="ms">
+  <owner>jonasolsson@chromium.org</owner>
+  <owner>maxmorin@chromium.org</owner>
+  <owner>olka@chromium.org</owner>
+  <summary>
+    The time delta between the moment a MojoAudioInputIPC instance on the
+    renderer process requests a new stream from the browser to the moment it
+    receives a response.
+  </summary>
+</histogram>
+
 <histogram name="Media.Audio.Render.OutputStreamDuration" units="ms">
   <owner>maxmorin@chromium.org</owner>
   <summary>