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