1 /*
2 * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved.
3 *
4 * Use of this source code is governed by a BSD-style license
5 * that can be found in the LICENSE file in the root of the source
6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree.
9 */
10
11 #include "modules/audio_device/audio_device_buffer.h"
12
13 #include <string.h>
14
15 #include <cmath>
16 #include <cstddef>
17 #include <cstdint>
18
19 #include "common_audio/signal_processing/include/signal_processing_library.h"
20 #include "rtc_base/checks.h"
21 #include "rtc_base/logging.h"
22 #include "rtc_base/time_utils.h"
23 #include "rtc_base/trace_event.h"
24 #include "system_wrappers/include/metrics.h"
25
26 namespace webrtc {
27
28 static const char kTimerQueueName[] = "AudioDeviceBufferTimer";
29
30 // Time between two sucessive calls to LogStats().
31 static const size_t kTimerIntervalInSeconds = 10;
32 static const size_t kTimerIntervalInMilliseconds =
33 kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec;
34 // Min time required to qualify an audio session as a "call". If playout or
35 // recording has been active for less than this time we will not store any
36 // logs or UMA stats but instead consider the call as too short.
37 static const size_t kMinValidCallTimeTimeInSeconds = 10;
38 static const size_t kMinValidCallTimeTimeInMilliseconds =
39 kMinValidCallTimeTimeInSeconds * rtc::kNumMillisecsPerSec;
40 #ifdef AUDIO_DEVICE_PLAYS_SINUS_TONE
41 static const double k2Pi = 6.28318530717959;
42 #endif
43
AudioDeviceBuffer(TaskQueueFactory * task_queue_factory)44 AudioDeviceBuffer::AudioDeviceBuffer(TaskQueueFactory* task_queue_factory)
45 : task_queue_(task_queue_factory->CreateTaskQueue(
46 kTimerQueueName,
47 TaskQueueFactory::Priority::NORMAL)),
48 audio_transport_cb_(nullptr),
49 rec_sample_rate_(0),
50 play_sample_rate_(0),
51 rec_channels_(0),
52 play_channels_(0),
53 playing_(false),
54 recording_(false),
55 typing_status_(false),
56 play_delay_ms_(0),
57 rec_delay_ms_(0),
58 capture_timestamp_ns_(0),
59 num_stat_reports_(0),
60 last_timer_task_time_(0),
61 rec_stat_count_(0),
62 play_stat_count_(0),
63 play_start_time_(0),
64 only_silence_recorded_(true),
65 log_stats_(false) {
66 RTC_LOG(LS_INFO) << "AudioDeviceBuffer::ctor";
67 #ifdef AUDIO_DEVICE_PLAYS_SINUS_TONE
68 phase_ = 0.0;
69 RTC_LOG(LS_WARNING) << "AUDIO_DEVICE_PLAYS_SINUS_TONE is defined!";
70 #endif
71 }
72
~AudioDeviceBuffer()73 AudioDeviceBuffer::~AudioDeviceBuffer() {
74 RTC_DCHECK_RUN_ON(&main_thread_checker_);
75 RTC_DCHECK(!playing_);
76 RTC_DCHECK(!recording_);
77 RTC_LOG(LS_INFO) << "AudioDeviceBuffer::~dtor";
78 }
79
RegisterAudioCallback(AudioTransport * audio_callback)80 int32_t AudioDeviceBuffer::RegisterAudioCallback(
81 AudioTransport* audio_callback) {
82 RTC_DCHECK_RUN_ON(&main_thread_checker_);
83 RTC_DLOG(LS_INFO) << __FUNCTION__;
84 if (playing_ || recording_) {
85 RTC_LOG(LS_ERROR) << "Failed to set audio transport since media was active";
86 return -1;
87 }
88 audio_transport_cb_ = audio_callback;
89 return 0;
90 }
91
StartPlayout()92 void AudioDeviceBuffer::StartPlayout() {
93 RTC_DCHECK_RUN_ON(&main_thread_checker_);
94 // TODO(henrika): allow for usage of DCHECK(!playing_) here instead. Today the
95 // ADM allows calling Start(), Start() by ignoring the second call but it
96 // makes more sense to only allow one call.
97 if (playing_) {
98 return;
99 }
100 RTC_DLOG(LS_INFO) << __FUNCTION__;
101 // Clear members tracking playout stats and do it on the task queue.
102 task_queue_.PostTask([this] { ResetPlayStats(); });
103 // Start a periodic timer based on task queue if not already done by the
104 // recording side.
105 if (!recording_) {
106 StartPeriodicLogging();
107 }
108 const int64_t now_time = rtc::TimeMillis();
109 // Clear members that are only touched on the main (creating) thread.
110 play_start_time_ = now_time;
111 playing_ = true;
112 }
113
StartRecording()114 void AudioDeviceBuffer::StartRecording() {
115 RTC_DCHECK_RUN_ON(&main_thread_checker_);
116 if (recording_) {
117 return;
118 }
119 RTC_DLOG(LS_INFO) << __FUNCTION__;
120 // Clear members tracking recording stats and do it on the task queue.
121 task_queue_.PostTask([this] { ResetRecStats(); });
122 // Start a periodic timer based on task queue if not already done by the
123 // playout side.
124 if (!playing_) {
125 StartPeriodicLogging();
126 }
127 // Clear members that will be touched on the main (creating) thread.
128 rec_start_time_ = rtc::TimeMillis();
129 recording_ = true;
130 // And finally a member which can be modified on the native audio thread.
131 // It is safe to do so since we know by design that the owning ADM has not
132 // yet started the native audio recording.
133 only_silence_recorded_ = true;
134 }
135
StopPlayout()136 void AudioDeviceBuffer::StopPlayout() {
137 RTC_DCHECK_RUN_ON(&main_thread_checker_);
138 if (!playing_) {
139 return;
140 }
141 RTC_DLOG(LS_INFO) << __FUNCTION__;
142 playing_ = false;
143 // Stop periodic logging if no more media is active.
144 if (!recording_) {
145 StopPeriodicLogging();
146 }
147 RTC_LOG(LS_INFO) << "total playout time: "
148 << rtc::TimeSince(play_start_time_);
149 }
150
StopRecording()151 void AudioDeviceBuffer::StopRecording() {
152 RTC_DCHECK_RUN_ON(&main_thread_checker_);
153 if (!recording_) {
154 return;
155 }
156 RTC_DLOG(LS_INFO) << __FUNCTION__;
157 recording_ = false;
158 // Stop periodic logging if no more media is active.
159 if (!playing_) {
160 StopPeriodicLogging();
161 }
162 // Add UMA histogram to keep track of the case when only zeros have been
163 // recorded. Measurements (max of absolute level) are taken twice per second,
164 // which means that if e.g 10 seconds of audio has been recorded, a total of
165 // 20 level estimates must all be identical to zero to trigger the histogram.
166 // `only_silence_recorded_` can only be cleared on the native audio thread
167 // that drives audio capture but we know by design that the audio has stopped
168 // when this method is called, hence there should not be aby conflicts. Also,
169 // the fact that `only_silence_recorded_` can be affected during the complete
170 // call makes chances of conflicts with potentially one last callback very
171 // small.
172 const size_t time_since_start = rtc::TimeSince(rec_start_time_);
173 if (time_since_start > kMinValidCallTimeTimeInMilliseconds) {
174 const int only_zeros = static_cast<int>(only_silence_recorded_);
175 RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros", only_zeros);
176 RTC_LOG(LS_INFO) << "HISTOGRAM(WebRTC.Audio.RecordedOnlyZeros): "
177 << only_zeros;
178 }
179 RTC_LOG(LS_INFO) << "total recording time: " << time_since_start;
180 }
181
SetRecordingSampleRate(uint32_t fsHz)182 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) {
183 RTC_LOG(LS_INFO) << "SetRecordingSampleRate(" << fsHz << ")";
184 rec_sample_rate_ = fsHz;
185 return 0;
186 }
187
SetPlayoutSampleRate(uint32_t fsHz)188 int32_t AudioDeviceBuffer::SetPlayoutSampleRate(uint32_t fsHz) {
189 RTC_LOG(LS_INFO) << "SetPlayoutSampleRate(" << fsHz << ")";
190 play_sample_rate_ = fsHz;
191 return 0;
192 }
193
RecordingSampleRate() const194 uint32_t AudioDeviceBuffer::RecordingSampleRate() const {
195 return rec_sample_rate_;
196 }
197
PlayoutSampleRate() const198 uint32_t AudioDeviceBuffer::PlayoutSampleRate() const {
199 return play_sample_rate_;
200 }
201
SetRecordingChannels(size_t channels)202 int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) {
203 RTC_LOG(LS_INFO) << "SetRecordingChannels(" << channels << ")";
204 rec_channels_ = channels;
205 return 0;
206 }
207
SetPlayoutChannels(size_t channels)208 int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) {
209 RTC_LOG(LS_INFO) << "SetPlayoutChannels(" << channels << ")";
210 play_channels_ = channels;
211 return 0;
212 }
213
RecordingChannels() const214 size_t AudioDeviceBuffer::RecordingChannels() const {
215 return rec_channels_;
216 }
217
PlayoutChannels() const218 size_t AudioDeviceBuffer::PlayoutChannels() const {
219 return play_channels_;
220 }
221
SetTypingStatus(bool typing_status)222 int32_t AudioDeviceBuffer::SetTypingStatus(bool typing_status) {
223 typing_status_ = typing_status;
224 return 0;
225 }
226
SetVQEData(int play_delay_ms,int rec_delay_ms)227 void AudioDeviceBuffer::SetVQEData(int play_delay_ms, int rec_delay_ms) {
228 play_delay_ms_ = play_delay_ms;
229 rec_delay_ms_ = rec_delay_ms;
230 }
231
SetRecordedBuffer(const void * audio_buffer,size_t samples_per_channel)232 int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
233 size_t samples_per_channel) {
234 return SetRecordedBuffer(audio_buffer, samples_per_channel, 0);
235 }
236
SetRecordedBuffer(const void * audio_buffer,size_t samples_per_channel,int64_t capture_timestamp_ns)237 int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
238 size_t samples_per_channel,
239 int64_t capture_timestamp_ns) {
240 // Copy the complete input buffer to the local buffer.
241 const size_t old_size = rec_buffer_.size();
242 rec_buffer_.SetData(static_cast<const int16_t*>(audio_buffer),
243 rec_channels_ * samples_per_channel);
244 // Keep track of the size of the recording buffer. Only updated when the
245 // size changes, which is a rare event.
246 if (old_size != rec_buffer_.size()) {
247 RTC_LOG(LS_INFO) << "Size of recording buffer: " << rec_buffer_.size();
248 }
249
250 // If the timestamp is less then or equal to zero, it's not valid and are
251 // ignored. If we do antimestamp alignment on them they might accidentally
252 // become greater then zero, and will be handled as if they were a correct
253 // timestamp.
254 capture_timestamp_ns_ =
255 (capture_timestamp_ns > 0)
256 ? rtc::kNumNanosecsPerMicrosec *
257 timestamp_aligner_.TranslateTimestamp(
258 capture_timestamp_ns_ / rtc::kNumNanosecsPerMicrosec,
259 rtc::TimeMicros())
260 : capture_timestamp_ns;
261 // Derive a new level value twice per second and check if it is non-zero.
262 int16_t max_abs = 0;
263 RTC_DCHECK_LT(rec_stat_count_, 50);
264 if (++rec_stat_count_ >= 50) {
265 // Returns the largest absolute value in a signed 16-bit vector.
266 max_abs = WebRtcSpl_MaxAbsValueW16(rec_buffer_.data(), rec_buffer_.size());
267 rec_stat_count_ = 0;
268 // Set `only_silence_recorded_` to false as soon as at least one detection
269 // of a non-zero audio packet is found. It can only be restored to true
270 // again by restarting the call.
271 if (max_abs > 0) {
272 only_silence_recorded_ = false;
273 }
274 }
275 // Update recording stats which is used as base for periodic logging of the
276 // audio input state.
277 UpdateRecStats(max_abs, samples_per_channel);
278 return 0;
279 }
280
DeliverRecordedData()281 int32_t AudioDeviceBuffer::DeliverRecordedData() {
282 if (!audio_transport_cb_) {
283 RTC_LOG(LS_WARNING) << "Invalid audio transport";
284 return 0;
285 }
286 const size_t frames = rec_buffer_.size() / rec_channels_;
287 const size_t bytes_per_frame = rec_channels_ * sizeof(int16_t);
288 uint32_t new_mic_level_dummy = 0;
289 uint32_t total_delay_ms = play_delay_ms_ + rec_delay_ms_;
290 int32_t res = audio_transport_cb_->RecordedDataIsAvailable(
291 rec_buffer_.data(), frames, bytes_per_frame, rec_channels_,
292 rec_sample_rate_, total_delay_ms, 0, 0, typing_status_,
293 new_mic_level_dummy, capture_timestamp_ns_);
294 if (res == -1) {
295 RTC_LOG(LS_ERROR) << "RecordedDataIsAvailable() failed";
296 }
297 return 0;
298 }
299
RequestPlayoutData(size_t samples_per_channel)300 int32_t AudioDeviceBuffer::RequestPlayoutData(size_t samples_per_channel) {
301 TRACE_EVENT1("webrtc", "AudioDeviceBuffer::RequestPlayoutData",
302 "samples_per_channel", samples_per_channel);
303
304 // The consumer can change the requested size on the fly and we therefore
305 // resize the buffer accordingly. Also takes place at the first call to this
306 // method.
307 const size_t total_samples = play_channels_ * samples_per_channel;
308 if (play_buffer_.size() != total_samples) {
309 play_buffer_.SetSize(total_samples);
310 RTC_LOG(LS_INFO) << "Size of playout buffer: " << play_buffer_.size();
311 }
312
313 size_t num_samples_out(0);
314 // It is currently supported to start playout without a valid audio
315 // transport object. Leads to warning and silence.
316 if (!audio_transport_cb_) {
317 RTC_LOG(LS_WARNING) << "Invalid audio transport";
318 return 0;
319 }
320
321 // Retrieve new 16-bit PCM audio data using the audio transport instance.
322 int64_t elapsed_time_ms = -1;
323 int64_t ntp_time_ms = -1;
324 const size_t bytes_per_frame = play_channels_ * sizeof(int16_t);
325 uint32_t res = audio_transport_cb_->NeedMorePlayData(
326 samples_per_channel, bytes_per_frame, play_channels_, play_sample_rate_,
327 play_buffer_.data(), num_samples_out, &elapsed_time_ms, &ntp_time_ms);
328 if (res != 0) {
329 RTC_LOG(LS_ERROR) << "NeedMorePlayData() failed";
330 }
331
332 // Derive a new level value twice per second.
333 int16_t max_abs = 0;
334 RTC_DCHECK_LT(play_stat_count_, 50);
335 if (++play_stat_count_ >= 50) {
336 // Returns the largest absolute value in a signed 16-bit vector.
337 max_abs =
338 WebRtcSpl_MaxAbsValueW16(play_buffer_.data(), play_buffer_.size());
339 play_stat_count_ = 0;
340 }
341 // Update playout stats which is used as base for periodic logging of the
342 // audio output state.
343 UpdatePlayStats(max_abs, num_samples_out / play_channels_);
344 return static_cast<int32_t>(num_samples_out / play_channels_);
345 }
346
GetPlayoutData(void * audio_buffer)347 int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) {
348 RTC_DCHECK_GT(play_buffer_.size(), 0);
349 #ifdef AUDIO_DEVICE_PLAYS_SINUS_TONE
350 const double phase_increment =
351 k2Pi * 440.0 / static_cast<double>(play_sample_rate_);
352 int16_t* destination_r = reinterpret_cast<int16_t*>(audio_buffer);
353 if (play_channels_ == 1) {
354 for (size_t i = 0; i < play_buffer_.size(); ++i) {
355 destination_r[i] = static_cast<int16_t>((sin(phase_) * (1 << 14)));
356 phase_ += phase_increment;
357 }
358 } else if (play_channels_ == 2) {
359 for (size_t i = 0; i < play_buffer_.size() / 2; ++i) {
360 destination_r[2 * i] = destination_r[2 * i + 1] =
361 static_cast<int16_t>((sin(phase_) * (1 << 14)));
362 phase_ += phase_increment;
363 }
364 }
365 #else
366 memcpy(audio_buffer, play_buffer_.data(),
367 play_buffer_.size() * sizeof(int16_t));
368 #endif
369 // Return samples per channel or number of frames.
370 return static_cast<int32_t>(play_buffer_.size() / play_channels_);
371 }
372
StartPeriodicLogging()373 void AudioDeviceBuffer::StartPeriodicLogging() {
374 task_queue_.PostTask([this] { LogStats(AudioDeviceBuffer::LOG_START); });
375 }
376
StopPeriodicLogging()377 void AudioDeviceBuffer::StopPeriodicLogging() {
378 task_queue_.PostTask([this] { LogStats(AudioDeviceBuffer::LOG_STOP); });
379 }
380
LogStats(LogState state)381 void AudioDeviceBuffer::LogStats(LogState state) {
382 RTC_DCHECK_RUN_ON(&task_queue_);
383 int64_t now_time = rtc::TimeMillis();
384
385 if (state == AudioDeviceBuffer::LOG_START) {
386 // Reset counters at start. We will not add any logging in this state but
387 // the timer will started by posting a new (delayed) task.
388 num_stat_reports_ = 0;
389 last_timer_task_time_ = now_time;
390 log_stats_ = true;
391 } else if (state == AudioDeviceBuffer::LOG_STOP) {
392 // Stop logging and posting new tasks.
393 log_stats_ = false;
394 } else if (state == AudioDeviceBuffer::LOG_ACTIVE) {
395 // Keep logging unless logging was disabled while task was posted.
396 }
397
398 // Avoid adding more logs since we are in STOP mode.
399 if (!log_stats_) {
400 return;
401 }
402
403 int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds;
404 int64_t time_since_last = rtc::TimeDiff(now_time, last_timer_task_time_);
405 last_timer_task_time_ = now_time;
406
407 Stats stats;
408 {
409 MutexLock lock(&lock_);
410 stats = stats_;
411 stats_.max_rec_level = 0;
412 stats_.max_play_level = 0;
413 }
414
415 // Cache current sample rate from atomic members.
416 const uint32_t rec_sample_rate = rec_sample_rate_;
417 const uint32_t play_sample_rate = play_sample_rate_;
418
419 // Log the latest statistics but skip the first two rounds just after state
420 // was set to LOG_START to ensure that we have at least one full stable
421 // 10-second interval for sample-rate estimation. Hence, first printed log
422 // will be after ~20 seconds.
423 if (++num_stat_reports_ > 2 &&
424 static_cast<size_t>(time_since_last) > kTimerIntervalInMilliseconds / 2) {
425 uint32_t diff_samples = stats.rec_samples - last_stats_.rec_samples;
426 float rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
427 uint32_t abs_diff_rate_in_percent = 0;
428 if (rec_sample_rate > 0 && rate > 0) {
429 abs_diff_rate_in_percent = static_cast<uint32_t>(
430 0.5f +
431 ((100.0f * std::abs(rate - rec_sample_rate)) / rec_sample_rate));
432 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Audio.RecordSampleRateOffsetInPercent",
433 abs_diff_rate_in_percent);
434 RTC_LOG(LS_INFO) << "[REC : " << time_since_last << "msec, "
435 << rec_sample_rate / 1000 << "kHz] callbacks: "
436 << stats.rec_callbacks - last_stats_.rec_callbacks
437 << ", "
438 "samples: "
439 << diff_samples
440 << ", "
441 "rate: "
442 << static_cast<int>(rate + 0.5)
443 << ", "
444 "rate diff: "
445 << abs_diff_rate_in_percent
446 << "%, "
447 "level: "
448 << stats.max_rec_level;
449 }
450
451 diff_samples = stats.play_samples - last_stats_.play_samples;
452 rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
453 abs_diff_rate_in_percent = 0;
454 if (play_sample_rate > 0 && rate > 0) {
455 abs_diff_rate_in_percent = static_cast<uint32_t>(
456 0.5f +
457 ((100.0f * std::abs(rate - play_sample_rate)) / play_sample_rate));
458 RTC_HISTOGRAM_PERCENTAGE("WebRTC.Audio.PlayoutSampleRateOffsetInPercent",
459 abs_diff_rate_in_percent);
460 RTC_LOG(LS_INFO) << "[PLAY: " << time_since_last << "msec, "
461 << play_sample_rate / 1000 << "kHz] callbacks: "
462 << stats.play_callbacks - last_stats_.play_callbacks
463 << ", "
464 "samples: "
465 << diff_samples
466 << ", "
467 "rate: "
468 << static_cast<int>(rate + 0.5)
469 << ", "
470 "rate diff: "
471 << abs_diff_rate_in_percent
472 << "%, "
473 "level: "
474 << stats.max_play_level;
475 }
476 }
477 last_stats_ = stats;
478
479 int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis();
480 RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
481
482 // Keep posting new (delayed) tasks until state is changed to kLogStop.
483 task_queue_.PostDelayedTask(
484 [this] { AudioDeviceBuffer::LogStats(AudioDeviceBuffer::LOG_ACTIVE); },
485 TimeDelta::Millis(time_to_wait_ms));
486 }
487
ResetRecStats()488 void AudioDeviceBuffer::ResetRecStats() {
489 RTC_DCHECK_RUN_ON(&task_queue_);
490 last_stats_.ResetRecStats();
491 MutexLock lock(&lock_);
492 stats_.ResetRecStats();
493 }
494
ResetPlayStats()495 void AudioDeviceBuffer::ResetPlayStats() {
496 RTC_DCHECK_RUN_ON(&task_queue_);
497 last_stats_.ResetPlayStats();
498 MutexLock lock(&lock_);
499 stats_.ResetPlayStats();
500 }
501
UpdateRecStats(int16_t max_abs,size_t samples_per_channel)502 void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs,
503 size_t samples_per_channel) {
504 MutexLock lock(&lock_);
505 ++stats_.rec_callbacks;
506 stats_.rec_samples += samples_per_channel;
507 if (max_abs > stats_.max_rec_level) {
508 stats_.max_rec_level = max_abs;
509 }
510 }
511
UpdatePlayStats(int16_t max_abs,size_t samples_per_channel)512 void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs,
513 size_t samples_per_channel) {
514 MutexLock lock(&lock_);
515 ++stats_.play_callbacks;
516 stats_.play_samples += samples_per_channel;
517 if (max_abs > stats_.max_play_level) {
518 stats_.max_play_level = max_abs;
519 }
520 }
521
522 } // namespace webrtc
523