diff --git a/webrtc/modules/audio_device/audio_device_buffer.cc b/webrtc/modules/audio_device/audio_device_buffer.cc index fb82b91ea1..b40d5afeb8 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.cc +++ b/webrtc/modules/audio_device/audio_device_buffer.cc @@ -10,21 +10,29 @@ #include "webrtc/modules/audio_device/audio_device_buffer.h" +#include "webrtc/base/bind.h" #include "webrtc/base/checks.h" #include "webrtc/base/logging.h" #include "webrtc/base/format_macros.h" +#include "webrtc/base/timeutils.h" #include "webrtc/modules/audio_device/audio_device_config.h" -#include "webrtc/system_wrappers/include/critical_section_wrapper.h" namespace webrtc { static const int kHighDelayThresholdMs = 300; static const int kLogHighDelayIntervalFrames = 500; // 5 seconds. +static const char kTimerQueueName[] = "AudioDeviceBufferTimer"; + +// Time between two sucessive calls to LogStats(). +static const size_t kTimerIntervalInSeconds = 10; +static const size_t kTimerIntervalInMilliseconds = + kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec; + AudioDeviceBuffer::AudioDeviceBuffer() - : _critSect(*CriticalSectionWrapper::CreateCriticalSection()), - _critSectCb(*CriticalSectionWrapper::CreateCriticalSection()), - _ptrCbAudioTransport(nullptr), + : _ptrCbAudioTransport(nullptr), + task_queue_(kTimerQueueName), + timer_has_started_(false), _recSampleRate(0), _playSampleRate(0), _recChannels(0), @@ -45,58 +53,72 @@ AudioDeviceBuffer::AudioDeviceBuffer() _recDelayMS(0), _clockDrift(0), // Set to the interval in order to log on the first occurrence. - high_delay_counter_(kLogHighDelayIntervalFrames) { + high_delay_counter_(kLogHighDelayIntervalFrames), + num_stat_reports_(0), + rec_callbacks_(0), + last_rec_callbacks_(0), + play_callbacks_(0), + last_play_callbacks_(0), + rec_samples_(0), + last_rec_samples_(0), + play_samples_(0), + last_play_samples_(0), + last_log_stat_time_(0) { LOG(INFO) << "AudioDeviceBuffer::ctor"; memset(_recBuffer, 0, kMaxBufferSizeBytes); memset(_playBuffer, 0, kMaxBufferSizeBytes); } AudioDeviceBuffer::~AudioDeviceBuffer() { + RTC_DCHECK(thread_checker_.CalledOnValidThread()); LOG(INFO) << "AudioDeviceBuffer::~dtor"; - { - CriticalSectionScoped lock(&_critSect); + _recFile.Flush(); + _recFile.CloseFile(); + delete &_recFile; - _recFile.Flush(); - _recFile.CloseFile(); - delete &_recFile; - - _playFile.Flush(); - _playFile.CloseFile(); - delete &_playFile; - } - - delete &_critSect; - delete &_critSectCb; + _playFile.Flush(); + _playFile.CloseFile(); + delete &_playFile; } int32_t AudioDeviceBuffer::RegisterAudioCallback( AudioTransport* audioCallback) { LOG(INFO) << __FUNCTION__; - CriticalSectionScoped lock(&_critSectCb); + rtc::CritScope lock(&_critSectCb); _ptrCbAudioTransport = audioCallback; return 0; } int32_t AudioDeviceBuffer::InitPlayout() { + RTC_DCHECK(thread_checker_.CalledOnValidThread()); LOG(INFO) << __FUNCTION__; + if (!timer_has_started_) { + StartTimer(); + timer_has_started_ = true; + } return 0; } int32_t AudioDeviceBuffer::InitRecording() { + RTC_DCHECK(thread_checker_.CalledOnValidThread()); LOG(INFO) << __FUNCTION__; + if (!timer_has_started_) { + StartTimer(); + timer_has_started_ = true; + } return 0; } int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) { LOG(INFO) << "SetRecordingSampleRate(" << fsHz << ")"; - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _recSampleRate = fsHz; return 0; } int32_t AudioDeviceBuffer::SetPlayoutSampleRate(uint32_t fsHz) { LOG(INFO) << "SetPlayoutSampleRate(" << fsHz << ")"; - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _playSampleRate = fsHz; return 0; } @@ -110,7 +132,7 @@ int32_t AudioDeviceBuffer::PlayoutSampleRate() const { } int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _recChannels = channels; _recBytesPerSample = 2 * channels; // 16 bits per sample in mono, 32 bits in stereo @@ -118,7 +140,7 @@ int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) { } int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _playChannels = channels; // 16 bits per sample in mono, 32 bits in stereo _playBytesPerSample = 2 * channels; @@ -127,7 +149,7 @@ int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) { int32_t AudioDeviceBuffer::SetRecordingChannel( const AudioDeviceModule::ChannelType channel) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); if (_recChannels == 1) { return -1; @@ -193,7 +215,7 @@ void AudioDeviceBuffer::SetVQEData(int playDelayMs, int32_t AudioDeviceBuffer::StartInputFileRecording( const char fileName[kAdmMaxFileNameSize]) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _recFile.Flush(); _recFile.CloseFile(); @@ -202,7 +224,7 @@ int32_t AudioDeviceBuffer::StartInputFileRecording( } int32_t AudioDeviceBuffer::StopInputFileRecording() { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _recFile.Flush(); _recFile.CloseFile(); @@ -212,7 +234,7 @@ int32_t AudioDeviceBuffer::StopInputFileRecording() { int32_t AudioDeviceBuffer::StartOutputFileRecording( const char fileName[kAdmMaxFileNameSize]) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _playFile.Flush(); _playFile.CloseFile(); @@ -221,7 +243,7 @@ int32_t AudioDeviceBuffer::StartOutputFileRecording( } int32_t AudioDeviceBuffer::StopOutputFileRecording() { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); _playFile.Flush(); _playFile.CloseFile(); @@ -231,7 +253,7 @@ int32_t AudioDeviceBuffer::StopOutputFileRecording() { int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audioBuffer, size_t nSamples) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); if (_recBytesPerSample == 0) { assert(false); @@ -270,11 +292,16 @@ int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audioBuffer, _recFile.Write(&_recBuffer[0], _recSize); } + // Update some stats but do it on the task queue to ensure that the members + // are modified and read on the same thread. + task_queue_.PostTask( + rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this, nSamples)); + return 0; } int32_t AudioDeviceBuffer::DeliverRecordedData() { - CriticalSectionScoped lock(&_critSectCb); + rtc::CritScope lock(&_critSectCb); // Ensure that user has initialized all essential members if ((_recSampleRate == 0) || (_recSamples == 0) || (_recBytesPerSample == 0) || (_recChannels == 0)) { @@ -309,7 +336,7 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) { // TOOD(henrika): improve bad locking model and make it more clear that only // 10ms buffer sizes is supported in WebRTC. { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); // Store copies under lock and use copies hereafter to avoid race with // setter methods. @@ -332,7 +359,7 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) { size_t nSamplesOut(0); - CriticalSectionScoped lock(&_critSectCb); + rtc::CritScope lock(&_critSectCb); // It is currently supported to start playout without a valid audio // transport object. Leads to warning and silence. @@ -351,11 +378,16 @@ int32_t AudioDeviceBuffer::RequestPlayoutData(size_t nSamples) { LOG(LS_ERROR) << "NeedMorePlayData() failed"; } + // 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_.PostTask( + rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this, nSamplesOut)); + return static_cast(nSamplesOut); } int32_t AudioDeviceBuffer::GetPlayoutData(void* audioBuffer) { - CriticalSectionScoped lock(&_critSect); + rtc::CritScope lock(&_critSect); RTC_CHECK_LE(_playSize, kMaxBufferSizeBytes); memcpy(audioBuffer, &_playBuffer[0], _playSize); @@ -368,4 +400,67 @@ int32_t AudioDeviceBuffer::GetPlayoutData(void* audioBuffer) { return static_cast(_playSamples); } +void AudioDeviceBuffer::StartTimer() { + last_log_stat_time_ = rtc::TimeMillis(); + task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this), + kTimerIntervalInMilliseconds); +} + +void AudioDeviceBuffer::LogStats() { + 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; + + // 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. + if (++num_stat_reports_ > 1) { + uint32_t diff_samples = rec_samples_ - last_rec_samples_; + uint32_t rate = diff_samples / kTimerIntervalInSeconds; + LOG(INFO) << "[REC : " << time_since_last << "msec, " + << _recSampleRate / 1000 + << "kHz] callbacks: " << rec_callbacks_ - last_rec_callbacks_ + << ", " + << "samples: " << diff_samples << ", " + << "rate: " << rate; + + diff_samples = play_samples_ - last_play_samples_; + rate = diff_samples / kTimerIntervalInSeconds; + LOG(INFO) << "[PLAY: " << time_since_last << "msec, " + << _playSampleRate / 1000 + << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_ + << ", " + << "samples: " << diff_samples << ", " + << "rate: " << rate; + } + + last_rec_callbacks_ = rec_callbacks_; + last_play_callbacks_ = play_callbacks_; + last_rec_samples_ = rec_samples_; + last_play_samples_ = play_samples_; + + 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), + time_to_wait_ms); +} + +void AudioDeviceBuffer::UpdateRecStats(size_t num_samples) { + RTC_DCHECK(task_queue_.IsCurrent()); + ++rec_callbacks_; + rec_samples_ += num_samples; +} + +void AudioDeviceBuffer::UpdatePlayStats(size_t num_samples) { + RTC_DCHECK(task_queue_.IsCurrent()); + ++play_callbacks_; + play_samples_ += num_samples; +} + } // namespace webrtc diff --git a/webrtc/modules/audio_device/audio_device_buffer.h b/webrtc/modules/audio_device/audio_device_buffer.h index 1267e08be2..ee6b2297c7 100644 --- a/webrtc/modules/audio_device/audio_device_buffer.h +++ b/webrtc/modules/audio_device/audio_device_buffer.h @@ -8,9 +8,12 @@ * be found in the AUTHORS file in the root of the source tree. */ -#ifndef WEBRTC_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H -#define WEBRTC_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H +#ifndef WEBRTC_MODULES_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H_ +#define WEBRTC_MODULES_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H_ +#include "webrtc/base/criticalsection.h" +#include "webrtc/base/task_queue.h" +#include "webrtc/base/thread_checker.h" #include "webrtc/modules/audio_device/include/audio_device.h" #include "webrtc/system_wrappers/include/file_wrapper.h" #include "webrtc/typedefs.h" @@ -63,11 +66,36 @@ class AudioDeviceBuffer { int32_t SetTypingStatus(bool typingStatus); private: - CriticalSectionWrapper& _critSect; - CriticalSectionWrapper& _critSectCb; + // Posts the first delayed task in the task queue and starts the periodic + // timer. + void StartTimer(); + + // Called periodically on the internal thread created by the TaskQueue. + void LogStats(); + + // 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 + // each task is serialized by the task queue. + void UpdateRecStats(size_t num_samples); + void UpdatePlayStats(size_t num_samples); + + // Ensures that methods are called on the same thread as the thread that + // creates this object. + rtc::ThreadChecker thread_checker_; + + rtc::CriticalSection _critSect; + rtc::CriticalSection _critSectCb; AudioTransport* _ptrCbAudioTransport; + // Task queue used to invoke LogStats() periodically. Tasks are executed on a + // worker thread but it does not necessarily have to be the same thread for + // each task. + rtc::TaskQueue task_queue_; + + // Ensures that the timer is only started once. + bool timer_has_started_; + uint32_t _recSampleRate; uint32_t _playSampleRate; @@ -107,8 +135,40 @@ class AudioDeviceBuffer { int _recDelayMS; int _clockDrift; int high_delay_counter_; + + // Counts number of times LogStats() has been called. + size_t num_stat_reports_; + + // Total number of recording callbacks where the source provides 10ms audio + // data each time. + uint64_t rec_callbacks_; + + // Total number of recording callbacks stored at the last timer task. + uint64_t last_rec_callbacks_; + + // Total number of playback callbacks where the sink asks for 10ms audio + // data each time. + uint64_t play_callbacks_; + + // Total number of playout callbacks stored at the last timer task. + uint64_t last_play_callbacks_; + + // Total number of recorded audio samples. + uint64_t rec_samples_; + + // Total number of recorded samples stored at the previous timer task. + uint64_t last_rec_samples_; + + // Total number of played audio samples. + uint64_t play_samples_; + + // 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_; }; } // namespace webrtc -#endif // WEBRTC_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H +#endif // WEBRTC_MODULES_AUDIO_DEVICE_AUDIO_DEVICE_BUFFER_H_