From 2d0ba28e2521ab1ff907b98f6bb12272b4346823 Mon Sep 17 00:00:00 2001 From: Olga Sharonova Date: Tue, 27 Sep 2022 15:22:34 +0200 Subject: [PATCH] Audio stack traces Bug: webrtc:0 Change-Id: I90ea6301f02c2ebe72711ddbeda0bf000a6873aa Reviewed-on: https://webrtc-review.googlesource.com/c/src/+/276940 Auto-Submit: Olga Sharonova Commit-Queue: Henrik Andreassson Reviewed-by: Henrik Andreassson Cr-Commit-Position: refs/heads/main@{#38223} --- audio/BUILD.gn | 1 + audio/audio_send_stream.cc | 2 ++ audio/audio_transport_impl.cc | 5 +++++ audio/channel_receive.cc | 4 +++- audio/channel_send.cc | 3 +++ media/engine/webrtc_voice_engine.cc | 4 ++++ modules/audio_device/BUILD.gn | 1 + modules/audio_device/audio_device_buffer.cc | 4 ++++ modules/audio_mixer/BUILD.gn | 1 + modules/audio_mixer/audio_mixer_impl.cc | 2 ++ modules/rtp_rtcp/source/source_tracker.cc | 4 ++++ pc/BUILD.gn | 1 + pc/remote_audio_source.cc | 2 ++ pc/rtp_sender.cc | 2 ++ 14 files changed, 35 insertions(+), 1 deletion(-) diff --git a/audio/BUILD.gn b/audio/BUILD.gn index e42a1225bd..d1a91e6ac0 100644 --- a/audio/BUILD.gn +++ b/audio/BUILD.gn @@ -87,6 +87,7 @@ rtc_library("audio") { "../rtc_base:audio_format_to_string", "../rtc_base:buffer", "../rtc_base:checks", + "../rtc_base:event_tracer", "../rtc_base:logging", "../rtc_base:macromagic", "../rtc_base:race_checker", diff --git a/audio/audio_send_stream.cc b/audio/audio_send_stream.cc index 0f6c9c10ef..0a93079974 100644 --- a/audio/audio_send_stream.cc +++ b/audio/audio_send_stream.cc @@ -39,6 +39,7 @@ #include "rtc_base/logging.h" #include "rtc_base/strings/audio_format_to_string.h" #include "rtc_base/task_queue.h" +#include "rtc_base/trace_event.h" namespace webrtc { namespace { @@ -392,6 +393,7 @@ void AudioSendStream::Stop() { void AudioSendStream::SendAudioData(std::unique_ptr audio_frame) { RTC_CHECK_RUNS_SERIALIZED(&audio_capture_race_checker_); RTC_DCHECK_GT(audio_frame->sample_rate_hz_, 0); + TRACE_EVENT0("webrtc", "AudioSendStream::SendAudioData"); double duration = static_cast(audio_frame->samples_per_channel_) / audio_frame->sample_rate_hz_; { diff --git a/audio/audio_transport_impl.cc b/audio/audio_transport_impl.cc index 194f09cf6c..7528bf0765 100644 --- a/audio/audio_transport_impl.cc +++ b/audio/audio_transport_impl.cc @@ -20,6 +20,7 @@ #include "modules/async_audio_processing/async_audio_processing.h" #include "modules/audio_processing/include/audio_frame_proxies.h" #include "rtc_base/checks.h" +#include "rtc_base/trace_event.h" namespace webrtc { @@ -177,6 +178,7 @@ int32_t AudioTransportImpl::RecordedDataIsAvailable( void AudioTransportImpl::SendProcessedData( std::unique_ptr audio_frame) { + TRACE_EVENT0("webrtc", "AudioTransportImpl::SendProcessedData"); RTC_DCHECK_GT(audio_frame->samples_per_channel_, 0); MutexLock lock(&capture_lock_); if (audio_senders_.empty()) @@ -202,6 +204,7 @@ int32_t AudioTransportImpl::NeedMorePlayData(const size_t nSamples, size_t& nSamplesOut, int64_t* elapsed_time_ms, int64_t* ntp_time_ms) { + TRACE_EVENT0("webrtc", "AudioTransportImpl::SendProcessedData"); RTC_DCHECK_EQ(sizeof(int16_t) * nChannels, nBytesPerSample); RTC_DCHECK_GE(nChannels, 1); RTC_DCHECK_LE(nChannels, 2); @@ -239,6 +242,8 @@ void AudioTransportImpl::PullRenderData(int bits_per_sample, void* audio_data, int64_t* elapsed_time_ms, int64_t* ntp_time_ms) { + TRACE_EVENT2("webrtc", "AudioTransportImpl::PullRenderData", "sample_rate", + sample_rate, "number_of_frames", number_of_frames); RTC_DCHECK_EQ(bits_per_sample, 16); RTC_DCHECK_GE(number_of_channels, 1); RTC_DCHECK_GE(sample_rate, AudioProcessing::NativeRate::kSampleRate8kHz); diff --git a/audio/channel_receive.cc b/audio/channel_receive.cc index 91294ad4d8..18f9ecb29c 100644 --- a/audio/channel_receive.cc +++ b/audio/channel_receive.cc @@ -48,6 +48,7 @@ #include "rtc_base/synchronization/mutex.h" #include "rtc_base/system/no_unique_address.h" #include "rtc_base/time_utils.h" +#include "rtc_base/trace_event.h" #include "system_wrappers/include/metrics.h" #include "system_wrappers/include/ntp_time.h" @@ -375,6 +376,8 @@ void ChannelReceive::InitFrameTransformerDelegate( AudioMixer::Source::AudioFrameInfo ChannelReceive::GetAudioFrameWithInfo( int sample_rate_hz, AudioFrame* audio_frame) { + TRACE_EVENT1("webrtc", "ChannelReceive::GetAudioFrameWithInfo", + "sample_rate_hz", sample_rate_hz); RTC_DCHECK_RUNS_SERIALIZED(&audio_thread_race_checker_); audio_frame->sample_rate_hz_ = sample_rate_hz; @@ -440,7 +443,6 @@ AudioMixer::Source::AudioFrameInfo ChannelReceive::GetAudioFrameWithInfo( if (capture_start_rtp_time_stamp_ >= 0) { // audio_frame.timestamp_ should be valid from now on. - // Compute elapsed time. int64_t unwrap_timestamp = rtp_ts_wraparound_handler_->Unwrap(audio_frame->timestamp_); diff --git a/audio/channel_send.cc b/audio/channel_send.cc index 0a49285236..73b3851fdb 100644 --- a/audio/channel_send.cc +++ b/audio/channel_send.cc @@ -40,6 +40,7 @@ #include "rtc_base/synchronization/mutex.h" #include "rtc_base/task_queue.h" #include "rtc_base/time_utils.h" +#include "rtc_base/trace_event.h" #include "system_wrappers/include/clock.h" #include "system_wrappers/include/metrics.h" @@ -801,6 +802,8 @@ void ChannelSend::RtcpPacketTypesCounterUpdated( void ChannelSend::ProcessAndEncodeAudio( std::unique_ptr audio_frame) { + TRACE_EVENT0("webrtc", "ChannelSend::ProcessAndEncodeAudio"); + RTC_DCHECK_RUNS_SERIALIZED(&audio_thread_race_checker_); RTC_DCHECK_GT(audio_frame->samples_per_channel_, 0); RTC_DCHECK_LE(audio_frame->num_channels_, 8); diff --git a/media/engine/webrtc_voice_engine.cc b/media/engine/webrtc_voice_engine.cc index 03d9537a69..d36c5985e5 100644 --- a/media/engine/webrtc_voice_engine.cc +++ b/media/engine/webrtc_voice_engine.cc @@ -923,6 +923,8 @@ class WebRtcVoiceMediaChannel::WebRtcAudioSendStream size_t number_of_channels, size_t number_of_frames, absl::optional absolute_capture_timestamp_ms) override { + TRACE_EVENT_BEGIN2("webrtc", "WebRtcAudioSendStream::OnData", "sample_rate", + sample_rate, "number_of_frames", number_of_frames); RTC_DCHECK_EQ(16, bits_per_sample); RTC_CHECK_RUNS_SERIALIZED(&audio_capture_race_checker_); RTC_DCHECK(stream_); @@ -938,6 +940,8 @@ class WebRtcVoiceMediaChannel::WebRtcAudioSendStream *absolute_capture_timestamp_ms); } stream_->SendAudioData(std::move(audio_frame)); + TRACE_EVENT_END1("webrtc", "WebRtcAudioSendStream::OnData", + "number_of_channels", number_of_channels); } // Callback from the `source_` when it is going away. In case Start() has diff --git a/modules/audio_device/BUILD.gn b/modules/audio_device/BUILD.gn index 7919dcb1ac..6c7292aba1 100644 --- a/modules/audio_device/BUILD.gn +++ b/modules/audio_device/BUILD.gn @@ -72,6 +72,7 @@ rtc_library("audio_device_buffer") { "../../common_audio:common_audio_c", "../../rtc_base:buffer", "../../rtc_base:checks", + "../../rtc_base:event_tracer", "../../rtc_base:logging", "../../rtc_base:macromagic", "../../rtc_base:rtc_task_queue", diff --git a/modules/audio_device/audio_device_buffer.cc b/modules/audio_device/audio_device_buffer.cc index 8cc11debf4..6232a93d8f 100644 --- a/modules/audio_device/audio_device_buffer.cc +++ b/modules/audio_device/audio_device_buffer.cc @@ -20,6 +20,7 @@ #include "rtc_base/checks.h" #include "rtc_base/logging.h" #include "rtc_base/time_utils.h" +#include "rtc_base/trace_event.h" #include "system_wrappers/include/metrics.h" namespace webrtc { @@ -297,6 +298,9 @@ int32_t AudioDeviceBuffer::DeliverRecordedData() { } int32_t AudioDeviceBuffer::RequestPlayoutData(size_t samples_per_channel) { + TRACE_EVENT1("webrtc", "AudioDeviceBuffer::RequestPlayoutData", + "samples_per_channel", samples_per_channel); + // The consumer can change the requested size on the fly and we therefore // resize the buffer accordingly. Also takes place at the first call to this // method. diff --git a/modules/audio_mixer/BUILD.gn b/modules/audio_mixer/BUILD.gn index 1196835fec..fe20f3d6c7 100644 --- a/modules/audio_mixer/BUILD.gn +++ b/modules/audio_mixer/BUILD.gn @@ -46,6 +46,7 @@ rtc_library("audio_mixer_impl") { "../../audio/utility:audio_frame_operations", "../../common_audio", "../../rtc_base:checks", + "../../rtc_base:event_tracer", "../../rtc_base:logging", "../../rtc_base:macromagic", "../../rtc_base:race_checker", diff --git a/modules/audio_mixer/audio_mixer_impl.cc b/modules/audio_mixer/audio_mixer_impl.cc index 73a6e3a8a4..0c203a1d9f 100644 --- a/modules/audio_mixer/audio_mixer_impl.cc +++ b/modules/audio_mixer/audio_mixer_impl.cc @@ -21,6 +21,7 @@ #include "modules/audio_mixer/default_output_rate_calculator.h" #include "rtc_base/checks.h" #include "rtc_base/logging.h" +#include "rtc_base/trace_event.h" namespace webrtc { @@ -156,6 +157,7 @@ rtc::scoped_refptr AudioMixerImpl::Create( void AudioMixerImpl::Mix(size_t number_of_channels, AudioFrame* audio_frame_for_mixing) { + TRACE_EVENT0("webrtc", "AudioMixerImpl::Mix"); RTC_DCHECK(number_of_channels >= 1); MutexLock lock(&mutex_); diff --git a/modules/rtp_rtcp/source/source_tracker.cc b/modules/rtp_rtcp/source/source_tracker.cc index 090e435784..7a5cbac77d 100644 --- a/modules/rtp_rtcp/source/source_tracker.cc +++ b/modules/rtp_rtcp/source/source_tracker.cc @@ -13,6 +13,8 @@ #include #include +#include "rtc_base/trace_event.h" + namespace webrtc { constexpr int64_t SourceTracker::kTimeoutMs; @@ -24,6 +26,8 @@ void SourceTracker::OnFrameDelivered(const RtpPacketInfos& packet_infos) { return; } + TRACE_EVENT0("webrtc", "SourceTracker::OnFrameDelivered"); + int64_t now_ms = clock_->TimeInMilliseconds(); MutexLock lock_scope(&lock_); diff --git a/pc/BUILD.gn b/pc/BUILD.gn index 5c251c5c32..79b9a089b4 100644 --- a/pc/BUILD.gn +++ b/pc/BUILD.gn @@ -1828,6 +1828,7 @@ rtc_library("remote_audio_source") { "../media:rtc_media_base", "../rtc_base", "../rtc_base:checks", + "../rtc_base:event_tracer", "../rtc_base:logging", "../rtc_base:safe_conversions", "../rtc_base:stringutils", diff --git a/pc/remote_audio_source.cc b/pc/remote_audio_source.cc index 667312c38c..1058d1cbf9 100644 --- a/pc/remote_audio_source.cc +++ b/pc/remote_audio_source.cc @@ -23,6 +23,7 @@ #include "rtc_base/checks.h" #include "rtc_base/logging.h" #include "rtc_base/strings/string_format.h" +#include "rtc_base/trace_event.h" namespace webrtc { @@ -149,6 +150,7 @@ void RemoteAudioSource::RemoveSink(AudioTrackSinkInterface* sink) { void RemoteAudioSource::OnData(const AudioSinkInterface::Data& audio) { // Called on the externally-owned audio callback thread, via/from webrtc. + TRACE_EVENT0("webrtc", "RemoteAudioSource::OnData"); MutexLock lock(&sink_lock_); for (auto* sink : sinks_) { // When peerconnection acts as an audio source, it should not provide diff --git a/pc/rtp_sender.cc b/pc/rtp_sender.cc index aa640f3829..b4c773003b 100644 --- a/pc/rtp_sender.cc +++ b/pc/rtp_sender.cc @@ -474,6 +474,8 @@ void LocalAudioSinkAdapter::OnData( size_t number_of_channels, size_t number_of_frames, absl::optional absolute_capture_timestamp_ms) { + TRACE_EVENT2("webrtc", "LocalAudioSinkAdapter::OnData", "sample_rate", + sample_rate, "number_of_frames", number_of_frames); MutexLock lock(&lock_); if (sink_) { sink_->OnData(audio_data, bits_per_sample, sample_rate, number_of_channels,