Metrics to undestand output controller mismatch when running AudioService in- and out-of-process

The theory is that the count difference is due to different timing of
events when navigation happens during the output stream creation.
That situation would correspond to the cases when AudioOutputStreamBroker
is destroyed while its internal |disconnect_reason_| state is
DisconnectReason::kDocumentDestroyed.
We'll measure both probability of this situation as well as duration
of stream creation as seen by AudioOutputStreamBroker.

Bug: 867827
Change-Id: I226fd275b485cccbc3899ec4c6fa39232a719979
Reviewed-on: https://chromium-review.googlesource.com/1249841
Commit-Queue: Olga Sharonova <olka@chromium.org>
Reviewed-by: Max Morin <maxmorin@chromium.org>
Reviewed-by: Steven Holte <holte@chromium.org>
Cr-Commit-Position: refs/heads/master@{#595776}

content/browser/media/audio_output_stream_broker.cc

@@ -16,6 +16,48 @@
 
 namespace content {
 
+namespace {
+
+// Used in Media.Audio.Render.StreamBrokerDisconnectReason2 histogram, matches
+// StreamBrokerDisconnectReason2 enum.
+enum class StreamBrokerDisconnectReason {
+  kDefault = 0,
+  kPlatformError,
+  kTerminatedByClient,
+  kTerminatedByClientAwaitingCreated,
+  kStreamCreationFailed,
+  kDocumentDestroyed,
+  kDocumentDestroyedAwaitingCreated,
+  kMaxValue = kDocumentDestroyedAwaitingCreated
+};
+
+using DisconnectReason =
+    media::mojom::AudioOutputStreamObserver::DisconnectReason;
+
+StreamBrokerDisconnectReason GetDisconnectReason(DisconnectReason reason,
+                                                 bool awaiting_created) {
+  switch (reason) {
+    case DisconnectReason::kPlatformError:
+      return StreamBrokerDisconnectReason::kPlatformError;
+    case DisconnectReason::kTerminatedByClient:
+      return awaiting_created
+                 ? StreamBrokerDisconnectReason::
+                       kTerminatedByClientAwaitingCreated
+                 : StreamBrokerDisconnectReason::kTerminatedByClient;
+    case DisconnectReason::kStreamCreationFailed:
+      return StreamBrokerDisconnectReason::kStreamCreationFailed;
+    case DisconnectReason::kDocumentDestroyed:
+      return awaiting_created
+                 ? StreamBrokerDisconnectReason::
+                       kDocumentDestroyedAwaitingCreated
+                 : StreamBrokerDisconnectReason::kDocumentDestroyed;
+    case DisconnectReason::kDefault:
+      return StreamBrokerDisconnectReason::kDefault;
+  }
+}
+
+}  // namespace
+
 AudioOutputStreamBroker::AudioOutputStreamBroker(
     int render_process_id,
     int render_frame_id,
@@ -49,23 +91,34 @@ AudioOutputStreamBroker::AudioOutputStreamBroker(
     media_observer->OnCreatingAudioStream(render_process_id, render_frame_id);
 
   // Unretained is safe because |this| owns |client_|
-  client_.set_connection_error_handler(base::BindOnce(
-      &AudioOutputStreamBroker::ClientBindingLost, base::Unretained(this)));
+  client_.set_connection_error_handler(
+      base::BindOnce(&AudioOutputStreamBroker::Cleanup, base::Unretained(this),
+                     DisconnectReason::kTerminatedByClient));
 }
 
 AudioOutputStreamBroker::~AudioOutputStreamBroker() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
 
-  if (awaiting_created_) {
+  const StreamBrokerDisconnectReason reason =
+      GetDisconnectReason(disconnect_reason_, AwaitingCreated());
+
+  if (AwaitingCreated()) {
     TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
                                     "failed or cancelled");
   }
+
   TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "AudioOutputStreamBroker", this,
                                   "disconnect reason",
-                                  static_cast<uint32_t>(disconnect_reason_));
+                                  static_cast<uint32_t>(reason));
+
+  UMA_HISTOGRAM_ENUMERATION("Media.Audio.Render.StreamBrokerDisconnectReason2",
+                            reason);
 
-  UMA_HISTOGRAM_ENUMERATION("Media.Audio.Render.StreamBrokerDisconnectReason",
-                            disconnect_reason_);
+  if (AwaitingCreated()) {
+    UMA_HISTOGRAM_TIMES(
+        "Media.Audio.Render.StreamBrokerDocumentDestroyedAwaitingCreatedTime",
+        base::TimeTicks::Now() - stream_creation_start_time_);
+  }
 }
 
 void AudioOutputStreamBroker::CreateStream(
@@ -74,7 +127,7 @@ void AudioOutputStreamBroker::CreateStream(
   DCHECK(!observer_binding_.is_bound());
   TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("audio", "CreateStream", this, "device id",
                                     output_device_id_);
-  awaiting_created_ = true;
+  stream_creation_start_time_ = base::TimeTicks::Now();
 
   // Set up observer ptr. Unretained is safe because |this| owns
   // |observer_binding_|.
@@ -107,16 +160,15 @@ void AudioOutputStreamBroker::StreamCreated(
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
                                   !!data_pipe);
-  awaiting_created_ = false;
+  UMA_HISTOGRAM_TIMES("Media.Audio.Render.StreamBrokerStreamCreationTime",
+                      base::TimeTicks::Now() - stream_creation_start_time_);
+  stream_creation_start_time_ = base::TimeTicks();
+
   if (!data_pipe) {
     // Stream creation failed. Signal error.
     client_.ResetWithReason(
-        static_cast<uint32_t>(media::mojom::AudioOutputStreamObserver::
-                                  DisconnectReason::kPlatformError),
-        std::string());
-    disconnect_reason_ = media::mojom::AudioOutputStreamObserver::
-        DisconnectReason::kStreamCreationFailed;
-    Cleanup();
+        static_cast<uint32_t>(DisconnectReason::kPlatformError), std::string());
+    Cleanup(DisconnectReason::kStreamCreationFailed);
     return;
   }
 
@@ -127,39 +179,31 @@ void AudioOutputStreamBroker::ObserverBindingLost(
     uint32_t reason,
     const std::string& description) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
-
   TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("audio", "ObserverBindingLost", this,
                                       "reset reason", reason);
-  const uint32_t maxValidReason = static_cast<uint32_t>(
-      media::mojom::AudioOutputStreamObserver::DisconnectReason::kMaxValue);
-  if (reason > maxValidReason) {
+  if (reason > static_cast<uint32_t>(DisconnectReason::kMaxValue))
     NOTREACHED() << "Invalid reason: " << reason;
-  } else if (disconnect_reason_ == media::mojom::AudioOutputStreamObserver::
-                                       DisconnectReason::kDocumentDestroyed) {
-    disconnect_reason_ =
-        static_cast<media::mojom::AudioOutputStreamObserver::DisconnectReason>(
-            reason);
-  }
+
+  DisconnectReason reason_enum = static_cast<DisconnectReason>(reason);
 
   // TODO(https://crbug.com/787806): Don't propagate errors if we can retry
   // instead.
   client_.ResetWithReason(
-      static_cast<uint32_t>(media::mojom::AudioOutputStreamObserver::
-                                DisconnectReason::kPlatformError),
-      std::string());
-
-  Cleanup();
+      static_cast<uint32_t>(DisconnectReason::kPlatformError), std::string());
+  Cleanup((reason_enum == DisconnectReason::kPlatformError && AwaitingCreated())
+              ? DisconnectReason::kStreamCreationFailed
+              : reason_enum);
 }
 
