Add tracing for audio service streams.

Bug: 845105
Change-Id: Id7dfb50a2e4b1539dfd92c62a127b29c31e65c16
Reviewed-on: https://chromium-review.googlesource.com/1065778
Commit-Queue: Max Morin <maxmorin@chromium.org>
Reviewed-by: Olga Sharonova <olka@chromium.org>
Cr-Commit-Position: refs/heads/master@{#561020}

content/browser/media/audio_input_stream_broker.cc

@@ -8,6 +8,7 @@
 
 #include "base/command_line.h"
 #include "base/memory/read_only_shared_memory_region.h"
+#include "base/trace_event/trace_event.h"
 #include "content/browser/browser_main_loop.h"
 #include "content/browser/media/media_internals.h"
 #include "content/public/browser/browser_thread.h"
@@ -47,6 +48,7 @@ AudioInputStreamBroker::AudioInputStreamBroker(
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DCHECK(renderer_factory_client_);
   DCHECK(deleter_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "AudioInputStreamBroker", this);
 
   // Unretained is safe because |this| owns |renderer_factory_client_|.
   renderer_factory_client_.set_connection_error_handler(
@@ -101,6 +103,12 @@ AudioInputStreamBroker::~AudioInputStreamBroker() {
     process_host->OnMediaStreamRemoved();
 
   // TODO(https://crbug.com/829317) update tab recording indicator.
+
+  if (awaiting_created_) {
+    TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
+                                    "failed or cancelled");
+  }
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "AudioInputStreamBroker", this);
 }
 
 void AudioInputStreamBroker::CreateStream(
@@ -108,6 +116,9 @@ void AudioInputStreamBroker::CreateStream(
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DCHECK(!observer_binding_.is_bound());
   DCHECK(!client_request_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("audio", "CreateStream", this, "device id",
+                                    device_id_);
+  awaiting_created_ = true;
 
   base::ReadOnlySharedMemoryRegion key_press_count_buffer;
   if (user_input_monitor_) {
@@ -157,6 +168,9 @@ void AudioInputStreamBroker::StreamCreated(
     bool initially_muted,
     const base::Optional<base::UnguessableToken>& stream_id) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  awaiting_created_ = false;
+  TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
+                                  !!data_pipe);
 
   if (!data_pipe) {
     Cleanup();

content/browser/media/audio_input_stream_broker.h

@@ -60,6 +60,9 @@ class CONTENT_EXPORT AudioInputStreamBroker final
   const bool enable_agc_;
   media::UserInputMonitorBase* user_input_monitor_ = nullptr;
 
+  // Indicates that CreateStream has been called, but not StreamCreated.
+  bool awaiting_created_ = false;
+
   DeleterCallback deleter_;
 
   mojom::RendererAudioInputStreamFactoryClientPtr renderer_factory_client_;

content/browser/media/audio_output_stream_broker.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "content/browser/media/media_internals.h"
 #include "content/public/browser/content_browser_client.h"
 #include "content/public/browser/media_observer.h"
@@ -35,6 +36,7 @@ AudioOutputStreamBroker::AudioOutputStreamBroker(
   DCHECK(client_);
   DCHECK(deleter_);
   DCHECK(group_id_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "AudioOutputStreamBroker", this);
 
   MediaObserver* media_observer =
       GetContentClient()->browser()->GetMediaObserver();
@@ -50,12 +52,21 @@ AudioOutputStreamBroker::AudioOutputStreamBroker(
 
 AudioOutputStreamBroker::~AudioOutputStreamBroker() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+
+  if (awaiting_created_) {
+    TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
+                                    "failed or cancelled");
+  }
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "AudioOutputStreamBroker", this);
 }
 
 void AudioOutputStreamBroker::CreateStream(
     audio::mojom::StreamFactory* factory) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(!observer_binding_.is_bound());
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN1("audio", "CreateStream", this, "device id",
+                                    output_device_id_);
+  awaiting_created_ = true;
 
   // Set up observer ptr. Unretained is safe because |this| owns
   // |observer_binding_|.
@@ -86,6 +97,9 @@ void AudioOutputStreamBroker::StreamCreated(
     media::mojom::AudioOutputStreamPtr stream,
     media::mojom::AudioDataPipePtr data_pipe) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_END1("audio", "CreateStream", this, "success",
+                                  !!data_pipe);
+  awaiting_created_ = false;
   if (!data_pipe) {
     // Stream creation failed. Signal error.
     client_.ResetWithReason(media::mojom::AudioOutputStreamProviderClient::
@@ -102,6 +116,10 @@ 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);
+
   // TODO(https://crbug.com/787806): Don't propagate errors if we can retry
   // instead.
   client_.ResetWithReason(media::mojom::AudioOutputStreamProviderClient::

content/browser/media/audio_output_stream_broker.h

@@ -54,6 +54,9 @@ class CONTENT_EXPORT AudioOutputStreamBroker final : public AudioStreamBroker {
   const media::AudioParameters params_;
   const base::UnguessableToken group_id_;
 
+  // Indicates that CreateStream has been called, but not StreamCreated.
+  bool awaiting_created_ = false;
+
   DeleterCallback deleter_;
 
   media::mojom::AudioOutputStreamProviderClientPtr client_;

content/browser/media/forwarding_audio_stream_factory.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "content/browser/web_contents/web_contents_impl.h"
 #include "content/public/browser/browser_thread.h"
 #include "content/public/browser/navigation_handle.h"
@@ -100,10 +101,17 @@ void ForwardingAudioStreamFactory::CreateLoopbackStream(
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DCHECK(frame);
   DCHECK(frame_of_source_web_contents);
+
+  TRACE_EVENT_BEGIN1("audio", "CreateLoopbackStream", "group",
+                     group_id_.GetLowForSerialization());
+
   WebContents* source_contents =
       WebContents::FromRenderFrameHost(frame_of_source_web_contents);
-  if (!source_contents)
+  if (!source_contents) {
+    TRACE_EVENT_END1("audio", "CreateLoopbackStream", "source",
+                     "failed to find source");
     return;
+  }
 
   const int process_id = frame->GetProcess()->GetID();
   const int frame_id = frame->GetRoutingID();
@@ -118,11 +126,18 @@ void ForwardingAudioStreamFactory::CreateLoopbackStream(
           std::move(renderer_factory_client)))
       .first->get()
       ->CreateStream(GetFactory());
+  TRACE_EVENT_END1("audio", "CreateLoopbackStream", "source",
+                   static_cast<WebContentsImpl*>(source_contents)
+                       ->GetAudioStreamFactory()
+                       ->group_id()
+                       .GetLowForSerialization());
 }
 
 void ForwardingAudioStreamFactory::SetMuted(bool muted) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   DCHECK_NE(muted, IsMuted());
+  TRACE_EVENT_INSTANT2("audio", "SetMuted", TRACE_EVENT_SCOPE_THREAD, "group",
+                       group_id_.GetLowForSerialization(), "muted", muted);
 
   if (!muted) {
     muter_.reset();
@@ -148,8 +163,14 @@ void ForwardingAudioStreamFactory::FrameDeleted(
 void ForwardingAudioStreamFactory::CleanupStreamsBelongingTo(
     RenderFrameHost* render_frame_host) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+
   const int process_id = render_frame_host->GetProcess()->GetID();
   const int frame_id = render_frame_host->GetRoutingID();
+
+  TRACE_EVENT_BEGIN2("audio", "CleanupStreamsBelongingTo", "group",
+                     group_id_.GetLowForSerialization(), "process id",
+                     process_id);
+
   auto match_rfh =
       [process_id,
        frame_id](const std::unique_ptr<AudioStreamBroker>& broker) -> bool {
@@ -161,6 +182,8 @@ void ForwardingAudioStreamFactory::CleanupStreamsBelongingTo(
   base::EraseIf(inputs_, match_rfh);
 
   ResetRemoteFactoryPtrIfIdle();
+
+  TRACE_EVENT_END1("audio", "CleanupStreamsBelongingTo", "frame_id", frame_id);
 }
 
 void ForwardingAudioStreamFactory::RemoveInput(AudioStreamBroker* broker) {
@@ -182,6 +205,9 @@ void ForwardingAudioStreamFactory::RemoveOutput(AudioStreamBroker* broker) {
 audio::mojom::StreamFactory* ForwardingAudioStreamFactory::GetFactory() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   if (!remote_factory_) {
+    TRACE_EVENT_INSTANT1(
+        "audio", "ForwardingAudioStreamFactory: Binding new factory",
+        TRACE_EVENT_SCOPE_THREAD, "group", group_id_.GetLowForSerialization());
     connector_->BindInterface(audio::mojom::kServiceName,
                               mojo::MakeRequest(&remote_factory_));
     // Unretained is safe because |this| owns |remote_factory_|.
@@ -200,11 +226,16 @@ audio::mojom::StreamFactory* ForwardingAudioStreamFactory::GetFactory() {
 void ForwardingAudioStreamFactory::ResetRemoteFactoryPtrIfIdle() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   if (inputs_.empty() && outputs_.empty())
-    remote_factory_.reset();
+    ResetRemoteFactoryPtr();
 }
 
 void ForwardingAudioStreamFactory::ResetRemoteFactoryPtr() {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  if (remote_factory_) {
+    TRACE_EVENT_INSTANT1(
+        "audio", "ForwardingAudioStreamFactory: Resetting factory",
+        TRACE_EVENT_SCOPE_THREAD, "group", group_id_.GetLowForSerialization());
+  }
   remote_factory_.reset();
   // The stream brokers will call a callback to be deleted soon, give them a
   // chance to signal an error to the client first.

content/browser/renderer_host/media/audio_output_authorization_handler.h

@@ -65,26 +65,34 @@ class CONTENT_EXPORT AudioOutputAuthorizationHandler {
   static void UMALogDeviceAuthorizationTime(base::TimeTicks auth_start_time);
 
  private:
-  void HashDeviceId(AuthorizationCompletedCallback cb,
+  // Helper class for recording traces.
+  class TraceScope;
+
+  void HashDeviceId(std::unique_ptr<TraceScope> trace_scope,
+                    AuthorizationCompletedCallback cb,
                     const std::string& raw_device_id,
                     const MediaDeviceSaltAndOrigin& salt_and_origin) const;
 
-  void AccessChecked(AuthorizationCompletedCallback cb,
+  void AccessChecked(std::unique_ptr<TraceScope> trace_scope,
+                     AuthorizationCompletedCallback cb,
                      const std::string& device_id,
                      std::string salt,
                      url::Origin security_origin,
                      bool has_access) const;
 
-  void TranslateDeviceID(AuthorizationCompletedCallback cb,
+  void TranslateDeviceID(std::unique_ptr<TraceScope> trace_scope,
+                         AuthorizationCompletedCallback cb,
                          const std::string& device_id,
                          const std::string& salt,
                          const url::Origin& security_origin,
                          const MediaDeviceEnumeration& enumeration) const;
 
-  void GetDeviceParameters(AuthorizationCompletedCallback cb,
+  void GetDeviceParameters(std::unique_ptr<TraceScope> trace_scope,
+                           AuthorizationCompletedCallback cb,
                            const std::string& raw_device_id) const;
 
   void DeviceParametersReceived(
+      std::unique_ptr<TraceScope> trace_scope,
       AuthorizationCompletedCallback cb,
       const std::string& device_id_for_renderer,
       const std::string& raw_device_id,

content/browser/renderer_host/media/render_frame_audio_input_stream_factory.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "content/browser/media/capture/desktop_capture_device_uma_types.h"
 #include "content/browser/media/forwarding_audio_stream_factory.h"
 #include "content/public/browser/browser_thread.h"
@@ -57,6 +58,10 @@ void RenderFrameAudioInputStreamFactory::CreateStream(
     bool automatic_gain_control,
     uint32_t shared_memory_count) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  TRACE_EVENT_INSTANT1("audio",
+                       "RenderFrameAudioInputStreamFactory::CreateStream",
+                       TRACE_EVENT_SCOPE_THREAD, "session id", session_id);
+
   BrowserThread::PostTask(
       BrowserThread::IO, FROM_HERE,
       base::BindOnce(
@@ -75,6 +80,10 @@ void RenderFrameAudioInputStreamFactory::CreateStreamAfterLookingUpDevice(
     bool automatic_gain_control,
     uint32_t shared_memory_count,
     const MediaStreamDevice& device) {
+  TRACE_EVENT1(
+      "audio",
+      "RenderFrameAudioInputStreamFactory::CreateStreamAfterLookingUpDevice",
+      "device id", device.id);
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
   ForwardingAudioStreamFactory* factory =
       ForwardingAudioStreamFactory::ForFrame(render_frame_host_);

content/browser/renderer_host/media/render_frame_audio_output_stream_factory.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "content/browser/media/forwarding_audio_stream_factory.h"
 #include "content/browser/renderer_host/media/audio_output_authorization_handler.h"
 #include "content/public/browser/render_frame_host.h"
@@ -38,6 +39,10 @@ class RenderFrameAudioOutputStreamFactory::ProviderImpl final
       const media::AudioParameters& params,
       media::mojom::AudioOutputStreamProviderClientPtr provider_client) final {
     DCHECK_CURRENTLY_ON(BrowserThread::UI);
+    TRACE_EVENT1("audio",
+                 "RenderFrameAudioOutputStreamFactory::ProviderImpl::Acquire",
+                 "raw device id", device_id_);
+
     RenderFrameHost* frame = owner_->frame_;
     ForwardingAudioStreamFactory* factory =
         ForwardingAudioStreamFactory::ForFrame(frame);
@@ -90,6 +95,11 @@ void RenderFrameAudioOutputStreamFactory::RequestDeviceAuthorization(
     const std::string& device_id,
     RequestDeviceAuthorizationCallback callback) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  TRACE_EVENT2(
+      "audio",
+      "RenderFrameAudioOutputStreamFactory::RequestDeviceAuthorization",
+      "device id", device_id, "session_id", session_id);
+
   const base::TimeTicks auth_start_time = base::TimeTicks::Now();
   // TODO(https://crbug.com/837625): This thread hopping is suboptimal since
   // AudioOutputAuthorizationHandler was made to be used on the IO thread.
@@ -120,6 +130,10 @@ void RenderFrameAudioOutputStreamFactory::AuthorizationCompleted(
     const std::string& raw_device_id,
     const std::string& device_id_for_renderer) {
   DCHECK_CURRENTLY_ON(BrowserThread::UI);
+  TRACE_EVENT2("audio",
+               "RenderFrameAudioOutputStreamFactory::AuthorizationCompleted",
+               "raw device id", raw_device_id, "status", status);
+
   AudioOutputAuthorizationHandler::UMALogDeviceAuthorizationTime(
       auth_start_time);
 

content/renderer/media/audio_renderer_sink_cache_impl.cc

@@ -14,6 +14,7 @@
 #include "base/metrics/histogram_macros.h"
 #include "base/synchronization/lock.h"
 #include "base/threading/thread_task_runner_handle.h"
+#include "base/trace_event/trace_event.h"
 #include "content/public/renderer/render_frame.h"
 #include "content/public/renderer/render_frame_observer.h"
 #include "content/renderer/media/audio_device_factory.h"
@@ -128,6 +129,10 @@ media::OutputDeviceInfo AudioRendererSinkCacheImpl::GetSinkInfo(
     int source_render_frame_id,
     int session_id,
     const std::string& device_id) {
+  TRACE_EVENT_BEGIN2("audio", "AudioRendererSinkCacheImpl::GetSinkInfo",
+                     "frame_id", source_render_frame_id, "device id",
+                     device_id);
+
   if (media::AudioDeviceDescription::UseSessionIdToSelectDevice(session_id,
                                                                 device_id)) {
     // We are provided with session id instead of device id. Session id is
@@ -141,6 +146,8 @@ media::OutputDeviceInfo AudioRendererSinkCacheImpl::GetSinkInfo(
     UMA_HISTOGRAM_ENUMERATION(
         "Media.Audio.Render.SinkCache.GetOutputDeviceInfoCacheUtilization",
         SINK_CACHE_MISS_CANNOT_LOOKUP_BY_SESSION_ID, SINK_CACHE_LAST_ENTRY);
+    TRACE_EVENT_END1("audio", "AudioRendererSinkCacheImpl::GetSinkInfo",
+                     "result", "Cache not used due to using |session_id|");
 
     return sink->GetOutputDeviceInfo();
   }
@@ -154,6 +161,8 @@ media::OutputDeviceInfo AudioRendererSinkCacheImpl::GetSinkInfo(
       UMA_HISTOGRAM_ENUMERATION(
           "Media.Audio.Render.SinkCache.GetOutputDeviceInfoCacheUtilization",
           SINK_CACHE_HIT, SINK_CACHE_LAST_ENTRY);
+      TRACE_EVENT_END1("audio", "AudioRendererSinkCacheImpl::GetSinkInfo",
+                       "result", "Cache hit");
       return cache_iter->sink->GetOutputDeviceInfo();
     }
   }
@@ -168,6 +177,8 @@ media::OutputDeviceInfo AudioRendererSinkCacheImpl::GetSinkInfo(
       "Media.Audio.Render.SinkCache.GetOutputDeviceInfoCacheUtilization",
       SINK_CACHE_MISS_NO_SINK, SINK_CACHE_LAST_ENTRY);
 
+  TRACE_EVENT_END1("audio", "AudioRendererSinkCacheImpl::GetSinkInfo", "result",
+                   "Cache miss");
   // |sink| is ref-counted, so it's ok if it is removed from cache before we get
   // here.
   return sink->GetOutputDeviceInfo();
@@ -178,6 +189,8 @@ scoped_refptr<media::AudioRendererSink> AudioRendererSinkCacheImpl::GetSink(
     const std::string& device_id) {
   UMA_HISTOGRAM_BOOLEAN("Media.Audio.Render.SinkCache.UsedForSinkCreation",
                         true);
+  TRACE_EVENT_BEGIN2("audio", "AudioRendererSinkCacheImpl::GetSink", "frame_id",
+                     source_render_frame_id, "device id", device_id);
 
   base::AutoLock auto_lock(cache_lock_);
 
@@ -189,6 +202,8 @@ scoped_refptr<media::AudioRendererSink> AudioRendererSinkCacheImpl::GetSink(
     cache_iter->used = true;
     UMA_HISTOGRAM_BOOLEAN(
         "Media.Audio.Render.SinkCache.InfoSinkReusedForOutput", true);
+    TRACE_EVENT_END1("audio", "AudioRendererSinkCacheImpl::GetSink", "result",
+                     "Cache hit");
     return cache_iter->sink;
   }
 
@@ -198,9 +213,15 @@ scoped_refptr<media::AudioRendererSink> AudioRendererSinkCacheImpl::GetSink(
                                                 0 /* session_id */, device_id),
                             true /* used */};
 
-  if (SinkIsHealthy(cache_entry.sink.get()))
+  if (SinkIsHealthy(cache_entry.sink.get())) {
+    TRACE_EVENT_INSTANT0(
+        "audio", "AudioRendererSinkCacheImpl::GetSink: caching new sink",
+        TRACE_EVENT_SCOPE_THREAD);
     cache_.push_back(cache_entry);
+  }
 
+  TRACE_EVENT_END1("audio", "AudioRendererSinkCacheImpl::GetSink", "result",
+                   "Cache miss");
   return cache_entry.sink;
 }
 
@@ -292,6 +313,8 @@ void AudioRendererSinkCacheImpl::CacheOrStopUnusedSink(
     const std::string& device_id,
     scoped_refptr<media::AudioRendererSink> sink) {
   if (!SinkIsHealthy(sink.get())) {
+    TRACE_EVENT_INSTANT0("audio", "CacheOrStopUnusedSink: Unhealthy sink",
+                         TRACE_EVENT_SCOPE_THREAD);
     // Since |sink| is not cached, we must make sure to Stop it now.
     sink->Stop();
     return;

services/audio/input_stream.cc

@@ -8,6 +8,7 @@
 #include <utility>
 
 #include "base/bind_helpers.h"
+#include "base/trace_event/trace_event.h"
 #include "media/audio/audio_input_sync_writer.h"
 #include "media/audio/audio_manager.h"
 #include "media/base/audio_parameters.h"
@@ -58,6 +59,10 @@ InputStream::InputStream(CreatedCallback created_callback,
   DCHECK(client_.is_bound());
   DCHECK(created_callback_);
   DCHECK(delete_callback_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "audio::InputStream", this);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("audio", "InputStream", this, "device id",
+                                    device_id, "params",
+                                    params.AsHumanReadableString());
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler =
@@ -108,11 +113,16 @@ InputStream::~InputStream() {
   // TODO(https://crbug.com/803102): remove AudioInputController::Close() after
   // content/ streams are removed, destructor should suffice.
   controller_->Close(base::OnceClosure());
+
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "InputStream", this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "audio::InputStream", this);
 }
 
 void InputStream::Record() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(controller_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "Record", this);
+
   controller_->Record();
   if (observer_)
     observer_->DidStartRecording();
@@ -123,6 +133,8 @@ void InputStream::Record() {
 void InputStream::SetVolume(double volume) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(controller_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("audio", "SetVolume", this, "volume",
+                                      volume);
 
   if (volume < 0 || volume > 1) {
     mojo::ReportBadMessage("Invalid volume");
@@ -136,6 +148,7 @@ void InputStream::SetVolume(double volume) {
 }
 
 void InputStream::OnCreated(bool initially_muted) {
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "Created", this);
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
 
   const base::SharedMemory* memory = writer_->shared_memory();
@@ -163,6 +176,8 @@ void InputStream::OnCreated(bool initially_muted) {
 
 void InputStream::OnError(media::AudioInputController::ErrorCode error_code) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "Error", this);
+
   client_->OnError();
   if (log_)
     log_->get()->OnError();
@@ -182,6 +197,7 @@ void InputStream::OnMuted(bool is_muted) {
 
 void InputStream::OnStreamError() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "OnStreamError", this);
 
   // Defer callback so we're not destructed while in the constructor.
   base::SequencedTaskRunnerHandle::Get()->PostTask(

services/audio/output_stream.cc

@@ -8,6 +8,7 @@
 
 #include "base/bind.h"
 #include "base/threading/sequenced_task_runner_handle.h"
+#include "base/trace_event/trace_event.h"
 #include "services/audio/group_coordinator.h"
 
 namespace audio {
@@ -52,6 +53,10 @@ OutputStream::OutputStream(
   DCHECK(created_callback);
   DCHECK(delete_callback_);
   DCHECK(coordinator_);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "audio::OutputStream", this);
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN2("audio", "OutputStream", this, "device id",
+                                    output_device_id, "params",
+                                    params.AsHumanReadableString());
 
   // |this| owns these objects, so unretained is safe.
   base::RepeatingClosure error_handler =
@@ -82,6 +87,15 @@ OutputStream::~OutputStream() {
 
   controller_.Close();
   coordinator_->UnregisterGroupMember(&controller_);
+
+  if (is_audible_)
+    TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "Audible", this);
+
+  if (playing_)
+    TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "Playing", this);
+
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "OutputStream", this);
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "audio::OutputStream", this);
 }
 
 void OutputStream::Play() {
@@ -100,6 +114,8 @@ void OutputStream::Pause() {
 
 void OutputStream::SetVolume(double volume) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT1("audio", "SetVolume", this, "volume",
+                                      volume);
 
   if (volume < 0 || volume > 1) {
     mojo::ReportBadMessage("Invalid volume");
@@ -114,6 +130,7 @@ void OutputStream::SetVolume(double volume) {
 void OutputStream::CreateAudioPipe(CreatedCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
   DCHECK(reader_.IsValid());
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "CreateAudioPipe", this);
 
   const base::SharedMemory* memory = reader_.shared_memory();
   base::SharedMemoryHandle foreign_memory_handle =
@@ -143,6 +160,7 @@ void OutputStream::OnControllerPlaying() {
   if (playing_)
     return;
 
+  TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "Playing", this);
   playing_ = true;
   observer_->DidStartPlaying();
   if (OutputController::will_monitor_audio_levels()) {
@@ -173,10 +191,12 @@ void OutputStream::OnControllerPaused() {
     poll_timer_.Stop();
   }
   observer_->DidStopPlaying();
+  TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "Playing", this);
 }
 
 void OutputStream::OnControllerError() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "OnControllerError", this);
 
   // Stop checking the audio level to avoid using this object while it's being
   // torn down.
@@ -197,6 +217,7 @@ void OutputStream::OnLog(base::StringPiece message) {
 
 void OutputStream::OnError() {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT_NESTABLE_ASYNC_INSTANT0("audio", "OnError", this);
 
   // Defer callback so we're not destructed while in the constructor.
   base::SequencedTaskRunnerHandle::Get()->PostTask(
@@ -219,8 +240,13 @@ void OutputStream::PollAudioLevel() {
   bool was_audible = is_audible_;
   is_audible_ = IsAudible();
 
-  if (is_audible_ != was_audible)
+  if (is_audible_ && !was_audible) {
+    TRACE_EVENT_NESTABLE_ASYNC_BEGIN0("audio", "Audible", this);
+    observer_->DidChangeAudibleState(is_audible_);
+  } else if (!is_audible_ && was_audible) {
+    TRACE_EVENT_NESTABLE_ASYNC_END0("audio", "Audible", this);
     observer_->DidChangeAudibleState(is_audible_);
+  }
 }
 
 bool OutputStream::IsAudible() {

services/audio/service.cc

@@ -11,6 +11,7 @@
 #include "base/single_thread_task_runner.h"
 #include "base/system_monitor/system_monitor.h"
 #include "base/time/default_clock.h"
+#include "base/trace_event/trace_event.h"
 #include "media/audio/audio_manager.h"
 #include "services/audio/debug_recording.h"
 #include "services/audio/device_notifier.h"
@@ -82,6 +83,8 @@ void Service::OnBindInterface(
   DCHECK(ref_factory_);
   DCHECK_CALLED_ON_VALID_THREAD(thread_checker_);
   DVLOG(4) << "audio::Service::OnBindInterface";
+  TRACE_EVENT1("audio", "audio::Service::OnBindInterface", "interface",
+               interface_name);
 
   if (ref_factory_->HasNoRefs())
     metrics_->HasConnections();

services/audio/stream_factory.cc

@@ -6,6 +6,7 @@
 
 #include <utility>
 
+#include "base/trace_event/trace_event.h"
 #include "base/unguessable_token.h"
 #include "services/audio/input_stream.h"
 #include "services/audio/local_muter.h"
@@ -42,6 +43,8 @@ void StreamFactory::CreateInputStream(
     mojo::ScopedSharedBufferHandle key_press_count_buffer,
     CreateInputStreamCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT1("audio", "StreamFactory::CreateInputStream", "device id",
+               device_id);
 
   // Unretained is safe since |this| indirectly owns the InputStream.
   auto deleter_callback = base::BindOnce(&StreamFactory::DestroyInputStream,
@@ -64,6 +67,8 @@ void StreamFactory::CreateOutputStream(
     const base::UnguessableToken& group_id,
     CreateOutputStreamCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT1("audio", "StreamFactory::CreateOutputStream", "device id",
+               output_device_id);
 
   media::mojom::AudioOutputStreamObserverAssociatedPtr observer;
   observer.Bind(std::move(observer_info));
@@ -81,6 +86,8 @@ void StreamFactory::CreateOutputStream(
 void StreamFactory::BindMuter(mojom::LocalMuterAssociatedRequest request,
                               const base::UnguessableToken& group_id) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
+  TRACE_EVENT1("audio", "StreamFactory::BindMuter", "group id",
+               group_id.GetLowForSerialization());
 
   // Find the existing LocalMuter for this group, or create one on-demand.
   auto it = std::find_if(muters_.begin(), muters_.end(),
@@ -112,6 +119,8 @@ void StreamFactory::CreateLoopbackStream(
     CreateLoopbackStreamCallback created_callback) {
   DCHECK_CALLED_ON_VALID_SEQUENCE(owning_sequence_);
 
+  TRACE_EVENT1("audio", "StreamFactory::CreateLoopbackStream", "group id",
+               group_id.GetLowForSerialization());
   auto stream = std::make_unique<LoopbackStream>(
       std::move(created_callback),
       base::BindOnce(&StreamFactory::DestroyLoopbackStream,