diff --git a/webrtc/modules/audio_device/audio_device_buffer.cc b/webrtc/modules/audio_device/audio_device_buffer.cc index f74d3d58e1..ec6a8be490 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.cc +++ b/webrtc/modules/audio_device/audio_device_buffer.cc @@ -30,11 +30,18 @@ static const char kTimerQueueName[] = "AudioDeviceBufferTimer"; static const size_t kTimerIntervalInSeconds = 10; static const size_t kTimerIntervalInMilliseconds = kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec; +// Min time required to qualify an audio session as a "call". If playout or +// recording has been active for less than this time we will not store any +// logs or UMA stats but instead consider the call as too short. +static const size_t kMinValidCallTimeTimeInSeconds = 10; +static const size_t kMinValidCallTimeTimeInMilliseconds = + kMinValidCallTimeTimeInSeconds * rtc::kNumMillisecsPerSec; AudioDeviceBuffer::AudioDeviceBuffer() : audio_transport_cb_(nullptr), task_queue_(kTimerQueueName), - timer_has_started_(false), + playing_(false), + recording_(false), rec_sample_rate_(0), play_sample_rate_(0), rec_channels_(0), @@ -56,46 +63,22 @@ AudioDeviceBuffer::AudioDeviceBuffer() last_rec_samples_(0), play_samples_(0), last_play_samples_(0), - last_log_stat_time_(0), + last_timer_task_time_(0), max_rec_level_(0), max_play_level_(0), - num_rec_level_is_zero_(0), rec_stat_count_(0), - play_stat_count_(0) { + play_stat_count_(0), + play_start_time_(0), + rec_start_time_(0), + only_silence_recorded_(true) { LOG(INFO) << "AudioDeviceBuffer::ctor"; } AudioDeviceBuffer::~AudioDeviceBuffer() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); + RTC_DCHECK(!playing_); + RTC_DCHECK(!recording_); LOG(INFO) << "AudioDeviceBuffer::~dtor"; - - size_t total_diff_time = 0; - int num_measurements = 0; - LOG(INFO) << "[playout diff time => #measurements]"; - for (size_t diff = 0; diff < arraysize(playout_diff_times_); ++diff) { - uint32_t num_elements = playout_diff_times_[diff]; - if (num_elements > 0) { - total_diff_time += num_elements * diff; - num_measurements += num_elements; - LOG(INFO) << "[" << diff << " => " << num_elements << "]"; - } - } - if (num_measurements > 0) { - LOG(INFO) << "total_diff_time: " << total_diff_time; - LOG(INFO) << "num_measurements: " << num_measurements; - LOG(INFO) << "average: " - << static_cast(total_diff_time) / num_measurements; - } - - // Add UMA histogram to keep track of the case when only zeros have been - // recorded. Ensure that recording callbacks have started and that at least - // one timer event has been able to update |num_rec_level_is_zero_|. - // I am avoiding use of the task queue here since we are under destruction - // and reading these members on the creating thread feels safe. - if (rec_callbacks_ > 0 && num_stat_reports_ > 0) { - RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros", - static_cast(num_stat_reports_ == num_rec_level_is_zero_)); - } } int32_t AudioDeviceBuffer::RegisterAudioCallback( @@ -106,26 +89,116 @@ int32_t AudioDeviceBuffer::RegisterAudioCallback( return 0; } -int32_t AudioDeviceBuffer::InitPlayout() { - LOG(INFO) << __FUNCTION__; +void AudioDeviceBuffer::StartPlayout() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); - ResetPlayStats(); - if (!timer_has_started_) { - StartTimer(); - timer_has_started_ = true; + // TODO(henrika): allow for usage of DCHECK(!playing_) here instead. Today the + // ADM allows calling Start(), Start() by ignoring the second call but it + // makes more sense to only allow one call. + if (playing_) { + return; } - return 0; + LOG(INFO) << __FUNCTION__; + // Clear members tracking playout stats and do it on the task queue. + task_queue_.PostTask([this] { ResetPlayStats(); }); + // Start a periodic timer based on task queue if not already done by the + // recording side. + if (!recording_) { + StartPeriodicLogging(); + } + const uint64_t now_time = rtc::TimeMillis(); + // Clear members that are only touched on the main (creating) thread. + play_start_time_ = now_time; + last_playout_time_ = now_time; + playing_ = true; } -int32_t AudioDeviceBuffer::InitRecording() { - LOG(INFO) << __FUNCTION__; +void AudioDeviceBuffer::StartRecording() { RTC_DCHECK(thread_checker_.CalledOnValidThread()); - ResetRecStats(); - if (!timer_has_started_) { - StartTimer(); - timer_has_started_ = true; + if (recording_) { + return; } - return 0; + LOG(INFO) << __FUNCTION__; + // Clear members tracking recording stats and do it on the task queue. + task_queue_.PostTask([this] { ResetRecStats(); }); + // Start a periodic timer based on task queue if not already done by the + // playout side. + if (!playing_) { + StartPeriodicLogging(); + } + // Clear members that will be touched on the main (creating) thread. + rec_start_time_ = rtc::TimeMillis(); + recording_ = true; + // And finally a member which can be modified on the native audio thread. + // It is safe to do so since we know by design that the owning ADM has not + // yet started the native audio recording. + only_silence_recorded_ = true; +} + +void AudioDeviceBuffer::StopPlayout() { + RTC_DCHECK(thread_checker_.CalledOnValidThread()); + if (!playing_) { + return; + } + LOG(INFO) << __FUNCTION__; + playing_ = false; + // Stop periodic logging if no more media is active. + if (!recording_) { + StopPeriodicLogging(); + } + // Add diagnostic logging of delta times for playout callbacks. We are doing + // this wihout a lock since playout should be stopped by now and it a minor + // conflict during stop will not have a great impact on the total statistics. + const size_t time_since_start = rtc::TimeSince(play_start_time_); + if (time_since_start > kMinValidCallTimeTimeInMilliseconds) { + size_t total_diff_time = 0; + int num_measurements = 0; + LOG(INFO) << "[playout diff time => #measurements]"; + for (size_t diff = 0; diff < arraysize(playout_diff_times_); ++diff) { + uint32_t num_elements = playout_diff_times_[diff]; + if (num_elements > 0) { + total_diff_time += num_elements * diff; + num_measurements += num_elements; + LOG(INFO) << "[" << diff << " => " << num_elements << "]"; + } + } + if (num_measurements > 0) { + LOG(INFO) << "total_diff_time: " << total_diff_time << ", " + << "num_measurements: " << num_measurements << ", " + << "average: " + << static_cast(total_diff_time) / num_measurements; + } + } + LOG(INFO) << "total playout time: " << time_since_start; +} + +void AudioDeviceBuffer::StopRecording() { + RTC_DCHECK(thread_checker_.CalledOnValidThread()); + if (!recording_) { + return; + } + LOG(INFO) << __FUNCTION__; + recording_ = false; + // Stop periodic logging if no more media is active. + if (!playing_) { + StopPeriodicLogging(); + } + // Add UMA histogram to keep track of the case when only zeros have been + // recorded. Measurements (max of absolute level) are taken twice per second, + // which means that if e.g 10 seconds of audio has been recorded, a total of + // 20 level estimates must all be identical to zero to trigger the histogram. + // |only_silence_recorded_| can only be cleared on the native audio thread + // that drives audio capture but we know by design that the audio has stopped + // when this method is called, hence there should not be aby conflicts. Also, + // the fact that |only_silence_recorded_| can be affected during the complete + // call makes chances of conflicts with potentially one last callback very + // small. + const size_t time_since_start = rtc::TimeSince(rec_start_time_); + if (time_since_start > kMinValidCallTimeTimeInMilliseconds) { + const int only_zeros = static_cast(only_silence_recorded_); + RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros", only_zeros); + LOG(INFO) << "HISTOGRAM(WebRTC.Audio.RecordedOnlyZeros): " << only_zeros; + } + LOG(INFO) << "total recording time: " << time_since_start; } int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) { @@ -249,7 +322,7 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer, if (old_size != rec_buffer_.size()) { LOG(LS_INFO) << "Size of recording buffer: " << rec_buffer_.size(); } - // Derive a new level value twice per second. + // Derive a new level value twice per second and check if it is non-zero. int16_t max_abs = 0; RTC_DCHECK_LT(rec_stat_count_, 50); if (++rec_stat_count_ >= 50) { @@ -258,13 +331,19 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer, max_abs = WebRtcSpl_MaxAbsValueW16( reinterpret_cast(rec_buffer_.data()), size); rec_stat_count_ = 0; + // Set |only_silence_recorded_| to false as soon as at least one detection + // of a non-zero audio packet is found. It can only be restored to true + // again by restarting the call. + if (max_abs > 0) { + only_silence_recorded_ = false; + } } // Update some stats but do it on the task queue to ensure that the members // are modified and read on the same thread. Note that |max_abs| will be // zero in most calls and then have no effect of the stats. It is only updated // approximately two times per second and can then change the stats. - task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this, - max_abs, num_samples)); + task_queue_.PostTask( + [this, max_abs, num_samples] { UpdateRecStats(max_abs, num_samples); }); return 0; } @@ -320,24 +399,26 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t num_samples) { LOG(LS_INFO) << "Size of playout buffer: " << play_buffer_.size(); } - rtc::CritScope lock(&lock_cb_); - - // It is currently supported to start playout without a valid audio - // transport object. Leads to warning and silence. - if (!audio_transport_cb_) { - LOG(LS_WARNING) << "Invalid audio transport"; - return 0; - } - - // Retrieve new 16-bit PCM audio data using the audio transport instance. - int64_t elapsed_time_ms = -1; - int64_t ntp_time_ms = -1; size_t num_samples_out(0); - uint32_t res = audio_transport_cb_->NeedMorePlayData( - num_samples, play_bytes_per_sample_, play_channels, play_sample_rate_, - play_buffer_.data(), num_samples_out, &elapsed_time_ms, &ntp_time_ms); - if (res != 0) { - LOG(LS_ERROR) << "NeedMorePlayData() failed"; + { + rtc::CritScope lock(&lock_cb_); + + // It is currently supported to start playout without a valid audio + // transport object. Leads to warning and silence. + if (!audio_transport_cb_) { + LOG(LS_WARNING) << "Invalid audio transport"; + return 0; + } + + // Retrieve new 16-bit PCM audio data using the audio transport instance. + int64_t elapsed_time_ms = -1; + int64_t ntp_time_ms = -1; + uint32_t res = audio_transport_cb_->NeedMorePlayData( + num_samples, play_bytes_per_sample_, play_channels, play_sample_rate_, + play_buffer_.data(), num_samples_out, &elapsed_time_ms, &ntp_time_ms); + if (res != 0) { + LOG(LS_ERROR) << "NeedMorePlayData() failed"; + } } // Derive a new level value twice per second. @@ -354,8 +435,9 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t num_samples) { // are modified and read on the same thread. Note that |max_abs| will be // zero in most calls and then have no effect of the stats. It is only updated // approximately two times per second and can then change the stats. - task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this, - max_abs, num_samples_out)); + task_queue_.PostTask([this, max_abs, num_samples_out] { + UpdatePlayStats(max_abs, num_samples_out); + }); return static_cast(num_samples_out); } @@ -369,24 +451,37 @@ int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) { return static_cast(play_buffer_.size() / play_bytes_per_sample); } -void AudioDeviceBuffer::StartTimer() { - num_stat_reports_ = 0; - last_log_stat_time_ = rtc::TimeMillis(); - task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this), - kTimerIntervalInMilliseconds); +void AudioDeviceBuffer::StartPeriodicLogging() { + task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this, + AudioDeviceBuffer::LOG_START)); } -void AudioDeviceBuffer::LogStats() { +void AudioDeviceBuffer::StopPeriodicLogging() { + task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this, + AudioDeviceBuffer::LOG_STOP)); +} + +void AudioDeviceBuffer::LogStats(LogState state) { RTC_DCHECK(task_queue_.IsCurrent()); - int64_t now_time = rtc::TimeMillis(); - int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds; - int64_t time_since_last = rtc::TimeDiff(now_time, last_log_stat_time_); - last_log_stat_time_ = now_time; + if (state == AudioDeviceBuffer::LOG_START) { + // Reset counters at start. We will not add any logging in this state but + // the timer will started by posting a new (delayed) task. + num_stat_reports_ = 0; + last_timer_task_time_ = now_time; + } else if (state == AudioDeviceBuffer::LOG_STOP) { + // Stop logging and posting new tasks. + return; + } else if (state == AudioDeviceBuffer::LOG_ACTIVE) { + // Default state. Just keep on logging. + } - // Log the latest statistics but skip the first 10 seconds since we are not - // sure of the exact starting point. I.e., the first log printout will be - // after ~20 seconds. + int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds; + int64_t time_since_last = rtc::TimeDiff(now_time, last_timer_task_time_); + last_timer_task_time_ = now_time; + + // Log the latest statistics but skip the first round just after state was + // set to LOG_START. Hence, first printed log will be after ~10 seconds. if (++num_stat_reports_ > 1 && time_since_last > 0) { uint32_t diff_samples = rec_samples_ - last_rec_samples_; float rate = diff_samples / (static_cast(time_since_last) / 1000.0); @@ -409,12 +504,6 @@ void AudioDeviceBuffer::LogStats() { << "level: " << max_play_level_; } - // Count number of times we detect "no audio" corresponding to a case where - // all level measurements have been zero. - if (max_rec_level_ == 0) { - ++num_rec_level_is_zero_; - } - last_rec_callbacks_ = rec_callbacks_; last_play_callbacks_ = play_callbacks_; last_rec_samples_ = rec_samples_; @@ -425,23 +514,23 @@ void AudioDeviceBuffer::LogStats() { int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis(); RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval"; - // Update some stats but do it on the task queue to ensure that access of - // members is serialized hence avoiding usage of locks. - task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this), + // Keep posting new (delayed) tasks until state is changed to kLogStop. + task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this, + AudioDeviceBuffer::LOG_ACTIVE), time_to_wait_ms); } void AudioDeviceBuffer::ResetRecStats() { + RTC_DCHECK(task_queue_.IsCurrent()); rec_callbacks_ = 0; last_rec_callbacks_ = 0; rec_samples_ = 0; last_rec_samples_ = 0; max_rec_level_ = 0; - num_rec_level_is_zero_ = 0; } void AudioDeviceBuffer::ResetPlayStats() { - last_playout_time_ = rtc::TimeMillis(); + RTC_DCHECK(task_queue_.IsCurrent()); play_callbacks_ = 0; last_play_callbacks_ = 0; play_samples_ = 0; diff --git a/webrtc/modules/audio_device/audio_device_buffer.h b/webrtc/modules/audio_device/audio_device_buffer.h index 6967ebd757..7e9f3e3eec 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.h +++ b/webrtc/modules/audio_device/audio_device_buffer.h @@ -30,14 +30,22 @@ class AudioDeviceObserver; class AudioDeviceBuffer { public: + enum LogState { + LOG_START = 0, + LOG_STOP, + LOG_ACTIVE, + }; + AudioDeviceBuffer(); virtual ~AudioDeviceBuffer(); void SetId(uint32_t id) {}; int32_t RegisterAudioCallback(AudioTransport* audio_callback); - int32_t InitPlayout(); - int32_t InitRecording(); + void StartPlayout(); + void StartRecording(); + void StopPlayout(); + void StopRecording(); int32_t SetRecordingSampleRate(uint32_t fsHz); int32_t SetPlayoutSampleRate(uint32_t fsHz); @@ -72,16 +80,17 @@ class AudioDeviceBuffer { int32_t SetTypingStatus(bool typing_status); private: - // Posts the first delayed task in the task queue and starts the periodic - // timer. - void StartTimer(); + // Starts/stops periodic logging of audio stats. + void StartPeriodicLogging(); + void StopPeriodicLogging(); // Called periodically on the internal thread created by the TaskQueue. - void LogStats(); - - // Clears all members tracking stats for recording and playout. - void ResetRecStats(); - void ResetPlayStats(); + // Updates some stats but dooes it on the task queue to ensure that access of + // members is serialized hence avoiding usage of locks. + // state = LOG_START => members are initialized and the timer starts. + // state = LOG_STOP => no logs are printed and the timer stops. + // state = LOG_ACTIVE => logs are printed and the timer is kept alive. + void LogStats(LogState state); // Updates counters in each play/record callback but does it on the task // queue to ensure that they can be read by LogStats() without any locks since @@ -89,6 +98,11 @@ class AudioDeviceBuffer { void UpdateRecStats(int16_t max_abs, size_t num_samples); void UpdatePlayStats(int16_t max_abs, size_t num_samples); + // Clears all members tracking stats for recording and playout. + // These methods both run on the task queue. + void ResetRecStats(); + void ResetPlayStats(); + // Ensures that methods are called on the same thread as the thread that // creates this object. rtc::ThreadChecker thread_checker_; @@ -107,8 +121,11 @@ class AudioDeviceBuffer { // each task. rtc::TaskQueue task_queue_; - // Ensures that the timer is only started once. - bool timer_has_started_; + // Keeps track of if playout/recording are active or not. A combination + // of these states are used to determine when to start and stop the timer. + // Only used on the creating thread and not used to control any media flow. + bool playing_; + bool recording_; // Sample rate in Hertz. uint32_t rec_sample_rate_; @@ -173,8 +190,8 @@ class AudioDeviceBuffer { // Total number of played samples stored at the previous timer task. uint64_t last_play_samples_; - // Time stamp of last stat report. - uint64_t last_log_stat_time_; + // Time stamp of last timer task (drives logging). + uint64_t last_timer_task_time_; // Time stamp of last playout callback. uint64_t last_playout_time_; @@ -196,18 +213,19 @@ class AudioDeviceBuffer { // where a new measurement is done twice per second. int16_t max_play_level_; - // Counts number of times we detect "no audio" corresponding to a case where - // all level measurements since the last log has been exactly zero. - // In other words: this counter is incremented only if 20 measurements - // (two per second) in a row equals zero. The member is only incremented on - // the task queue and max once every 10th second. - size_t num_rec_level_is_zero_; - // Counts number of audio callbacks modulo 50 to create a signal when // a new storage of audio stats shall be done. // Only updated on the OS-specific audio thread that drives audio. int16_t rec_stat_count_; int16_t play_stat_count_; + + // Time stamps of when playout and recording starts. + uint64_t play_start_time_; + uint64_t rec_start_time_; + + // Set to true at construction and modified to false as soon as one audio- + // level estimate larger than zero is detected. + bool only_silence_recorded_; }; } // namespace webrtc diff --git a/webrtc/modules/audio_device/audio_device_impl.cc b/webrtc/modules/audio_device/audio_device_impl.cc index cf69275eeb..80cb1be449 100644 --- a/webrtc/modules/audio_device/audio_device_impl.cc +++ b/webrtc/modules/audio_device/audio_device_impl.cc @@ -1346,7 +1346,6 @@ int32_t AudioDeviceModuleImpl::InitPlayout() { if (PlayoutIsInitialized()) { return 0; } - _audioDeviceBuffer.InitPlayout(); int32_t result = _ptrAudioDevice->InitPlayout(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.InitPlayoutSuccess", @@ -1364,7 +1363,6 @@ int32_t AudioDeviceModuleImpl::InitRecording() { if (RecordingIsInitialized()) { return 0; } - _audioDeviceBuffer.InitRecording(); int32_t result = _ptrAudioDevice->InitRecording(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.InitRecordingSuccess", @@ -1402,6 +1400,7 @@ int32_t AudioDeviceModuleImpl::StartPlayout() { if (Playing()) { return 0; } + _audioDeviceBuffer.StartPlayout(); int32_t result = _ptrAudioDevice->StartPlayout(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.StartPlayoutSuccess", @@ -1417,6 +1416,7 @@ int32_t AudioDeviceModuleImpl::StopPlayout() { LOG(INFO) << __FUNCTION__; CHECK_INITIALIZED(); int32_t result = _ptrAudioDevice->StopPlayout(); + _audioDeviceBuffer.StopPlayout(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.StopPlayoutSuccess", static_cast(result == 0)); @@ -1443,6 +1443,7 @@ int32_t AudioDeviceModuleImpl::StartRecording() { if (Recording()) { return 0; } + _audioDeviceBuffer.StartRecording(); int32_t result = _ptrAudioDevice->StartRecording(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.StartRecordingSuccess", @@ -1457,6 +1458,7 @@ int32_t AudioDeviceModuleImpl::StopRecording() { LOG(INFO) << __FUNCTION__; CHECK_INITIALIZED(); int32_t result = _ptrAudioDevice->StopRecording(); + _audioDeviceBuffer.StopRecording(); LOG(INFO) << "output: " << result; RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.StopRecordingSuccess", static_cast(result == 0));