[audio_core] Squelch glitch-logging
Detecting audio glitches (underflows leading to discontinuities) is a
good thing. However, logging every detected underflow -- when it is
likely that high resource contention caused it in the first place --
could reasonably be called an anti-pattern.
When the mixer entirely or partially skips a client-submitted packet,
because it considers that packet's (explicit or implicit) timestamp to
be LATE, we call that a "client-side underflow".
With this CL, audio_core tracks the number of client-side underflows,
per Renderer, with separate counts of full (whole-packet) vs. partial.
Although we tally them all, we do not log-display them all. With this
CL, we continue to log the first client "glitch" detected, but
subsequently throttle how frequently these are logged, based on
constants associated with audio_core's current logging level.
By default on non-debug builds, audio_core will log each renderer's
glitch #1, 101, 201, etc. On debug builds, audio_core will log #1, 11,
21, etc.
This CL also disables the logging of normal position notifications
altogether. Previously, these were throttled to approx. 1-3 per hour
on DEBUG and not at all on NDEBUG.
Bug: 34866
Test: logging-only
Change-Id: I4d6de50176ba192e9db6fbd7ba014de600da2a9f
diff --git a/src/media/audio/audio_core/audio_capturer_impl.cc b/src/media/audio/audio_core/audio_capturer_impl.cc
index 2de08ba..37ccda0 100644
--- a/src/media/audio/audio_core/audio_capturer_impl.cc
+++ b/src/media/audio/audio_core/audio_capturer_impl.cc
@@ -881,11 +881,11 @@
void DumpRbRegions(const RbRegion* regions) {
for (auto i = 0; i < 2; ++i) {
if (regions[i].len) {
- AUD_VLOG(TRACE) << " [" << i << "] srb_pos 0x" << std::hex << regions[i].srb_pos << ", len 0x"
- << regions[i].len << ", sfrac_pts 0x" << regions[i].sfrac_pts << " ("
- << std::dec << (regions[i].sfrac_pts >> kPtsFractionalBits) << " frames)";
+ AUD_VLOG(SPEW) << " [" << i << "] srb_pos 0x" << std::hex << regions[i].srb_pos << ", len 0x"
+ << regions[i].len << ", sfrac_pts 0x" << regions[i].sfrac_pts << " ("
+ << std::dec << (regions[i].sfrac_pts >> kPtsFractionalBits) << " frames)";
} else {
- AUD_VLOG(TRACE) << " [" << i << "] len 0x0";
+ AUD_VLOG(SPEW) << " [" << i << "] len 0x0";
}
}
}
diff --git a/src/media/audio/audio_core/audio_driver.cc b/src/media/audio/audio_core/audio_driver.cc
index bf3ffce..4042719 100644
--- a/src/media/audio/audio_core/audio_driver.cc
+++ b/src/media/audio/audio_core/audio_driver.cc
@@ -30,7 +30,7 @@
// Trace const. If INFO, even less frequently per Info const (INFO is default for DEBUG builds).
// Default for audio_core in NDEBUG builds is WARNING, so by default we do not log any of these
// messages on Release builds. Set to false to not log at all, even for unsolicited notifications.
-static constexpr bool kLogPositionNotifications = true;
+static constexpr bool kLogPositionNotifications = false;
static constexpr uint16_t kPositionNotificationSpewInterval = 1;
static constexpr uint16_t kPositionNotificationTraceInterval = 60;
static constexpr uint16_t kPositionNotificationInfoInterval = 3600;
diff --git a/src/media/audio/audio_core/audio_output.cc b/src/media/audio/audio_core/audio_output.cc
index 3b52e4e..2589ea6 100644
--- a/src/media/audio/audio_core/audio_output.cc
+++ b/src/media/audio/audio_core/audio_output.cc
@@ -374,11 +374,10 @@
auto clock_mono_late = info->clock_mono_to_frac_source_frames.rate().Inverse().Scale(
frac_source_for_first_mix_job_frame - mixer.neg_filter_width() -
frac_source_for_first_packet_frame);
- AUD_LOG_OBJ(ERROR, audio_renderer.get())
- << ", skipping packet [" << frac_source_for_first_packet_frame << ","
- << frac_source_for_final_packet_frame << "]: missed mix-start "
- << frac_source_for_first_mix_job_frame - mixer.neg_filter_width() << " by "
- << static_cast<double>(clock_mono_late) / ZX_MSEC(1) << " ms";
+
+ audio_renderer->UnderflowOccurred(frac_source_for_first_packet_frame,
+ frac_source_for_first_mix_job_frame, clock_mono_late);
+
return true;
}
@@ -420,14 +419,7 @@
frac_source_offset_64 += dest_to_src.Scale(dest_offset_64);
- if (abs(frac_source_offset_64) >= (Mixer::FRAC_ONE >> 1)) {
- AUD_LOG_OBJ(WARNING, audio_renderer.get())
- << " skipped " << dest_offset_64 << " output frames; frac_source_offset is 0x" << std::hex
- << frac_source_offset_64;
- } else {
- AUD_VLOG_OBJ(TRACE, audio_renderer.get())
- << " skipped " << dest_offset_64 << " output frames to align with source timestamp";
- }
+ audio_renderer->PartialUnderflowOccurred(frac_source_offset_64, dest_offset_64);
}
FXL_DCHECK(dest_offset_64 >= 0);
@@ -492,11 +484,11 @@
info->gain.Advance(dest_offset - prev_dest_offset, cur_mix_job_.local_to_output->rate());
}
} else {
+ // This packet was initially within our mix window. After realigning our sampling point to the
+ // nearest dest frame, it is now entirely in the past. This can only occur when down-sampling
+ // and is made more likely if the rate conversion ratio is very high. We've already reported
+ // a partial underflow when realigning, so just complete the packet and move on to the next.
consumed_source = true;
- FXL_LOG(ERROR) << "Skipping packet -- frac_source_offset 0x" << std::hex << frac_source_offset
- << " exceeded final src frame's positive window 0x"
- << (static_cast<int32_t>(packet->frac_frame_len()) - Mixer::FRAC_ONE +
- mixer.pos_filter_width());
}
if (consumed_source) {
diff --git a/src/media/audio/audio_core/audio_renderer_impl.cc b/src/media/audio/audio_core/audio_renderer_impl.cc
index 05874e2..05f6b6e4 100644
--- a/src/media/audio/audio_core/audio_renderer_impl.cc
+++ b/src/media/audio/audio_core/audio_renderer_impl.cc
@@ -24,6 +24,21 @@
// Short-term workaround: pad our reported min_lead_time duration by this.
constexpr int64_t kPaddingForMinLeadTimeReporting = ZX_MSEC(4);
+// To what extent should client-side underflows be logged? (A "client-side underflow" refers to when
+// all or part of a packet's data is discarded because its start timestamp has already passed.)
+// For each Renderer, we will log the first underflow. For subsequent occurrances, depending on
+// audio_core's logging level, we throttle how frequently these are displayed. If log_level is set
+// to TRACE or SPEW, all client-side underflows are logged -- at log_level -1: VLOG TRACE -- as
+// specified by kRenderUnderflowTraceInterval. If set to INFO, we log less often, at log_level
+// 1: INFO, throttling by the factor kRenderUnderflowInfoInterval. If set to WARNING or higher,
+// we throttle these even more, specified by kRenderUnderflowErrorInterval. Note: by default we
+// set NDEBUG builds to WARNING and DEBUG builds to INFO. To disable all logging of client-side
+// underflows, set kLogRenderUnderflow to false.
+static constexpr bool kLogRenderUnderflow = true;
+static constexpr uint16_t kRenderUnderflowTraceInterval = 1;
+static constexpr uint16_t kRenderUnderflowInfoInterval = 10;
+static constexpr uint16_t kRenderUnderflowErrorInterval = 100;
+
fbl::RefPtr<AudioRendererImpl> AudioRendererImpl::Create(
fidl::InterfaceRequest<fuchsia::media::AudioRenderer> audio_renderer_request,
AudioCoreImpl* owner) {
@@ -38,7 +53,9 @@
owner_(owner),
audio_renderer_binding_(this, std::move(audio_renderer_request)),
pts_ticks_per_second_(1000000000, 1),
- ref_clock_to_frac_frames_(0, 0, {0, 1}) {
+ ref_clock_to_frac_frames_(0, 0, {0, 1}),
+ underflow_count_(0u),
+ partial_underflow_count_(0u) {
REP(AddingRenderer(*this));
AUD_VLOG_OBJ(TRACE, this);
@@ -247,6 +264,64 @@
}
}
+void AudioRendererImpl::UnderflowOccurred(int64_t source_start, int64_t mix_point,
+ zx_duration_t underflow_duration) {
+ uint16_t underflow_count = std::atomic_fetch_add<uint16_t>(&underflow_count_, 1u);
+
+ if constexpr (kLogRenderUnderflow) {
+ int64_t underflow_msec = underflow_duration / ZX_MSEC(1);
+
+ if ((kRenderUnderflowErrorInterval > 0) &&
+ (underflow_count % kRenderUnderflowErrorInterval == 0)) {
+ AUD_LOG_OBJ(ERROR, this) << "#" << underflow_count + 1 << " (1/"
+ << kRenderUnderflowErrorInterval << "): source-start 0x" << std::hex
+ << source_start << " missed mix-point 0x" << mix_point << " by "
+ << std::dec << underflow_msec << " ms";
+ } else if ((kRenderUnderflowInfoInterval > 0) &&
+ (underflow_count % kRenderUnderflowInfoInterval == 0)) {
+ AUD_LOG_OBJ(INFO, this) << "#" << underflow_count + 1 << " (1/"
+ << kRenderUnderflowErrorInterval << "): source-start 0x" << std::hex
+ << source_start << " missed mix-point 0x" << mix_point << " by "
+ << std::dec << underflow_msec << " ms";
+ } else if ((kRenderUnderflowTraceInterval > 0) &&
+ (underflow_count % kRenderUnderflowTraceInterval == 0)) {
+ AUD_VLOG_OBJ(TRACE, this) << "#" << underflow_count + 1 << " (1/"
+ << kRenderUnderflowErrorInterval << "): source-start 0x" << std::hex
+ << source_start << " missed mix-point 0x" << mix_point << " by "
+ << std::dec << underflow_msec << " ms";
+ }
+ }
+}
+
+void AudioRendererImpl::PartialUnderflowOccurred(int64_t source_offset, int64_t mix_offset) {
+ if (source_offset >= (Mixer::FRAC_ONE >> 1)) {
+ auto partial_underflow_count = std::atomic_fetch_add<uint16_t>(&partial_underflow_count_, 1u);
+ if constexpr (kLogRenderUnderflow) {
+ if ((kRenderUnderflowErrorInterval > 0) &&
+ (partial_underflow_count % kRenderUnderflowErrorInterval == 0)) {
+ AUD_LOG(WARNING) << "#" << partial_underflow_count + 1 << " (1/"
+ << kRenderUnderflowErrorInterval << "): shifted by "
+ << (source_offset < 0 ? "-0x" : "0x") << std::hex << abs(source_offset)
+ << " source subframes and " << std::dec << mix_offset << " mix frames";
+ } else if ((kRenderUnderflowInfoInterval > 0) &&
+ (partial_underflow_count % kRenderUnderflowInfoInterval == 0)) {
+ AUD_LOG(INFO) << "#" << partial_underflow_count + 1 << " (1/"
+ << kRenderUnderflowInfoInterval << "): shifted by "
+ << (source_offset < 0 ? "-0x" : "0x") << std::hex << abs(source_offset)
+ << " source subframes and " << std::dec << mix_offset << " mix frames";
+ } else if ((kRenderUnderflowTraceInterval > 0) &&
+ (partial_underflow_count % kRenderUnderflowTraceInterval == 0)) {
+ AUD_VLOG(TRACE) << "#" << partial_underflow_count + 1 << " (1/"
+ << kRenderUnderflowTraceInterval << "): shifted by "
+ << (source_offset < 0 ? "-0x" : "0x") << std::hex << abs(source_offset)
+ << " source subframes and " << std::dec << mix_offset << " mix frames";
+ }
+ }
+ } else {
+ AUD_VLOG(TRACE) << "skipped " << mix_offset << " output frames to align with source packet";
+ }
+}
+
////////////////////////////////////////////////////////////////////////////////
//
// AudioRenderer Interface
diff --git a/src/media/audio/audio_core/audio_renderer_impl.h b/src/media/audio/audio_core/audio_renderer_impl.h
index 9572a88..793f432 100644
--- a/src/media/audio/audio_core/audio_renderer_impl.h
+++ b/src/media/audio/audio_core/audio_renderer_impl.h
@@ -8,6 +8,7 @@
#include <fuchsia/media/cpp/fidl.h>
#include <lib/fit/function.h>
+#include <atomic>
#include <memory>
#include <unordered_map>
@@ -55,6 +56,11 @@
const fbl::RefPtr<AudioRendererFormatInfo>& format_info() const { return format_info_; }
bool format_info_valid() const { return (format_info_ != nullptr); }
+ // We track the number of packets that could not be mixed on time, per packet timestamp.
+ void UnderflowOccurred(int64_t source_start, int64_t mix_point, zx_duration_t underflow_duration);
+ // We also track the number of times PART of a packet had to be skipped, per timestamp.
+ void PartialUnderflowOccurred(int64_t source_offset, int64_t mix_offset);
+
// AudioRenderer interface
void SetPcmStreamType(fuchsia::media::AudioStreamType format) final;
void SetStreamType(fuchsia::media::StreamType format) final;
@@ -172,6 +178,9 @@
TimelineFunction ref_clock_to_frac_frames_ FXL_GUARDED_BY(ref_to_ff_lock_);
GenerationId ref_clock_to_frac_frames_gen_ FXL_GUARDED_BY(ref_to_ff_lock_);
+ std::atomic<uint16_t> underflow_count_;
+ std::atomic<uint16_t> partial_underflow_count_;
+
WavWriter<kEnableRendererWavWriters> wav_writer_;
};