-void AudioOutputStreamBroker::ClientBindingLost() {
-  disconnect_reason_ = media::mojom::AudioOutputStreamObserver::
-      DisconnectReason::kTerminatedByClient;
-  Cleanup();
-}
-
-void AudioOutputStreamBroker::Cleanup() {
+void AudioOutputStreamBroker::Cleanup(DisconnectReason reason) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  DCHECK_EQ(DisconnectReason::kDocumentDestroyed, disconnect_reason_);
+  disconnect_reason_ = reason;
   std::move(deleter_).Run(this);
 }
 
+bool AudioOutputStreamBroker::AwaitingCreated() const {
+  return stream_creation_start_time_ != base::TimeTicks();
+}
+
 }  // namespace content

content/browser/media/audio_output_stream_broker.h

@@ -44,11 +44,14 @@ class CONTENT_EXPORT AudioOutputStreamBroker final : public AudioStreamBroker {
   void CreateStream(audio::mojom::StreamFactory* factory) final;
 
  private:
+  using DisconnectReason =
+      media::mojom::AudioOutputStreamObserver::DisconnectReason;
+
   void StreamCreated(media::mojom::AudioOutputStreamPtr stream,
                      media::mojom::ReadWriteAudioDataPipePtr data_pipe);
   void ObserverBindingLost(uint32_t reason, const std::string& description);
-  void ClientBindingLost();
-  void Cleanup();
+  void Cleanup(DisconnectReason reason);
+  bool AwaitingCreated() const;
 
   SEQUENCE_CHECKER(owning_sequence_);
 
@@ -57,8 +60,8 @@ class CONTENT_EXPORT AudioOutputStreamBroker final : public AudioStreamBroker {
   const base::UnguessableToken group_id_;
   const base::Optional<base::UnguessableToken> processing_id_;
 
-  // Indicates that CreateStream has been called, but not StreamCreated.
-  bool awaiting_created_ = false;
+  // Set while CreateStream() has been called, but not StreamCreated().
+  base::TimeTicks stream_creation_start_time_;
 
   DeleterCallback deleter_;
 
@@ -68,9 +71,7 @@ class CONTENT_EXPORT AudioOutputStreamBroker final : public AudioStreamBroker {
   mojo::AssociatedBinding<media::mojom::AudioOutputStreamObserver>
       observer_binding_;
 
-  media::mojom::AudioOutputStreamObserver::DisconnectReason disconnect_reason_ =
-      media::mojom::AudioOutputStreamObserver::DisconnectReason::
-          kDocumentDestroyed;
+  DisconnectReason disconnect_reason_ = DisconnectReason::kDocumentDestroyed;
 
   base::WeakPtrFactory<AudioOutputStreamBroker> weak_ptr_factory_;
 

tools/metrics/histograms/enums.xml

@@ -2216,6 +2216,16 @@ uploading your change for review.  These are checked by presubmit scripts.
   <int value="4" label="Document destroyed"/>
 </enum>
 
+<enum name="AudioOutputStreamDisconnectReason2">
+  <int value="0" label="Default"/>
+  <int value="1" label="Platform error"/>
+  <int value="2" label="Terminated by client"/>
+  <int value="3" label="Terminated by client during stream creation"/>
+  <int value="4" label="Stream creation failed"/>
+  <int value="5" label="Document destroyed"/>
+  <int value="6" label="Document destroyed during stream creation"/>
+</enum>
+
 <enum name="AudioRenderDeviceError">
   <int value="0" label="No error"/>
   <int value="1" label="Error during stream creation"/>

tools/metrics/histograms/histograms.xml

@@ -41872,6 +41872,10 @@ uploading your change for review.
 
 <histogram name="Media.Audio.Render.StreamBrokerDisconnectReason"
     enum="AudioOutputStreamDisconnectReason" expires_after="2019-02-01">
+  <obsolete>
+    Deprecated 09/2018, and replaced by
+    Media.Audio.Render.StreamBrokerDisconnectReason2.
+  </obsolete>
   <owner>jonasolsson@chromium.org</owner>
   <owner>maxmorin@chromium.org</owner>
   <owner>olka@chromium.org</owner>
@@ -41881,6 +41885,40 @@ uploading your change for review.
   </summary>
 </histogram>
 
+<histogram name="Media.Audio.Render.StreamBrokerDisconnectReason2"
+    enum="AudioOutputStreamDisconnectReason2" expires_after="2019-02-01">
+  <owner>jonasolsson@chromium.org</owner>
+  <owner>maxmorin@chromium.org</owner>
+  <owner>olka@chromium.org</owner>
+  <summary>
+    Describes why and in which state an audio output stream ended.
+  </summary>
+</histogram>
+
+<histogram
+    name="Media.Audio.Render.StreamBrokerDocumentDestroyedAwaitingCreatedTime"
+    units="ms" expires_after="2019-02-01">
+  <owner>olka@chromium.org</owner>
+  <owner>marinaciocea@chromium.org</owner>
+  <owner>maxmorin@chromium.org</owner>
+  <summary>
+    If the document was destroyed after the broker requested the output stream
+    from the audio service, but before it received the reply: how long ago the
+    stream was requested.
+  </summary>
+</histogram>
+
+<histogram name="Media.Audio.Render.StreamBrokerStreamCreationTime" units="ms"
+    expires_after="2019-02-01">
+  <owner>olka@chromium.org</owner>
+  <owner>marinaciocea@chromium.org</owner>
+  <owner>maxmorin@chromium.org</owner>
+  <summary>
+    Time interval between the moment the broker requested the output stream from
+    the audio service, and the moment it received the reply.
+  </summary>
+</histogram>
+
 <histogram name="Media.Audio.Render.StreamCallbackError" enum="BooleanError">
   <obsolete>
     Replaced by Media.Audio.Render.StreamCallbackError2