Skip to content

Commit

Permalink
Add new audio metrics histograms covering AudioOutputDevice to OS.
Browse files Browse the repository at this point in the history
We are utilising the new info in
https://source.chromium.org/chromium/chromium/src/+/main:media/base/audio_glitch_info.h
to calculate these stats.

The histogram stuff might look weird. It's to make it faster when
logging it 200 times per second, see this discussion for an
explanation:
https://groups.google.com/a/google.com/g/uma-users/c/8IliQqP6UI4/m/LFX4qb_BDgAJ?utm_medium=email&utm_source=footer

Bug: 1384539
Change-Id: I4f01b82eee21b52ec3d4fafa6fde9d81bb039166
Reviewed-on: https://chromium-review.googlesource.com/c/chromium/src/+/4194273
Reviewed-by: Robert Kaplow <rkaplow@chromium.org>
Reviewed-by: Olga Sharonova <olka@chromium.org>
Commit-Queue: Fredrik Hernqvist <fhernqvist@google.com>
Cr-Commit-Position: refs/heads/main@{#1104460}
  • Loading branch information
Fredrik Hernqvist authored and Chromium LUCI CQ committed Feb 13, 2023
1 parent fe3973b commit 964e72c
Show file tree
Hide file tree
Showing 8 changed files with 566 additions and 1 deletion.
3 changes: 3 additions & 0 deletions media/audio/BUILD.gn
Original file line number Diff line number Diff line change
Expand Up @@ -71,6 +71,8 @@ source_set("audio") {
"audio_device_description.h",
"audio_device_name.cc",
"audio_device_name.h",
"audio_device_stats_reporter.cc",
"audio_device_stats_reporter.h",
"audio_device_thread.cc",
"audio_device_thread.h",
"audio_features.cc",
Expand Down Expand Up @@ -409,6 +411,7 @@ source_set("unit_tests") {
"audio_debug_recording_helper_unittest.cc",
"audio_debug_recording_manager_unittest.cc",
"audio_device_description_unittest.cc",
"audio_device_stats_reporter_unittest.cc",
"audio_encoders_unittest.cc",
"audio_input_device_unittest.cc",
"audio_input_stream_data_interceptor_unittest.cc",
Expand Down
192 changes: 192 additions & 0 deletions media/audio/audio_device_stats_reporter.cc
Original file line number Diff line number Diff line change
@@ -0,0 +1,192 @@
// Copyright 2023 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#include "media/audio/audio_device_stats_reporter.h"
#include "base/check.h"
#include "base/check_op.h"
#include "base/functional/bind.h"
#include "base/logging.h"
#include "base/metrics/histogram.h"
#include "base/metrics/histogram_base.h"
#include "base/metrics/histogram_functions.h"
#include "base/metrics/histogram_macros.h"
#include "base/strings/strcat.h"
#include "base/time/time.h"

namespace media {
namespace {

const char* LatencyToString(AudioLatency::LatencyType latency) {
switch (latency) {
case AudioLatency::LATENCY_EXACT_MS:
return "LatencyExactMs";
case AudioLatency::LATENCY_INTERACTIVE:
return "LatencyInteractive";
case AudioLatency::LATENCY_RTC:
return "LatencyRtc";
case AudioLatency::LATENCY_PLAYBACK:
return "LatencyPlayback";
default:
return "LatencyUnknown";
}
}

} // namespace

AudioDeviceStatsReporter::AudioDeviceStatsReporter(
const AudioParameters& params)
: callback_duration_(params.GetBufferDuration()),
delay_log_callback_(CreateRealtimeCallback(
"Delay",
params.latency_tag(),
/*max_value = */ 1000, // Measured in ms. Allows us to differentiate
// delays up to 1s.
/*bucket_count = */ 50)),
delay_difference_log_callback_(CreateAggregateCallback(
"DelayDifference",
params.latency_tag(),
/*max_value = */ 1000, // Measured in ms. Allows us to differentiate
// delay differences up to 1s.
/*bucket_count = */ 50)),
glitch_count_log_callback_(CreateAggregateCallback(
"GlitchCount",
params.latency_tag(),
/*max_value = */ 1000, // Measured in glitches per 1000 callbacks.
// Unlikely to be higher than 1000.
/*bucket_count = */ 50)),
glitch_duration_log_callback_(CreateAggregateCallback(
"GlitchDuration",
params.latency_tag(),
/*max_value = */ 1000, // Measured in permille.
/*bucket_count = */ 50)) {
CHECK(params.IsValid());
}

void AudioDeviceStatsReporter::ReportCallback(
base::TimeDelta delay,
const media::AudioGlitchInfo& glitch_info) {
// When the stream is started, the first callback always contains a delay of 0
// and empty glitch info. This should not be included in the stats. See
// sync_reader.cc.
if (!discarded_first_callback_) {
discarded_first_callback_ = true;
return;
}

delay_log_callback_.Run(delay.InMilliseconds());

++stats_.callback_count;
stats_.glitch_count += glitch_info.count;
stats_.glitch_duration += glitch_info.duration;
stats_.largest_delay = std::max(delay, stats_.largest_delay);
stats_.smallest_delay = std::min(delay, stats_.smallest_delay);

if (stats_.callback_count >= 1000) {
UploadStats(stats_, SamplingPeriod::kIntervals);
stats_ = {};
stream_is_short_ = false;
}
}

AudioDeviceStatsReporter::~AudioDeviceStatsReporter() {
if (stream_is_short_ && stats_.callback_count > 0) {
UploadStats(stats_, SamplingPeriod::kShort);
}
}

void AudioDeviceStatsReporter::UploadStats(const Stats& stats,
SamplingPeriod sampling_period) {
base::TimeDelta stats_duration = callback_duration_ * stats.callback_count;
DCHECK(stats_duration.is_positive());
int glitch_duration_permille =
std::round(1000 * stats.glitch_duration / stats_duration);

DCHECK_NE(stats.largest_delay, base::TimeDelta::Min());
DCHECK_NE(stats.smallest_delay, base::TimeDelta::Max());
int delay_difference_ms =
(stats.largest_delay - stats.smallest_delay).InMilliseconds();
DCHECK_GE(delay_difference_ms, 0);

glitch_count_log_callback_.Run(stats.glitch_count, sampling_period);
delay_difference_log_callback_.Run(delay_difference_ms, sampling_period);
glitch_duration_log_callback_.Run(glitch_duration_permille, sampling_period);
}

// Used to generate callbacks for:
// Media.AudioOutputDevice.AudioServiceDelayDifference.*.*
// Media.AudioOutputDevice.AudioServiceGlitchCount.*.*
// Media.AudioOutputDevice.AudioServiceDroppedAudio.*.*
AudioDeviceStatsReporter::AggregateLogCallback
AudioDeviceStatsReporter::CreateAggregateCallback(
const std::string& stat_name,
media::AudioLatency::LatencyType latency,
int max_value,
size_t bucket_count) {
std::string base_name(
base::StrCat({"Media.AudioOutputDevice.AudioService", stat_name}));
std::string short_name(base::StrCat({base_name, ".Short"}));
std::string intervals_name(base::StrCat({base_name, ".Intervals"}));
std::string short_with_latency_name(
base::StrCat({short_name, ".", LatencyToString(latency)}));
std::string intervals_with_latency_name(
base::StrCat({intervals_name, ".", LatencyToString(latency)}));

return base::BindRepeating(
[](int max_value, size_t bucket_count, const std::string& short_name,
const std::string& intervals_name,
const std::string& short_with_latency_name,
const std::string& intervals_with_latency_name, int value,
SamplingPeriod sampling_period) {
if (sampling_period == SamplingPeriod::kShort) {
base::UmaHistogramCustomCounts(short_name, value, 1, max_value,
bucket_count);
base::UmaHistogramCustomCounts(short_with_latency_name, value, 1,
max_value, bucket_count);
} else {
base::UmaHistogramCustomCounts(intervals_name, value, 1, max_value,
bucket_count);
base::UmaHistogramCustomCounts(intervals_with_latency_name, value, 1,
max_value, bucket_count);
}
},
max_value, bucket_count, std::move(short_name), std::move(intervals_name),
std::move(short_with_latency_name),
std::move(intervals_with_latency_name));
}

// Used to generate callback for Media.AudioOutputDevice.AudioServiceDelay.*
AudioDeviceStatsReporter::RealtimeLogCallback
AudioDeviceStatsReporter::CreateRealtimeCallback(
const std::string& stat_name,
media::AudioLatency::LatencyType latency,
int max_value,
size_t bucket_count) {
std::string base_name(
base::StrCat({"Media.AudioOutputDevice.AudioService", stat_name}));
std::string base_with_latency_name(
base::StrCat({base_name, ".", LatencyToString(latency)}));

// Since this callback will be called on every call to ReportCallback(), we
// pre-fetch the histograms for efficiency, like the histogram macros do. Note
// that we cannot use the macros here because the histogram names are
// dynamically generated, which is not allowed by the macros.
base::HistogramBase* histogram = base::Histogram::FactoryGet(
std::move(base_name), 1, max_value, bucket_count,
base::HistogramBase::kUmaTargetedHistogramFlag);
base::HistogramBase* histogram_with_latency = base::Histogram::FactoryGet(
std::move(base_with_latency_name), 1, max_value, bucket_count,
base::HistogramBase::kUmaTargetedHistogramFlag);

// Histogram pointers from FactoryGet are not owned by the caller. They are
// never deleted, see crbug.com/79322
return base::BindRepeating(
[](base::HistogramBase* histogram,
base::HistogramBase* histogram_with_latency, int value) {
histogram->Add(value);
histogram_with_latency->Add(value);
},
base::Unretained(histogram), base::Unretained(histogram_with_latency));
}

} // namespace media
92 changes: 92 additions & 0 deletions media/audio/audio_device_stats_reporter.h
Original file line number Diff line number Diff line change
@@ -0,0 +1,92 @@
// Copyright 2023 The Chromium Authors
// Use of this source code is governed by a BSD-style license that can be
// found in the LICENSE file.

#ifndef MEDIA_AUDIO_AUDIO_DEVICE_STATS_REPORTER_H_
#define MEDIA_AUDIO_AUDIO_DEVICE_STATS_REPORTER_H_

#include <list>
#include <string>
#include "base/functional/callback.h"
#include "base/time/time.h"
#include "media/base/audio_glitch_info.h"
#include "media/base/audio_latency.h"
#include "media/base/audio_parameters.h"
#include "media/base/media_export.h"

namespace media {

// Uploads audio UMA stats at the AudioOutputDevice level. Uploads Short stats
// on destruction, for streams shorter than 1000 callbacks. For streams of at
// least 1000 callbacks it uploads Interval stats every 1000 callbacks and drops
// any unuploaded stats on destruction.
class MEDIA_EXPORT AudioDeviceStatsReporter {
public:
explicit AudioDeviceStatsReporter(const AudioParameters& params);
AudioDeviceStatsReporter(const AudioDeviceStatsReporter&) = delete;
AudioDeviceStatsReporter& operator=(const AudioDeviceStatsReporter&) = delete;
virtual ~AudioDeviceStatsReporter();

// Should be called by AudioOutputDevice every time it pulls more data using
// AudioRendererSink::RenderCallback::Render(). Uploads Interval stats every
// 1000 callbacks.
void ReportCallback(base::TimeDelta delay,
const media::AudioGlitchInfo& glitch_info);

private:
// Indicates what period samples are aggregated over. kShort means entire
// streams of less than 1000 callbacks, kIntervals means exactly 1000
// callbacks.
enum class SamplingPeriod { kShort, kIntervals };

struct Stats {
int callback_count = 0;
int glitch_count = 0;
base::TimeDelta glitch_duration;
base::TimeDelta smallest_delay = base::TimeDelta::Max();
base::TimeDelta largest_delay = base::TimeDelta::Min();
};

// Logs data aggregated over intervals.
using AggregateLogCallback =
base::RepeatingCallback<void(int value, SamplingPeriod sampling_period)>;

// Logs data on every callback.
using RealtimeLogCallback = base::RepeatingCallback<void(int value)>;

static AggregateLogCallback CreateAggregateCallback(
const std::string& stat_name,
media::AudioLatency::LatencyType latency,
int max_value,
size_t bucket_count);

static RealtimeLogCallback CreateRealtimeCallback(
const std::string& stat_name,
media::AudioLatency::LatencyType latency,
int max_value,
size_t bucket_count);

void UploadStats(const Stats& stats, SamplingPeriod sampling_period);

Stats stats_;

// The duration that a single callback covers.
const base::TimeDelta callback_duration_;

// Callback functions for writing to the histograms.
const RealtimeLogCallback delay_log_callback_;
const AggregateLogCallback delay_difference_log_callback_;
const AggregateLogCallback glitch_count_log_callback_;
const AggregateLogCallback glitch_duration_log_callback_;

// Whether the stream is shorter than 1000 callbacks.
bool stream_is_short_ = true;

// Whether or not we have received and discarded the data from the first
// callback.
bool discarded_first_callback_ = false;
};

} // namespace media

#endif

0 comments on commit 964e72c

Please sign in to comment.