Chromium Code Reviews
chromiumcodereview-hr@appspot.gserviceaccount.com (chromiumcodereview-hr) | Please choose your nickname with Settings | Help | Chromium Project | Gerrit Changes | Sign out
(1824)

Side by Side Diff: webrtc/modules/audio_device/audio_device_buffer.cc

Issue 2445363003: Improvements in how WebRTC.Audio.RecordedOnlyZeros is added as histogram (Closed)
Patch Set: cleanup Created 4 years, 1 month ago
Use n/p to move between diff chunks; N/P to move between comments. Draft comments are only viewable by you.
Jump to:
View unified diff | Download patch
OLDNEW
1 /* 1 /*
2 * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved. 2 * Copyright (c) 2012 The WebRTC project authors. All Rights Reserved.
3 * 3 *
4 * Use of this source code is governed by a BSD-style license 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 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 6 * tree. An additional intellectual property rights grant can be found
7 * in the file PATENTS. All contributing project authors may 7 * in the file PATENTS. All contributing project authors may
8 * be found in the AUTHORS file in the root of the source tree. 8 * be found in the AUTHORS file in the root of the source tree.
9 */ 9 */
10 10
(...skipping 12 matching lines...) Expand all
23 #include "webrtc/system_wrappers/include/metrics.h" 23 #include "webrtc/system_wrappers/include/metrics.h"
24 24
25 namespace webrtc { 25 namespace webrtc {
26 26
27 static const char kTimerQueueName[] = "AudioDeviceBufferTimer"; 27 static const char kTimerQueueName[] = "AudioDeviceBufferTimer";
28 28
29 // Time between two sucessive calls to LogStats(). 29 // Time between two sucessive calls to LogStats().
30 static const size_t kTimerIntervalInSeconds = 10; 30 static const size_t kTimerIntervalInSeconds = 10;
31 static const size_t kTimerIntervalInMilliseconds = 31 static const size_t kTimerIntervalInMilliseconds =
32 kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec; 32 kTimerIntervalInSeconds * rtc::kNumMillisecsPerSec;
33 // Min time required to qualify an audio session as a "call". If playout or
34 // recording has been active for less than this time we will not store any
35 // logs or UMA stats but instead consider the call as too short.
36 static const size_t kMinValidCallTimeTimeInSeconds = 10;
37 static const size_t kMinValidCallTimeTimeInMilliseconds =
38 kMinValidCallTimeTimeInSeconds * rtc::kNumMillisecsPerSec;
33 39
34 AudioDeviceBuffer::AudioDeviceBuffer() 40 AudioDeviceBuffer::AudioDeviceBuffer()
35 : audio_transport_cb_(nullptr), 41 : audio_transport_cb_(nullptr),
36 task_queue_(kTimerQueueName), 42 playing_(false),
37 timer_has_started_(false), 43 recording_(false),
38 rec_sample_rate_(0), 44 rec_sample_rate_(0),
39 play_sample_rate_(0), 45 play_sample_rate_(0),
40 rec_channels_(0), 46 rec_channels_(0),
41 play_channels_(0), 47 play_channels_(0),
42 rec_bytes_per_sample_(0), 48 rec_bytes_per_sample_(0),
43 play_bytes_per_sample_(0), 49 play_bytes_per_sample_(0),
44 current_mic_level_(0), 50 current_mic_level_(0),
45 new_mic_level_(0), 51 new_mic_level_(0),
46 typing_status_(false), 52 typing_status_(false),
47 play_delay_ms_(0), 53 play_delay_ms_(0),
48 rec_delay_ms_(0), 54 rec_delay_ms_(0),
49 clock_drift_(0), 55 clock_drift_(0),
50 num_stat_reports_(0), 56 num_stat_reports_(0),
51 rec_callbacks_(0), 57 rec_callbacks_(0),
52 last_rec_callbacks_(0), 58 last_rec_callbacks_(0),
53 play_callbacks_(0), 59 play_callbacks_(0),
54 last_play_callbacks_(0), 60 last_play_callbacks_(0),
55 rec_samples_(0), 61 rec_samples_(0),
56 last_rec_samples_(0), 62 last_rec_samples_(0),
57 play_samples_(0), 63 play_samples_(0),
58 last_play_samples_(0), 64 last_play_samples_(0),
59 last_log_stat_time_(0), 65 last_log_stat_time_(0),
60 max_rec_level_(0), 66 max_rec_level_(0),
61 max_play_level_(0), 67 max_play_level_(0),
62 num_rec_level_is_zero_(0),
63 rec_stat_count_(0), 68 rec_stat_count_(0),
64 play_stat_count_(0) { 69 play_stat_count_(0),
70 play_start_time_(0),
71 rec_start_time_(0),
72 only_silence_recorded_(true) {
65 LOG(INFO) << "AudioDeviceBuffer::ctor"; 73 LOG(INFO) << "AudioDeviceBuffer::ctor";
66 } 74 }
67 75
68 AudioDeviceBuffer::~AudioDeviceBuffer() { 76 AudioDeviceBuffer::~AudioDeviceBuffer() {
tommi 2016/10/25 16:43:22 add checks for !playing_ and !recording_?
henrika_webrtc 2016/10/26 12:42:41 Done.
69 RTC_DCHECK(thread_checker_.CalledOnValidThread()); 77 RTC_DCHECK(thread_checker_.CalledOnValidThread());
70 LOG(INFO) << "AudioDeviceBuffer::~dtor"; 78 LOG(INFO) << "AudioDeviceBuffer::~dtor";
71
72 size_t total_diff_time = 0;
73 int num_measurements = 0;
74 LOG(INFO) << "[playout diff time => #measurements]";
75 for (size_t diff = 0; diff < arraysize(playout_diff_times_); ++diff) {
76 uint32_t num_elements = playout_diff_times_[diff];
77 if (num_elements > 0) {
78 total_diff_time += num_elements * diff;
79 num_measurements += num_elements;
80 LOG(INFO) << "[" << diff << " => " << num_elements << "]";
81 }
82 }
83 if (num_measurements > 0) {
84 LOG(INFO) << "total_diff_time: " << total_diff_time;
85 LOG(INFO) << "num_measurements: " << num_measurements;
86 LOG(INFO) << "average: "
87 << static_cast<float>(total_diff_time) / num_measurements;
88 }
89
90 // Add UMA histogram to keep track of the case when only zeros have been
91 // recorded. Ensure that recording callbacks have started and that at least
92 // one timer event has been able to update |num_rec_level_is_zero_|.
93 // I am avoiding use of the task queue here since we are under destruction
94 // and reading these members on the creating thread feels safe.
95 if (rec_callbacks_ > 0 && num_stat_reports_ > 0) {
96 RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros",
97 static_cast<int>(num_stat_reports_ == num_rec_level_is_zero_));
98 }
99 } 79 }
100 80
101 int32_t AudioDeviceBuffer::RegisterAudioCallback( 81 int32_t AudioDeviceBuffer::RegisterAudioCallback(
102 AudioTransport* audio_callback) { 82 AudioTransport* audio_callback) {
103 LOG(INFO) << __FUNCTION__; 83 LOG(INFO) << __FUNCTION__;
104 rtc::CritScope lock(&lock_cb_); 84 rtc::CritScope lock(&lock_cb_);
105 audio_transport_cb_ = audio_callback; 85 audio_transport_cb_ = audio_callback;
tommi 2016/10/25 16:43:22 first: RTC_DCHECK(!audio_transport_cb_ || !audio_c
tommi 2016/10/25 16:43:22 is it allowed to call RegisterAudioCallback while
henrika_webrtc 2016/10/26 12:42:41 We actually have unit tests today for the ADM (whi
henrika_webrtc 2016/10/26 12:42:41 Long story since this API goes way back when the i
106 return 0; 86 return 0;
107 } 87 }
108 88
109 int32_t AudioDeviceBuffer::InitPlayout() { 89 int32_t AudioDeviceBuffer::InitPlayout() {
tommi 2016/10/25 16:43:22 can we remove this function?
henrika_webrtc 2016/10/26 12:42:41 Done.
110 LOG(INFO) << __FUNCTION__; 90 LOG(INFO) << __FUNCTION__;
91 return 0;
92 }
93
94 void AudioDeviceBuffer::StartPlayout() {
111 RTC_DCHECK(thread_checker_.CalledOnValidThread()); 95 RTC_DCHECK(thread_checker_.CalledOnValidThread());
96 if (playing_) {
tommi 2016/10/25 16:43:23 what about RTC_DCHECK(!playing_) ?
henrika_webrtc 2016/10/26 12:42:41 Done.
97 return;
98 }
99 LOG(INFO) << __FUNCTION__;
112 ResetPlayStats(); 100 ResetPlayStats();
113 if (!timer_has_started_) { 101 // Start a periodic timer based on task queue if not already done by the
102 // recording side.
103 if (!task_queue_) {
114 StartTimer(); 104 StartTimer();
tommi 2016/10/25 16:43:23 it looks like every time StartTimer is called, you
henrika_webrtc 2016/10/26 12:42:40 Excellent idea ;-)
115 timer_has_started_ = true;
116 } 105 }
117 return 0; 106 playing_ = true;
118 } 107 }
119 108
120 int32_t AudioDeviceBuffer::InitRecording() { 109 int32_t AudioDeviceBuffer::InitRecording() {
121 LOG(INFO) << __FUNCTION__; 110 LOG(INFO) << __FUNCTION__;
122 RTC_DCHECK(thread_checker_.CalledOnValidThread());
123 ResetRecStats();
124 if (!timer_has_started_) {
125 StartTimer();
126 timer_has_started_ = true;
127 }
128 return 0; 111 return 0;
129 } 112 }
130 113
114 void AudioDeviceBuffer::StartRecording() {
115 RTC_DCHECK(thread_checker_.CalledOnValidThread());
116 if (recording_) {
tommi 2016/10/25 16:43:22 RTC_DCHECK(!recording_)?
henrika_webrtc 2016/10/26 12:42:41 Done.
117 return;
118 }
119 LOG(INFO) << __FUNCTION__;
120 ResetRecStats();
121 // Start a periodic timer based on task queue if not already done by the
122 // playout side.
123 if (!task_queue_) {
124 StartTimer();
125 }
126 recording_ = true;
127 }
128
129 void AudioDeviceBuffer::StopPlayout() {
130 RTC_DCHECK(thread_checker_.CalledOnValidThread());
131 if (!playing_) {
tommi 2016/10/25 16:43:22 RTC_DCHECK(playing_) ?
henrika_webrtc 2016/10/26 12:42:41 Done.
132 return;
133 }
134 LOG(INFO) << __FUNCTION__;
135 playing_ = false;
136 // Stop the timer if no more media is active.
137 if (!recording_) {
138 StopTimer();
139 }
140 // Add diagnostic logging of delta times for playout callbacks. We are doing
141 // this wihout a lock since playout should be stopped by now and it a minor
142 // conflict during stop will not have a great impact on the total statistics.
143 const size_t time_since_start = rtc::TimeSince(play_start_time_);
144 if (time_since_start > kMinValidCallTimeTimeInMilliseconds) {
145 size_t total_diff_time = 0;
146 int num_measurements = 0;
147 LOG(INFO) << "[playout diff time => #measurements]";
148 for (size_t diff = 0; diff < arraysize(playout_diff_times_); ++diff) {
149 uint32_t num_elements = playout_diff_times_[diff];
150 if (num_elements > 0) {
151 total_diff_time += num_elements * diff;
152 num_measurements += num_elements;
153 LOG(INFO) << "[" << diff << " => " << num_elements << "]";
154 }
155 }
156 if (num_measurements > 0) {
157 LOG(INFO) << "total_diff_time: " << total_diff_time;
tommi 2016/10/25 16:43:22 can all of these be merged to one LOG statement?
henrika_webrtc 2016/10/26 12:42:41 Done.
158 LOG(INFO) << "num_measurements: " << num_measurements;
159 LOG(INFO) << "average: "
160 << static_cast<float>(total_diff_time) / num_measurements;
161 }
162 }
163 LOG(INFO) << "total playout time: " << time_since_start;
164 }
165
166 void AudioDeviceBuffer::StopRecording() {
167 RTC_DCHECK(thread_checker_.CalledOnValidThread());
168 if (!recording_) {
tommi 2016/10/25 16:43:22 RTC_DCHECK(recording_) ?
henrika_webrtc 2016/10/26 12:42:41 Done.
169 return;
170 }
171 LOG(INFO) << __FUNCTION__;
172 recording_ = false;
173 // Stop the timer if no more media is active.
174 if (!playing_) {
175 StopTimer();
176 }
177 // Add UMA histogram to keep track of the case when only zeros have been
178 // recorded. Measurements (max of absolute level) are taken twice per second,
179 // which means that if e.g 10 seconds of audio has been recorded, a total of
180 // 20 level estimates must all be identical to zero to trigger the histogram.
181 // |only_silence_recorded_| can only be cleared on the native audio thread
182 // that drives audio capture but we know by design that the audio has stopped
183 // when this method is called, hence there should not be aby conflicts. Also,
184 // the fact that |only_silence_recorded_| can be affected during the complete
185 // call makes chances of conflicts with potentially one last callback very
186 // small.
187 const size_t time_since_start = rtc::TimeSince(rec_start_time_);
188 if (time_since_start > kMinValidCallTimeTimeInMilliseconds) {
189 const int only_zeros = static_cast<int>(only_silence_recorded_);
190 RTC_HISTOGRAM_BOOLEAN("WebRTC.Audio.RecordedOnlyZeros", only_zeros);
191 LOG(INFO) << "HISTOGRAM(WebRTC.Audio.RecordedOnlyZeros): " << only_zeros;
tommi 2016/10/25 16:43:22 fix spaces
henrika_webrtc 2016/10/26 12:42:41 Done.
192 }
193 LOG(INFO) << "total recording time: " << time_since_start;
194 }
195
131 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) { 196 int32_t AudioDeviceBuffer::SetRecordingSampleRate(uint32_t fsHz) {
132 LOG(INFO) << "SetRecordingSampleRate(" << fsHz << ")"; 197 LOG(INFO) << "SetRecordingSampleRate(" << fsHz << ")";
133 RTC_DCHECK(thread_checker_.CalledOnValidThread()); 198 RTC_DCHECK(thread_checker_.CalledOnValidThread());
134 rec_sample_rate_ = fsHz; 199 rec_sample_rate_ = fsHz;
135 return 0; 200 return 0;
136 } 201 }
137 202
138 int32_t AudioDeviceBuffer::SetPlayoutSampleRate(uint32_t fsHz) { 203 int32_t AudioDeviceBuffer::SetPlayoutSampleRate(uint32_t fsHz) {
139 LOG(INFO) << "SetPlayoutSampleRate(" << fsHz << ")"; 204 LOG(INFO) << "SetPlayoutSampleRate(" << fsHz << ")";
140 RTC_DCHECK(thread_checker_.CalledOnValidThread()); 205 RTC_DCHECK(thread_checker_.CalledOnValidThread());
141 play_sample_rate_ = fsHz; 206 play_sample_rate_ = fsHz;
142 return 0; 207 return 0;
143 } 208 }
144 209
145 int32_t AudioDeviceBuffer::RecordingSampleRate() const { 210 int32_t AudioDeviceBuffer::RecordingSampleRate() const {
146 return rec_sample_rate_; 211 return rec_sample_rate_;
147 } 212 }
148 213
149 int32_t AudioDeviceBuffer::PlayoutSampleRate() const { 214 int32_t AudioDeviceBuffer::PlayoutSampleRate() const {
150 return play_sample_rate_; 215 return play_sample_rate_;
151 } 216 }
152 217
153 int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) { 218 int32_t AudioDeviceBuffer::SetRecordingChannels(size_t channels) {
tommi 2016/10/25 16:43:22 See also question elsewhere about the rec_channels
henrika_webrtc 2016/10/26 12:42:41 I am working on a related CL which will improve ho
154 LOG(INFO) << "SetRecordingChannels(" << channels << ")"; 219 LOG(INFO) << "SetRecordingChannels(" << channels << ")";
155 rtc::CritScope lock(&lock_); 220 rtc::CritScope lock(&lock_);
156 rec_channels_ = channels; 221 rec_channels_ = channels;
157 rec_bytes_per_sample_ = sizeof(int16_t) * channels; 222 rec_bytes_per_sample_ = sizeof(int16_t) * channels;
158 return 0; 223 return 0;
159 } 224 }
160 225
161 int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) { 226 int32_t AudioDeviceBuffer::SetPlayoutChannels(size_t channels) {
162 LOG(INFO) << "SetPlayoutChannels(" << channels << ")"; 227 LOG(INFO) << "SetPlayoutChannels(" << channels << ")";
163 rtc::CritScope lock(&lock_); 228 rtc::CritScope lock(&lock_);
(...skipping 67 matching lines...) Expand 10 before | Expand all | Expand 10 after
231 296
232 int32_t AudioDeviceBuffer::StopOutputFileRecording() { 297 int32_t AudioDeviceBuffer::StopOutputFileRecording() {
233 LOG(LS_WARNING) << "Not implemented"; 298 LOG(LS_WARNING) << "Not implemented";
234 return 0; 299 return 0;
235 } 300 }
236 301
237 int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer, 302 int32_t AudioDeviceBuffer::SetRecordedBuffer(const void* audio_buffer,
238 size_t num_samples) { 303 size_t num_samples) {
239 const size_t rec_channels = [&] { 304 const size_t rec_channels = [&] {
240 rtc::CritScope lock(&lock_); 305 rtc::CritScope lock(&lock_);
241 return rec_channels_; 306 return rec_channels_;
tommi 2016/10/25 16:43:22 why do we do this? It looks like we're grabbing t
henrika_webrtc 2016/10/26 12:42:41 I use the lambda based on feedback from kwiberg@ i
242 }(); 307 }();
243 // Copy the complete input buffer to the local buffer. 308 // Copy the complete input buffer to the local buffer.
244 const size_t size_in_bytes = num_samples * rec_channels * sizeof(int16_t); 309 const size_t size_in_bytes = num_samples * rec_channels * sizeof(int16_t);
245 const size_t old_size = rec_buffer_.size(); 310 const size_t old_size = rec_buffer_.size();
246 rec_buffer_.SetData(static_cast<const uint8_t*>(audio_buffer), size_in_bytes); 311 rec_buffer_.SetData(static_cast<const uint8_t*>(audio_buffer), size_in_bytes);
247 // Keep track of the size of the recording buffer. Only updated when the 312 // Keep track of the size of the recording buffer. Only updated when the
248 // size changes, which is a rare event. 313 // size changes, which is a rare event.
249 if (old_size != rec_buffer_.size()) { 314 if (old_size != rec_buffer_.size()) {
250 LOG(LS_INFO) << "Size of recording buffer: " << rec_buffer_.size(); 315 LOG(LS_INFO) << "Size of recording buffer: " << rec_buffer_.size();
tommi 2016/10/25 16:43:23 fyi - logging from within performance sensitive ca
henrika_webrtc 2016/10/26 12:42:41 Wow, didn't know that. It is a very, very rare eve
251 } 316 }
252 // Derive a new level value twice per second. 317 // Derive a new level value twice per second and check if it is non-zero.
253 int16_t max_abs = 0; 318 int16_t max_abs = 0;
254 RTC_DCHECK_LT(rec_stat_count_, 50); 319 RTC_DCHECK_LT(rec_stat_count_, 50);
255 if (++rec_stat_count_ >= 50) { 320 if (++rec_stat_count_ >= 50) {
256 const size_t size = num_samples * rec_channels; 321 const size_t size = num_samples * rec_channels;
257 // Returns the largest absolute value in a signed 16-bit vector. 322 // Returns the largest absolute value in a signed 16-bit vector.
258 max_abs = WebRtcSpl_MaxAbsValueW16( 323 max_abs = WebRtcSpl_MaxAbsValueW16(
259 reinterpret_cast<const int16_t*>(rec_buffer_.data()), size); 324 reinterpret_cast<const int16_t*>(rec_buffer_.data()), size);
260 rec_stat_count_ = 0; 325 rec_stat_count_ = 0;
326 // Set |only_silence_recorded_| to false as soon as at least one detection
327 // of a non-zero audio packet is found. It can only be restored to true
328 // again by restarting the call.
329 if (max_abs > 0) {
330 only_silence_recorded_ = false;
331 }
261 } 332 }
262 // Update some stats but do it on the task queue to ensure that the members 333 // Update some stats but do it on the task queue to ensure that the members
263 // are modified and read on the same thread. Note that |max_abs| will be 334 // are modified and read on the same thread. Note that |max_abs| will be
264 // zero in most calls and then have no effect of the stats. It is only updated 335 // zero in most calls and then have no effect of the stats. It is only updated
265 // approximately two times per second and can then change the stats. 336 // approximately two times per second and can then change the stats.
266 task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this, 337 task_queue_->PostTask(rtc::Bind(&AudioDeviceBuffer::UpdateRecStats, this,
267 max_abs, num_samples)); 338 max_abs, num_samples));
268 return 0; 339 return 0;
269 } 340 }
270 341
271 int32_t AudioDeviceBuffer::DeliverRecordedData() { 342 int32_t AudioDeviceBuffer::DeliverRecordedData() {
272 rtc::CritScope lock(&lock_cb_); 343 rtc::CritScope lock(&lock_cb_);
273 if (!audio_transport_cb_) { 344 if (!audio_transport_cb_) {
274 LOG(LS_WARNING) << "Invalid audio transport"; 345 LOG(LS_WARNING) << "Invalid audio transport";
275 return 0; 346 return 0;
276 } 347 }
277 const size_t rec_bytes_per_sample = [&] { 348 const size_t rec_bytes_per_sample = [&] {
278 rtc::CritScope lock(&lock_); 349 rtc::CritScope lock(&lock_);
279 return rec_bytes_per_sample_; 350 return rec_bytes_per_sample_;
tommi 2016/10/25 16:43:22 nit: it seems unnecessarily fancy to use a lambda
henrika_webrtc 2016/10/26 12:42:41 LOL, I did initially but kwiberg@ wanted me to use
280 }(); 351 }();
281 uint32_t new_mic_level(0); 352 uint32_t new_mic_level(0);
282 uint32_t total_delay_ms = play_delay_ms_ + rec_delay_ms_; 353 uint32_t total_delay_ms = play_delay_ms_ + rec_delay_ms_;
283 size_t num_samples = rec_buffer_.size() / rec_bytes_per_sample; 354 size_t num_samples = rec_buffer_.size() / rec_bytes_per_sample;
284 int32_t res = audio_transport_cb_->RecordedDataIsAvailable( 355 int32_t res = audio_transport_cb_->RecordedDataIsAvailable(
285 rec_buffer_.data(), num_samples, rec_bytes_per_sample_, rec_channels_, 356 rec_buffer_.data(), num_samples, rec_bytes_per_sample_, rec_channels_,
286 rec_sample_rate_, total_delay_ms, clock_drift_, current_mic_level_, 357 rec_sample_rate_, total_delay_ms, clock_drift_, current_mic_level_,
287 typing_status_, new_mic_level); 358 typing_status_, new_mic_level);
288 if (res != -1) { 359 if (res != -1) {
289 new_mic_level_ = new_mic_level; 360 new_mic_level_ = new_mic_level;
(...skipping 39 matching lines...) Expand 10 before | Expand all | Expand 10 after
329 return 0; 400 return 0;
330 } 401 }
331 402
332 // Retrieve new 16-bit PCM audio data using the audio transport instance. 403 // Retrieve new 16-bit PCM audio data using the audio transport instance.
333 int64_t elapsed_time_ms = -1; 404 int64_t elapsed_time_ms = -1;
334 int64_t ntp_time_ms = -1; 405 int64_t ntp_time_ms = -1;
335 size_t num_samples_out(0); 406 size_t num_samples_out(0);
336 uint32_t res = audio_transport_cb_->NeedMorePlayData( 407 uint32_t res = audio_transport_cb_->NeedMorePlayData(
337 num_samples, play_bytes_per_sample_, play_channels, play_sample_rate_, 408 num_samples, play_bytes_per_sample_, play_channels, play_sample_rate_,
338 play_buffer_.data(), num_samples_out, &elapsed_time_ms, &ntp_time_ms); 409 play_buffer_.data(), num_samples_out, &elapsed_time_ms, &ntp_time_ms);
339 if (res != 0) { 410 if (res != 0) {
tommi 2016/10/25 16:43:22 at this point, we don't need to hold |lock| but we
henrika_webrtc 2016/10/26 12:42:41 As mentioned; I am planning a separate "improve lo
340 LOG(LS_ERROR) << "NeedMorePlayData() failed"; 411 LOG(LS_ERROR) << "NeedMorePlayData() failed";
341 } 412 }
342 413
343 // Derive a new level value twice per second. 414 // Derive a new level value twice per second.
344 int16_t max_abs = 0; 415 int16_t max_abs = 0;
345 RTC_DCHECK_LT(play_stat_count_, 50); 416 RTC_DCHECK_LT(play_stat_count_, 50);
346 if (++play_stat_count_ >= 50) { 417 if (++play_stat_count_ >= 50) {
347 const size_t size = num_samples * play_channels; 418 const size_t size = num_samples * play_channels;
348 // Returns the largest absolute value in a signed 16-bit vector. 419 // Returns the largest absolute value in a signed 16-bit vector.
349 max_abs = WebRtcSpl_MaxAbsValueW16( 420 max_abs = WebRtcSpl_MaxAbsValueW16(
350 reinterpret_cast<const int16_t*>(play_buffer_.data()), size); 421 reinterpret_cast<const int16_t*>(play_buffer_.data()), size);
351 play_stat_count_ = 0; 422 play_stat_count_ = 0;
352 } 423 }
353 // Update some stats but do it on the task queue to ensure that the members 424 // Update some stats but do it on the task queue to ensure that the members
354 // are modified and read on the same thread. Note that |max_abs| will be 425 // are modified and read on the same thread. Note that |max_abs| will be
355 // zero in most calls and then have no effect of the stats. It is only updated 426 // zero in most calls and then have no effect of the stats. It is only updated
356 // approximately two times per second and can then change the stats. 427 // approximately two times per second and can then change the stats.
357 task_queue_.PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this, 428 task_queue_->PostTask(rtc::Bind(&AudioDeviceBuffer::UpdatePlayStats, this,
358 max_abs, num_samples_out)); 429 max_abs, num_samples_out));
tommi 2016/10/25 16:43:22 fix indent (maybe run git cl format?)
henrika_webrtc 2016/10/26 12:42:41 For some reason git cl format does not work on thi
359 return static_cast<int32_t>(num_samples_out); 430 return static_cast<int32_t>(num_samples_out);
360 } 431 }
361 432
362 int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) { 433 int32_t AudioDeviceBuffer::GetPlayoutData(void* audio_buffer) {
363 RTC_DCHECK_GT(play_buffer_.size(), 0u); 434 RTC_DCHECK_GT(play_buffer_.size(), 0u);
364 const size_t play_bytes_per_sample = [&] { 435 const size_t play_bytes_per_sample = [&] {
365 rtc::CritScope lock(&lock_); 436 rtc::CritScope lock(&lock_);
366 return play_bytes_per_sample_; 437 return play_bytes_per_sample_;
367 }(); 438 }();
368 memcpy(audio_buffer, play_buffer_.data(), play_buffer_.size()); 439 memcpy(audio_buffer, play_buffer_.data(), play_buffer_.size());
369 return static_cast<int32_t>(play_buffer_.size() / play_bytes_per_sample); 440 return static_cast<int32_t>(play_buffer_.size() / play_bytes_per_sample);
370 } 441 }
371 442
372 void AudioDeviceBuffer::StartTimer() { 443 void AudioDeviceBuffer::StartTimer() {
444 LOG(INFO) << "StartTimer";
tommi 2016/10/25 16:43:22 do we need all of this logging in release builds?
henrika_webrtc 2016/10/26 12:42:40 Removed
373 num_stat_reports_ = 0; 445 num_stat_reports_ = 0;
374 last_log_stat_time_ = rtc::TimeMillis(); 446 last_log_stat_time_ = rtc::TimeMillis();
375 task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this), 447 task_queue_.reset(new rtc::TaskQueue(kTimerQueueName));
376 kTimerIntervalInMilliseconds); 448 task_queue_->PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
449 kTimerIntervalInMilliseconds);
450 }
451
452 void AudioDeviceBuffer::StopTimer() {
453 LOG(INFO) << "StopTimer";
454 if (task_queue_) {
tommi 2016/10/25 16:43:23 check isn't necessary (reset() handles it)
henrika_webrtc 2016/10/26 12:42:41 Thanks!
455 task_queue_.reset(nullptr);
456 }
377 } 457 }
378 458
379 void AudioDeviceBuffer::LogStats() { 459 void AudioDeviceBuffer::LogStats() {
380 RTC_DCHECK(task_queue_.IsCurrent()); 460 RTC_DCHECK(task_queue_->IsCurrent());
381 461
382 int64_t now_time = rtc::TimeMillis(); 462 int64_t now_time = rtc::TimeMillis();
383 int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds; 463 int64_t next_callback_time = now_time + kTimerIntervalInMilliseconds;
384 int64_t time_since_last = rtc::TimeDiff(now_time, last_log_stat_time_); 464 int64_t time_since_last = rtc::TimeDiff(now_time, last_log_stat_time_);
385 last_log_stat_time_ = now_time; 465 last_log_stat_time_ = now_time;
386 466
387 // Log the latest statistics but skip the first 10 seconds since we are not 467 // Log the latest statistics but skip the first 10 seconds since we are not
388 // sure of the exact starting point. I.e., the first log printout will be 468 // sure of the exact starting point. I.e., the first log printout will be
389 // after ~20 seconds. 469 // after ~20 seconds.
390 if (++num_stat_reports_ > 1 && time_since_last > 0) { 470 if (++num_stat_reports_ > 1 && time_since_last > 0) {
(...skipping 11 matching lines...) Expand all
402 rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0); 482 rate = diff_samples / (static_cast<float>(time_since_last) / 1000.0);
403 LOG(INFO) << "[PLAY: " << time_since_last << "msec, " 483 LOG(INFO) << "[PLAY: " << time_since_last << "msec, "
404 << play_sample_rate_ / 1000 484 << play_sample_rate_ / 1000
405 << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_ 485 << "kHz] callbacks: " << play_callbacks_ - last_play_callbacks_
406 << ", " 486 << ", "
407 << "samples: " << diff_samples << ", " 487 << "samples: " << diff_samples << ", "
408 << "rate: " << static_cast<int>(rate + 0.5) << ", " 488 << "rate: " << static_cast<int>(rate + 0.5) << ", "
409 << "level: " << max_play_level_; 489 << "level: " << max_play_level_;
410 } 490 }
411 491
412 // Count number of times we detect "no audio" corresponding to a case where
413 // all level measurements have been zero.
414 if (max_rec_level_ == 0) {
415 ++num_rec_level_is_zero_;
416 }
417
418 last_rec_callbacks_ = rec_callbacks_; 492 last_rec_callbacks_ = rec_callbacks_;
419 last_play_callbacks_ = play_callbacks_; 493 last_play_callbacks_ = play_callbacks_;
420 last_rec_samples_ = rec_samples_; 494 last_rec_samples_ = rec_samples_;
421 last_play_samples_ = play_samples_; 495 last_play_samples_ = play_samples_;
422 max_rec_level_ = 0; 496 max_rec_level_ = 0;
423 max_play_level_ = 0; 497 max_play_level_ = 0;
424 498
425 int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis(); 499 int64_t time_to_wait_ms = next_callback_time - rtc::TimeMillis();
426 RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval"; 500 RTC_DCHECK_GT(time_to_wait_ms, 0) << "Invalid timer interval";
427 501
428 // Update some stats but do it on the task queue to ensure that access of 502 // Update some stats but do it on the task queue to ensure that access of
429 // members is serialized hence avoiding usage of locks. 503 // members is serialized hence avoiding usage of locks.
430 task_queue_.PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this), 504 task_queue_->PostDelayedTask(rtc::Bind(&AudioDeviceBuffer::LogStats, this),
431 time_to_wait_ms); 505 time_to_wait_ms);
432 } 506 }
433 507
434 void AudioDeviceBuffer::ResetRecStats() { 508 void AudioDeviceBuffer::ResetRecStats() {
509 rec_start_time_ = rtc::TimeMillis();
435 rec_callbacks_ = 0; 510 rec_callbacks_ = 0;
436 last_rec_callbacks_ = 0; 511 last_rec_callbacks_ = 0;
437 rec_samples_ = 0; 512 rec_samples_ = 0;
438 last_rec_samples_ = 0; 513 last_rec_samples_ = 0;
439 max_rec_level_ = 0; 514 max_rec_level_ = 0;
440 num_rec_level_is_zero_ = 0; 515 only_silence_recorded_ = true;
441 } 516 }
442 517
443 void AudioDeviceBuffer::ResetPlayStats() { 518 void AudioDeviceBuffer::ResetPlayStats() {
444 last_playout_time_ = rtc::TimeMillis(); 519 const uint64_t now_time = rtc::TimeMillis();
520 play_start_time_ = now_time;
521 last_playout_time_ = now_time;
445 play_callbacks_ = 0; 522 play_callbacks_ = 0;
446 last_play_callbacks_ = 0; 523 last_play_callbacks_ = 0;
447 play_samples_ = 0; 524 play_samples_ = 0;
448 last_play_samples_ = 0; 525 last_play_samples_ = 0;
449 max_play_level_ = 0; 526 max_play_level_ = 0;
450 } 527 }
451 528
452 void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs, size_t num_samples) { 529 void AudioDeviceBuffer::UpdateRecStats(int16_t max_abs, size_t num_samples) {
453 RTC_DCHECK(task_queue_.IsCurrent()); 530 RTC_DCHECK(task_queue_->IsCurrent());
454 ++rec_callbacks_; 531 ++rec_callbacks_;
455 rec_samples_ += num_samples; 532 rec_samples_ += num_samples;
456 if (max_abs > max_rec_level_) { 533 if (max_abs > max_rec_level_) {
457 max_rec_level_ = max_abs; 534 max_rec_level_ = max_abs;
458 } 535 }
459 } 536 }
460 537
461 void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs, size_t num_samples) { 538 void AudioDeviceBuffer::UpdatePlayStats(int16_t max_abs, size_t num_samples) {
462 RTC_DCHECK(task_queue_.IsCurrent()); 539 RTC_DCHECK(task_queue_->IsCurrent());
463 ++play_callbacks_; 540 ++play_callbacks_;
464 play_samples_ += num_samples; 541 play_samples_ += num_samples;
465 if (max_abs > max_play_level_) { 542 if (max_abs > max_play_level_) {
466 max_play_level_ = max_abs; 543 max_play_level_ = max_abs;
467 } 544 }
468 } 545 }
469 546
470 } // namespace webrtc 547 } // namespace webrtc
OLDNEW

Powered by Google App Engine
This is Rietveld 408576698