1 /******************************************************************************
2 *
3 * Copyright 2016 The Android Open Source Project
4 * Copyright 2009-2012 Broadcom Corporation
5 *
6 * Licensed under the Apache License, Version 2.0 (the "License");
7 * you may not use this file except in compliance with the License.
8 * You may obtain a copy of the License at:
9 *
10 * http://www.apache.org/licenses/LICENSE-2.0
11 *
12 * Unless required by applicable law or agreed to in writing, software
13 * distributed under the License is distributed on an "AS IS" BASIS,
14 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
15 * See the License for the specific language governing permissions and
16 * limitations under the License.
17 *
18 ******************************************************************************/
19
20 #define LOG_TAG "bt_btif_a2dp_source"
21 #define ATRACE_TAG ATRACE_TAG_AUDIO
22
23 #include <base/run_loop.h>
24 #ifndef OS_GENERIC
25 #include <cutils/trace.h>
26 #endif
27 #include <inttypes.h>
28 #include <limits.h>
29 #include <string.h>
30 #include <algorithm>
31
32 #include "audio_a2dp_hw/include/audio_a2dp_hw.h"
33 #include "audio_hal_interface/a2dp_encoding.h"
34 #include "bt_common.h"
35 #include "bta_av_ci.h"
36 #include "btif_a2dp.h"
37 #include "btif_a2dp_audio_interface.h"
38 #include "btif_a2dp_control.h"
39 #include "btif_a2dp_source.h"
40 #include "btif_av.h"
41 #include "btif_av_co.h"
42 #include "btif_util.h"
43 #include "common/message_loop_thread.h"
44 #include "common/metrics.h"
45 #include "common/repeating_timer.h"
46 #include "common/time_util.h"
47 #include "osi/include/fixed_queue.h"
48 #include "osi/include/log.h"
49 #include "osi/include/osi.h"
50 #include "osi/include/wakelock.h"
51 #include "uipc.h"
52
53 using bluetooth::common::A2dpSessionMetrics;
54 using bluetooth::common::BluetoothMetricsLogger;
55 using bluetooth::common::RepeatingTimer;
56
57 extern std::unique_ptr<tUIPC_STATE> a2dp_uipc;
58
59 /**
60 * The typical runlevel of the tx queue size is ~1 buffer
61 * but due to link flow control or thread preemption in lower
62 * layers we might need to temporarily buffer up data.
63 */
64 #define MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ (MAX_PCM_FRAME_NUM_PER_TICK * 2)
65
66 class SchedulingStats {
67 public:
SchedulingStats()68 SchedulingStats() { Reset(); }
Reset()69 void Reset() {
70 total_updates = 0;
71 last_update_us = 0;
72 overdue_scheduling_count = 0;
73 total_overdue_scheduling_delta_us = 0;
74 max_overdue_scheduling_delta_us = 0;
75 premature_scheduling_count = 0;
76 total_premature_scheduling_delta_us = 0;
77 max_premature_scheduling_delta_us = 0;
78 exact_scheduling_count = 0;
79 total_scheduling_time_us = 0;
80 }
81
82 // Counter for total updates
83 size_t total_updates;
84
85 // Last update timestamp (in us)
86 uint64_t last_update_us;
87
88 // Counter for overdue scheduling
89 size_t overdue_scheduling_count;
90
91 // Accumulated overdue scheduling deviations (in us)
92 uint64_t total_overdue_scheduling_delta_us;
93
94 // Max. overdue scheduling delta time (in us)
95 uint64_t max_overdue_scheduling_delta_us;
96
97 // Counter for premature scheduling
98 size_t premature_scheduling_count;
99
100 // Accumulated premature scheduling deviations (in us)
101 uint64_t total_premature_scheduling_delta_us;
102
103 // Max. premature scheduling delta time (in us)
104 uint64_t max_premature_scheduling_delta_us;
105
106 // Counter for exact scheduling
107 size_t exact_scheduling_count;
108
109 // Accumulated and counted scheduling time (in us)
110 uint64_t total_scheduling_time_us;
111 };
112
113 class BtifMediaStats {
114 public:
BtifMediaStats()115 BtifMediaStats() { Reset(); }
Reset()116 void Reset() {
117 session_start_us = 0;
118 session_end_us = 0;
119 tx_queue_enqueue_stats.Reset();
120 tx_queue_dequeue_stats.Reset();
121 tx_queue_total_frames = 0;
122 tx_queue_max_frames_per_packet = 0;
123 tx_queue_total_queueing_time_us = 0;
124 tx_queue_max_queueing_time_us = 0;
125 tx_queue_total_readbuf_calls = 0;
126 tx_queue_last_readbuf_us = 0;
127 tx_queue_total_flushed_messages = 0;
128 tx_queue_last_flushed_us = 0;
129 tx_queue_total_dropped_messages = 0;
130 tx_queue_max_dropped_messages = 0;
131 tx_queue_dropouts = 0;
132 tx_queue_last_dropouts_us = 0;
133 media_read_total_underflow_bytes = 0;
134 media_read_total_underflow_count = 0;
135 media_read_last_underflow_us = 0;
136 codec_index = -1;
137 }
138
139 uint64_t session_start_us;
140 uint64_t session_end_us;
141
142 SchedulingStats tx_queue_enqueue_stats;
143 SchedulingStats tx_queue_dequeue_stats;
144
145 size_t tx_queue_total_frames;
146 size_t tx_queue_max_frames_per_packet;
147
148 uint64_t tx_queue_total_queueing_time_us;
149 uint64_t tx_queue_max_queueing_time_us;
150
151 size_t tx_queue_total_readbuf_calls;
152 uint64_t tx_queue_last_readbuf_us;
153
154 size_t tx_queue_total_flushed_messages;
155 uint64_t tx_queue_last_flushed_us;
156
157 size_t tx_queue_total_dropped_messages;
158 size_t tx_queue_max_dropped_messages;
159 size_t tx_queue_dropouts;
160 uint64_t tx_queue_last_dropouts_us;
161
162 size_t media_read_total_underflow_bytes;
163 size_t media_read_total_underflow_count;
164 uint64_t media_read_last_underflow_us;
165
166 int codec_index = -1;
167 };
168
169 class BtifA2dpSource {
170 public:
171 enum RunState {
172 kStateOff,
173 kStateStartingUp,
174 kStateRunning,
175 kStateShuttingDown
176 };
177
BtifA2dpSource()178 BtifA2dpSource()
179 : tx_audio_queue(nullptr),
180 tx_flush(false),
181 encoder_interface(nullptr),
182 encoder_interval_ms(0),
183 state_(kStateOff) {}
184
Reset()185 void Reset() {
186 fixed_queue_free(tx_audio_queue, nullptr);
187 tx_audio_queue = nullptr;
188 tx_flush = false;
189 media_alarm.CancelAndWait();
190 wakelock_release();
191 encoder_interface = nullptr;
192 encoder_interval_ms = 0;
193 stats.Reset();
194 accumulated_stats.Reset();
195 state_ = kStateOff;
196 }
197
State() const198 BtifA2dpSource::RunState State() const { return state_; }
StateStr() const199 std::string StateStr() const {
200 switch (state_) {
201 case kStateOff:
202 return "STATE_OFF";
203 case kStateStartingUp:
204 return "STATE_STARTING_UP";
205 case kStateRunning:
206 return "STATE_RUNNING";
207 case kStateShuttingDown:
208 return "STATE_SHUTTING_DOWN";
209 }
210 }
211
SetState(BtifA2dpSource::RunState state)212 void SetState(BtifA2dpSource::RunState state) { state_ = state; }
213
214 fixed_queue_t* tx_audio_queue;
215 bool tx_flush; /* Discards any outgoing data when true */
216 RepeatingTimer media_alarm;
217 const tA2DP_ENCODER_INTERFACE* encoder_interface;
218 uint64_t encoder_interval_ms; /* Local copy of the encoder interval */
219 BtifMediaStats stats;
220 BtifMediaStats accumulated_stats;
221
222 private:
223 BtifA2dpSource::RunState state_;
224 };
225
226 static bluetooth::common::MessageLoopThread btif_a2dp_source_thread(
227 "bt_a2dp_source_worker_thread");
228 static BtifA2dpSource btif_a2dp_source_cb;
229
230 static void btif_a2dp_source_init_delayed(void);
231 static void btif_a2dp_source_startup_delayed(void);
232 static void btif_a2dp_source_start_session_delayed(
233 const RawAddress& peer_address, std::promise<void> start_session_promise);
234 static void btif_a2dp_source_end_session_delayed(
235 const RawAddress& peer_address);
236 static void btif_a2dp_source_shutdown_delayed(void);
237 static void btif_a2dp_source_cleanup_delayed(void);
238 static void btif_a2dp_source_audio_tx_start_event(void);
239 static void btif_a2dp_source_audio_tx_stop_event(void);
240 static void btif_a2dp_source_audio_tx_flush_event(void);
241 // Set up the A2DP Source codec, and prepare the encoder.
242 // The peer address is |peer_addr|.
243 // This function should be called prior to starting A2DP streaming.
244 static void btif_a2dp_source_setup_codec(const RawAddress& peer_addr);
245 static void btif_a2dp_source_setup_codec_delayed(
246 const RawAddress& peer_address);
247 static void btif_a2dp_source_encoder_user_config_update_event(
248 const RawAddress& peer_address,
249 const btav_a2dp_codec_config_t& codec_user_config);
250 static void btif_a2dp_source_audio_feeding_update_event(
251 const btav_a2dp_codec_config_t& codec_audio_config);
252 static bool btif_a2dp_source_audio_tx_flush_req(void);
253 static void btif_a2dp_source_audio_handle_timer(void);
254 static uint32_t btif_a2dp_source_read_callback(uint8_t* p_buf, uint32_t len);
255 static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n,
256 uint32_t bytes_read);
257 static void log_tstamps_us(const char* comment, uint64_t timestamp_us);
258 static void update_scheduling_stats(SchedulingStats* stats, uint64_t now_us,
259 uint64_t expected_delta);
260 // Update the A2DP Source related metrics.
261 // This function should be called before collecting the metrics.
262 static void btif_a2dp_source_update_metrics(void);
263 static void btm_read_rssi_cb(void* data);
264 static void btm_read_failed_contact_counter_cb(void* data);
265 static void btm_read_automatic_flush_timeout_cb(void* data);
266 static void btm_read_tx_power_cb(void* data);
267
btif_a2dp_source_accumulate_scheduling_stats(SchedulingStats * src,SchedulingStats * dst)268 void btif_a2dp_source_accumulate_scheduling_stats(SchedulingStats* src,
269 SchedulingStats* dst) {
270 dst->total_updates += src->total_updates;
271 dst->last_update_us = src->last_update_us;
272 dst->overdue_scheduling_count += src->overdue_scheduling_count;
273 dst->total_overdue_scheduling_delta_us +=
274 src->total_overdue_scheduling_delta_us;
275 dst->max_overdue_scheduling_delta_us =
276 std::max(dst->max_overdue_scheduling_delta_us,
277 src->max_overdue_scheduling_delta_us);
278 dst->premature_scheduling_count += src->premature_scheduling_count;
279 dst->total_premature_scheduling_delta_us +=
280 src->total_premature_scheduling_delta_us;
281 dst->max_premature_scheduling_delta_us =
282 std::max(dst->max_premature_scheduling_delta_us,
283 src->max_premature_scheduling_delta_us);
284 dst->exact_scheduling_count += src->exact_scheduling_count;
285 dst->total_scheduling_time_us += src->total_scheduling_time_us;
286 }
287
btif_a2dp_source_accumulate_stats(BtifMediaStats * src,BtifMediaStats * dst)288 void btif_a2dp_source_accumulate_stats(BtifMediaStats* src,
289 BtifMediaStats* dst) {
290 dst->tx_queue_total_frames += src->tx_queue_total_frames;
291 dst->tx_queue_max_frames_per_packet = std::max(
292 dst->tx_queue_max_frames_per_packet, src->tx_queue_max_frames_per_packet);
293 dst->tx_queue_total_queueing_time_us += src->tx_queue_total_queueing_time_us;
294 dst->tx_queue_max_queueing_time_us = std::max(
295 dst->tx_queue_max_queueing_time_us, src->tx_queue_max_queueing_time_us);
296 dst->tx_queue_total_readbuf_calls += src->tx_queue_total_readbuf_calls;
297 dst->tx_queue_last_readbuf_us = src->tx_queue_last_readbuf_us;
298 dst->tx_queue_total_flushed_messages += src->tx_queue_total_flushed_messages;
299 dst->tx_queue_last_flushed_us = src->tx_queue_last_flushed_us;
300 dst->tx_queue_total_dropped_messages += src->tx_queue_total_dropped_messages;
301 dst->tx_queue_max_dropped_messages = std::max(
302 dst->tx_queue_max_dropped_messages, src->tx_queue_max_dropped_messages);
303 dst->tx_queue_dropouts += src->tx_queue_dropouts;
304 dst->tx_queue_last_dropouts_us = src->tx_queue_last_dropouts_us;
305 dst->media_read_total_underflow_bytes +=
306 src->media_read_total_underflow_bytes;
307 dst->media_read_total_underflow_count +=
308 src->media_read_total_underflow_count;
309 dst->media_read_last_underflow_us = src->media_read_last_underflow_us;
310 if (dst->codec_index < 0) dst->codec_index = src->codec_index;
311 btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_enqueue_stats,
312 &dst->tx_queue_enqueue_stats);
313 btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_dequeue_stats,
314 &dst->tx_queue_dequeue_stats);
315 src->Reset();
316 }
317
btif_a2dp_source_init(void)318 bool btif_a2dp_source_init(void) {
319 LOG_INFO(LOG_TAG, "%s", __func__);
320
321 // Start A2DP Source media task
322 btif_a2dp_source_thread.StartUp();
323 btif_a2dp_source_thread.DoInThread(
324 FROM_HERE, base::Bind(&btif_a2dp_source_init_delayed));
325 return true;
326 }
327
btif_a2dp_source_init_delayed(void)328 static void btif_a2dp_source_init_delayed(void) {
329 LOG_INFO(LOG_TAG, "%s", __func__);
330 // Nothing to do
331 }
332
btif_a2dp_source_startup(void)333 bool btif_a2dp_source_startup(void) {
334 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
335 btif_a2dp_source_cb.StateStr().c_str());
336
337 if (btif_a2dp_source_cb.State() != BtifA2dpSource::kStateOff) {
338 LOG_ERROR(LOG_TAG, "%s: A2DP Source media task already running", __func__);
339 return false;
340 }
341
342 btif_a2dp_source_cb.Reset();
343 btif_a2dp_source_cb.SetState(BtifA2dpSource::kStateStartingUp);
344 btif_a2dp_source_cb.tx_audio_queue = fixed_queue_new(SIZE_MAX);
345
346 // Schedule the rest of the operations
347 btif_a2dp_source_thread.DoInThread(
348 FROM_HERE, base::Bind(&btif_a2dp_source_startup_delayed));
349
350 return true;
351 }
352
btif_a2dp_source_startup_delayed()353 static void btif_a2dp_source_startup_delayed() {
354 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
355 btif_a2dp_source_cb.StateStr().c_str());
356 if (!btif_a2dp_source_thread.EnableRealTimeScheduling()) {
357 LOG(FATAL) << __func__ << ": unable to enable real time scheduling";
358 }
359 if (!bluetooth::audio::a2dp::init(&btif_a2dp_source_thread)) {
360 if (btif_av_is_a2dp_offload_enabled()) {
361 LOG(WARNING) << __func__ << ": Using BluetoothA2dp HAL";
362 } else {
363 LOG(WARNING) << __func__ << ": Using legacy HAL";
364 btif_a2dp_control_init();
365 }
366 }
367 btif_a2dp_source_cb.SetState(BtifA2dpSource::kStateRunning);
368 }
369
btif_a2dp_source_start_session(const RawAddress & peer_address,std::promise<void> peer_ready_promise)370 bool btif_a2dp_source_start_session(const RawAddress& peer_address,
371 std::promise<void> peer_ready_promise) {
372 LOG(INFO) << __func__ << ": peer_address=" << peer_address
373 << " state=" << btif_a2dp_source_cb.StateStr();
374 btif_a2dp_source_setup_codec(peer_address);
375 if (btif_a2dp_source_thread.DoInThread(
376 FROM_HERE,
377 base::BindOnce(&btif_a2dp_source_start_session_delayed, peer_address,
378 std::move(peer_ready_promise)))) {
379 return true;
380 } else {
381 // cannot set promise but triggers crash
382 LOG(FATAL) << __func__ << ": peer_address=" << peer_address
383 << " state=" << btif_a2dp_source_cb.StateStr()
384 << " fails to context switch";
385 return false;
386 }
387 }
388
btif_a2dp_source_start_session_delayed(const RawAddress & peer_address,std::promise<void> peer_ready_promise)389 static void btif_a2dp_source_start_session_delayed(
390 const RawAddress& peer_address, std::promise<void> peer_ready_promise) {
391 LOG(INFO) << __func__ << ": peer_address=" << peer_address
392 << " state=" << btif_a2dp_source_cb.StateStr();
393 if (btif_a2dp_source_cb.State() != BtifA2dpSource::kStateRunning) {
394 LOG(ERROR) << __func__ << ": A2DP Source media task is not running";
395 peer_ready_promise.set_value();
396 return;
397 }
398 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
399 bluetooth::audio::a2dp::start_session();
400 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart(
401 bluetooth::common::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0);
402 } else if (btif_av_is_a2dp_offload_enabled()) {
403 btif_a2dp_audio_interface_start_session();
404 } else {
405 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart(
406 bluetooth::common::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0);
407 }
408 peer_ready_promise.set_value();
409 }
410
btif_a2dp_source_restart_session(const RawAddress & old_peer_address,const RawAddress & new_peer_address,std::promise<void> peer_ready_promise)411 bool btif_a2dp_source_restart_session(const RawAddress& old_peer_address,
412 const RawAddress& new_peer_address,
413 std::promise<void> peer_ready_promise) {
414 bool is_streaming = btif_a2dp_source_cb.media_alarm.IsScheduled();
415 LOG(INFO) << __func__ << ": old_peer_address=" << old_peer_address
416 << " new_peer_address=" << new_peer_address
417 << " is_streaming=" << logbool(is_streaming)
418 << " state=" << btif_a2dp_source_cb.StateStr();
419
420 CHECK(!new_peer_address.IsEmpty());
421
422 // Must stop first the audio streaming
423 if (is_streaming) {
424 btif_a2dp_source_stop_audio_req();
425 }
426
427 // If the old active peer was valid, end the old session.
428 // Otherwise, time to startup the A2DP Source processing.
429 if (!old_peer_address.IsEmpty()) {
430 btif_a2dp_source_end_session(old_peer_address);
431 } else {
432 btif_a2dp_source_startup();
433 }
434
435 // Start the session.
436 // If audio was streaming before, start audio streaming as well.
437 btif_a2dp_source_start_session(new_peer_address,
438 std::move(peer_ready_promise));
439 if (is_streaming) {
440 btif_a2dp_source_start_audio_req();
441 }
442 return true;
443 }
444
btif_a2dp_source_end_session(const RawAddress & peer_address)445 bool btif_a2dp_source_end_session(const RawAddress& peer_address) {
446 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
447 peer_address.ToString().c_str(),
448 btif_a2dp_source_cb.StateStr().c_str());
449 btif_a2dp_source_thread.DoInThread(
450 FROM_HERE,
451 base::Bind(&btif_a2dp_source_end_session_delayed, peer_address));
452 return true;
453 }
454
btif_a2dp_source_end_session_delayed(const RawAddress & peer_address)455 static void btif_a2dp_source_end_session_delayed(
456 const RawAddress& peer_address) {
457 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
458 peer_address.ToString().c_str(),
459 btif_a2dp_source_cb.StateStr().c_str());
460 if ((btif_a2dp_source_cb.State() == BtifA2dpSource::kStateRunning) ||
461 (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateShuttingDown)) {
462 btif_av_stream_stop(peer_address);
463 } else {
464 LOG_ERROR(LOG_TAG, "%s: A2DP Source media task is not running", __func__);
465 }
466 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
467 bluetooth::audio::a2dp::end_session();
468 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd(
469 bluetooth::common::DISCONNECT_REASON_UNKNOWN, 0);
470 } else if (btif_av_is_a2dp_offload_enabled()) {
471 btif_a2dp_audio_interface_end_session();
472 } else {
473 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd(
474 bluetooth::common::DISCONNECT_REASON_UNKNOWN, 0);
475 }
476 }
477
btif_a2dp_source_shutdown(void)478 void btif_a2dp_source_shutdown(void) {
479 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
480 btif_a2dp_source_cb.StateStr().c_str());
481
482 if ((btif_a2dp_source_cb.State() == BtifA2dpSource::kStateOff) ||
483 (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateShuttingDown)) {
484 return;
485 }
486
487 /* Make sure no channels are restarted while shutting down */
488 btif_a2dp_source_cb.SetState(BtifA2dpSource::kStateShuttingDown);
489
490 btif_a2dp_source_thread.DoInThread(
491 FROM_HERE, base::Bind(&btif_a2dp_source_shutdown_delayed));
492 }
493
btif_a2dp_source_shutdown_delayed(void)494 static void btif_a2dp_source_shutdown_delayed(void) {
495 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
496 btif_a2dp_source_cb.StateStr().c_str());
497
498 // Stop the timer
499 btif_a2dp_source_cb.media_alarm.CancelAndWait();
500 wakelock_release();
501
502 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
503 bluetooth::audio::a2dp::cleanup();
504 } else if (btif_av_is_a2dp_offload_enabled()) {
505 btif_a2dp_audio_interface_end_session();
506 } else {
507 btif_a2dp_control_cleanup();
508 }
509 fixed_queue_free(btif_a2dp_source_cb.tx_audio_queue, nullptr);
510 btif_a2dp_source_cb.tx_audio_queue = nullptr;
511
512 btif_a2dp_source_cb.SetState(BtifA2dpSource::kStateOff);
513 }
514
btif_a2dp_source_cleanup(void)515 void btif_a2dp_source_cleanup(void) {
516 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
517 btif_a2dp_source_cb.StateStr().c_str());
518
519 // Make sure the source is shutdown
520 btif_a2dp_source_shutdown();
521
522 btif_a2dp_source_thread.DoInThread(
523 FROM_HERE, base::Bind(&btif_a2dp_source_cleanup_delayed));
524
525 // Exit the thread
526 btif_a2dp_source_thread.ShutDown();
527 }
528
btif_a2dp_source_cleanup_delayed(void)529 static void btif_a2dp_source_cleanup_delayed(void) {
530 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
531 btif_a2dp_source_cb.StateStr().c_str());
532 // Nothing to do
533 }
534
btif_a2dp_source_media_task_is_running(void)535 bool btif_a2dp_source_media_task_is_running(void) {
536 return (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateRunning);
537 }
538
btif_a2dp_source_media_task_is_shutting_down(void)539 bool btif_a2dp_source_media_task_is_shutting_down(void) {
540 return (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateShuttingDown);
541 }
542
btif_a2dp_source_is_streaming(void)543 bool btif_a2dp_source_is_streaming(void) {
544 return btif_a2dp_source_cb.media_alarm.IsScheduled();
545 }
546
btif_a2dp_source_setup_codec(const RawAddress & peer_address)547 static void btif_a2dp_source_setup_codec(const RawAddress& peer_address) {
548 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
549 peer_address.ToString().c_str(),
550 btif_a2dp_source_cb.StateStr().c_str());
551
552 // Check to make sure the platform has 8 bits/byte since
553 // we're using that in frame size calculations now.
554 CHECK(CHAR_BIT == 8);
555
556 btif_a2dp_source_audio_tx_flush_req();
557 btif_a2dp_source_thread.DoInThread(
558 FROM_HERE,
559 base::Bind(&btif_a2dp_source_setup_codec_delayed, peer_address));
560 }
561
btif_a2dp_source_setup_codec_delayed(const RawAddress & peer_address)562 static void btif_a2dp_source_setup_codec_delayed(
563 const RawAddress& peer_address) {
564 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
565 peer_address.ToString().c_str(),
566 btif_a2dp_source_cb.StateStr().c_str());
567
568 tA2DP_ENCODER_INIT_PEER_PARAMS peer_params;
569 bta_av_co_get_peer_params(peer_address, &peer_params);
570
571 if (!bta_av_co_set_active_peer(peer_address)) {
572 LOG_ERROR(LOG_TAG, "%s: Cannot stream audio: cannot set active peer to %s",
573 __func__, peer_address.ToString().c_str());
574 return;
575 }
576 btif_a2dp_source_cb.encoder_interface = bta_av_co_get_encoder_interface();
577 if (btif_a2dp_source_cb.encoder_interface == nullptr) {
578 LOG_ERROR(LOG_TAG, "%s: Cannot stream audio: no source encoder interface",
579 __func__);
580 return;
581 }
582
583 A2dpCodecConfig* a2dp_codec_config = bta_av_get_a2dp_current_codec();
584 if (a2dp_codec_config == nullptr) {
585 LOG_ERROR(LOG_TAG, "%s: Cannot stream audio: current codec is not set",
586 __func__);
587 return;
588 }
589
590 btif_a2dp_source_cb.encoder_interface->encoder_init(
591 &peer_params, a2dp_codec_config, btif_a2dp_source_read_callback,
592 btif_a2dp_source_enqueue_callback);
593
594 // Save a local copy of the encoder_interval_ms
595 btif_a2dp_source_cb.encoder_interval_ms =
596 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms();
597
598 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
599 bluetooth::audio::a2dp::setup_codec();
600 }
601 }
602
btif_a2dp_source_start_audio_req(void)603 void btif_a2dp_source_start_audio_req(void) {
604 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
605 btif_a2dp_source_cb.StateStr().c_str());
606
607 btif_a2dp_source_thread.DoInThread(
608 FROM_HERE, base::Bind(&btif_a2dp_source_audio_tx_start_event));
609 }
610
btif_a2dp_source_stop_audio_req(void)611 void btif_a2dp_source_stop_audio_req(void) {
612 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
613 btif_a2dp_source_cb.StateStr().c_str());
614
615 btif_a2dp_source_thread.DoInThread(
616 FROM_HERE, base::Bind(&btif_a2dp_source_audio_tx_stop_event));
617 }
618
btif_a2dp_source_encoder_user_config_update_req(const RawAddress & peer_address,const btav_a2dp_codec_config_t & codec_user_config)619 void btif_a2dp_source_encoder_user_config_update_req(
620 const RawAddress& peer_address,
621 const btav_a2dp_codec_config_t& codec_user_config) {
622 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
623 peer_address.ToString().c_str(),
624 btif_a2dp_source_cb.StateStr().c_str());
625 btif_a2dp_source_thread.DoInThread(
626 FROM_HERE, base::Bind(&btif_a2dp_source_encoder_user_config_update_event,
627 peer_address, codec_user_config));
628 }
629
btif_a2dp_source_encoder_user_config_update_event(const RawAddress & peer_address,const btav_a2dp_codec_config_t & codec_user_config)630 static void btif_a2dp_source_encoder_user_config_update_event(
631 const RawAddress& peer_address,
632 const btav_a2dp_codec_config_t& codec_user_config) {
633 LOG_INFO(LOG_TAG, "%s: peer_address=%s state=%s", __func__,
634 peer_address.ToString().c_str(),
635 btif_a2dp_source_cb.StateStr().c_str());
636 if (!bta_av_co_set_codec_user_config(peer_address, codec_user_config)) {
637 LOG_ERROR(LOG_TAG, "%s: cannot update codec user configuration", __func__);
638 }
639 }
640
btif_a2dp_source_feeding_update_req(const btav_a2dp_codec_config_t & codec_audio_config)641 void btif_a2dp_source_feeding_update_req(
642 const btav_a2dp_codec_config_t& codec_audio_config) {
643 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
644 btif_a2dp_source_cb.StateStr().c_str());
645 btif_a2dp_source_thread.DoInThread(
646 FROM_HERE, base::Bind(&btif_a2dp_source_audio_feeding_update_event,
647 codec_audio_config));
648 }
649
btif_a2dp_source_audio_feeding_update_event(const btav_a2dp_codec_config_t & codec_audio_config)650 static void btif_a2dp_source_audio_feeding_update_event(
651 const btav_a2dp_codec_config_t& codec_audio_config) {
652 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
653 btif_a2dp_source_cb.StateStr().c_str());
654 if (!bta_av_co_set_codec_audio_config(codec_audio_config)) {
655 LOG_ERROR(LOG_TAG, "%s: cannot update codec audio feeding parameters",
656 __func__);
657 }
658 }
659
btif_a2dp_source_on_idle(void)660 void btif_a2dp_source_on_idle(void) {
661 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
662 btif_a2dp_source_cb.StateStr().c_str());
663 if (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateOff) return;
664
665 /* Make sure media task is stopped */
666 btif_a2dp_source_stop_audio_req();
667 }
668
btif_a2dp_source_on_stopped(tBTA_AV_SUSPEND * p_av_suspend)669 void btif_a2dp_source_on_stopped(tBTA_AV_SUSPEND* p_av_suspend) {
670 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
671 btif_a2dp_source_cb.StateStr().c_str());
672
673 if (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateOff) return;
674
675 /* allow using this api for other than suspend */
676 if (p_av_suspend != nullptr) {
677 if (p_av_suspend->status != BTA_AV_SUCCESS) {
678 LOG_ERROR(LOG_TAG, "%s: A2DP stop request failed: status=%d", __func__,
679 p_av_suspend->status);
680 if (p_av_suspend->initiator) {
681 LOG_WARN(LOG_TAG, "%s: A2DP stop request failed: status=%d", __func__,
682 p_av_suspend->status);
683 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
684 bluetooth::audio::a2dp::ack_stream_suspended(A2DP_CTRL_ACK_FAILURE);
685 } else {
686 btif_a2dp_command_ack(A2DP_CTRL_ACK_FAILURE);
687 }
688 }
689 return;
690 }
691 }
692 if (btif_av_is_a2dp_offload_enabled()) {
693 bluetooth::audio::a2dp::ack_stream_suspended(A2DP_CTRL_ACK_SUCCESS);
694 return;
695 }
696 /* ensure tx frames are immediately suspended */
697 btif_a2dp_source_cb.tx_flush = true;
698
699 /* request to stop media task */
700 btif_a2dp_source_audio_tx_flush_req();
701 btif_a2dp_source_stop_audio_req();
702
703 /* once stream is fully stopped we will ack back */
704 }
705
btif_a2dp_source_on_suspended(tBTA_AV_SUSPEND * p_av_suspend)706 void btif_a2dp_source_on_suspended(tBTA_AV_SUSPEND* p_av_suspend) {
707 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
708 btif_a2dp_source_cb.StateStr().c_str());
709
710 if (btif_a2dp_source_cb.State() == BtifA2dpSource::kStateOff) return;
711
712 /* check for status failures */
713 if (p_av_suspend->status != BTA_AV_SUCCESS) {
714 if (p_av_suspend->initiator) {
715 LOG_WARN(LOG_TAG, "%s: A2DP suspend request failed: status=%d", __func__,
716 p_av_suspend->status);
717 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
718 bluetooth::audio::a2dp::ack_stream_suspended(A2DP_CTRL_ACK_FAILURE);
719 } else {
720 btif_a2dp_command_ack(A2DP_CTRL_ACK_FAILURE);
721 }
722 }
723 }
724 if (btif_av_is_a2dp_offload_enabled()) {
725 bluetooth::audio::a2dp::ack_stream_suspended(A2DP_CTRL_ACK_SUCCESS);
726 return;
727 }
728 /* once stream is fully stopped we will ack back */
729
730 /* ensure tx frames are immediately flushed */
731 btif_a2dp_source_cb.tx_flush = true;
732
733 /* stop timer tick */
734 btif_a2dp_source_stop_audio_req();
735 }
736
737 /* when true media task discards any tx frames */
btif_a2dp_source_set_tx_flush(bool enable)738 void btif_a2dp_source_set_tx_flush(bool enable) {
739 LOG_INFO(LOG_TAG, "%s: enable=%s state=%s", __func__,
740 (enable) ? "true" : "false", btif_a2dp_source_cb.StateStr().c_str());
741 btif_a2dp_source_cb.tx_flush = enable;
742 }
743
btif_a2dp_source_audio_tx_start_event(void)744 static void btif_a2dp_source_audio_tx_start_event(void) {
745 LOG_INFO(LOG_TAG, "%s: media_alarm is %srunning, streaming %s state=%s",
746 __func__,
747 btif_a2dp_source_cb.media_alarm.IsScheduled() ? "" : "not ",
748 btif_a2dp_source_is_streaming() ? "true" : "false",
749 btif_a2dp_source_cb.StateStr().c_str());
750
751 if (btif_av_is_a2dp_offload_enabled()) return;
752
753 /* Reset the media feeding state */
754 CHECK(btif_a2dp_source_cb.encoder_interface != nullptr);
755 btif_a2dp_source_cb.encoder_interface->feeding_reset();
756
757 APPL_TRACE_EVENT(
758 "%s: starting timer %" PRIu64 " ms", __func__,
759 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms());
760
761 wakelock_acquire();
762 btif_a2dp_source_cb.media_alarm.SchedulePeriodic(
763 btif_a2dp_source_thread.GetWeakPtr(), FROM_HERE,
764 base::Bind(&btif_a2dp_source_audio_handle_timer),
765 base::TimeDelta::FromMilliseconds(
766 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms()));
767
768 btif_a2dp_source_cb.stats.Reset();
769 // Assign session_start_us to 1 when
770 // bluetooth::common::time_get_os_boottime_us() is 0 to indicate
771 // btif_a2dp_source_start_audio_req() has been called
772 btif_a2dp_source_cb.stats.session_start_us =
773 bluetooth::common::time_get_os_boottime_us();
774 if (btif_a2dp_source_cb.stats.session_start_us == 0) {
775 btif_a2dp_source_cb.stats.session_start_us = 1;
776 }
777 btif_a2dp_source_cb.stats.session_end_us = 0;
778 A2dpCodecConfig* codec_config = bta_av_get_a2dp_current_codec();
779 if (codec_config != nullptr) {
780 btif_a2dp_source_cb.stats.codec_index = codec_config->codecIndex();
781 }
782 }
783
btif_a2dp_source_audio_tx_stop_event(void)784 static void btif_a2dp_source_audio_tx_stop_event(void) {
785 LOG_INFO(LOG_TAG, "%s: media_alarm is %srunning, streaming %s state=%s",
786 __func__,
787 btif_a2dp_source_cb.media_alarm.IsScheduled() ? "" : "not ",
788 btif_a2dp_source_is_streaming() ? "true" : "false",
789 btif_a2dp_source_cb.StateStr().c_str());
790
791 if (btif_av_is_a2dp_offload_enabled()) return;
792
793 btif_a2dp_source_cb.stats.session_end_us =
794 bluetooth::common::time_get_os_boottime_us();
795 btif_a2dp_source_update_metrics();
796 btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats,
797 &btif_a2dp_source_cb.accumulated_stats);
798
799 uint8_t p_buf[AUDIO_STREAM_OUTPUT_BUFFER_SZ * 2];
800 uint16_t event;
801
802 // Keep track of audio data still left in the pipe
803 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
804 btif_a2dp_control_log_bytes_read(
805 bluetooth::audio::a2dp::read(p_buf, sizeof(p_buf)));
806 } else if (a2dp_uipc != nullptr) {
807 btif_a2dp_control_log_bytes_read(UIPC_Read(*a2dp_uipc, UIPC_CH_ID_AV_AUDIO,
808 &event, p_buf, sizeof(p_buf)));
809 }
810
811 /* Stop the timer first */
812 btif_a2dp_source_cb.media_alarm.CancelAndWait();
813 wakelock_release();
814
815 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
816 bluetooth::audio::a2dp::ack_stream_suspended(A2DP_CTRL_ACK_SUCCESS);
817 } else if (a2dp_uipc != nullptr) {
818 UIPC_Close(*a2dp_uipc, UIPC_CH_ID_AV_AUDIO);
819
820 /*
821 * Try to send acknowldegment once the media stream is
822 * stopped. This will make sure that the A2DP HAL layer is
823 * un-blocked on wait for acknowledgment for the sent command.
824 * This resolves a corner cases AVDTP SUSPEND collision
825 * when the DUT and the remote device issue SUSPEND simultaneously
826 * and due to the processing of the SUSPEND request from the remote,
827 * the media path is torn down. If the A2DP HAL happens to wait
828 * for ACK for the initiated SUSPEND, it would never receive it casuing
829 * a block/wait. Due to this acknowledgement, the A2DP HAL is guranteed
830 * to get the ACK for any pending command in such cases.
831 */
832
833 btif_a2dp_command_ack(A2DP_CTRL_ACK_SUCCESS);
834 }
835
836 /* audio engine stopped, reset tx suspended flag */
837 btif_a2dp_source_cb.tx_flush = false;
838
839 /* Reset the media feeding state */
840 if (btif_a2dp_source_cb.encoder_interface != nullptr)
841 btif_a2dp_source_cb.encoder_interface->feeding_reset();
842 }
843
btif_a2dp_source_audio_handle_timer(void)844 static void btif_a2dp_source_audio_handle_timer(void) {
845 if (btif_av_is_a2dp_offload_enabled()) return;
846
847 uint64_t timestamp_us = bluetooth::common::time_get_os_boottime_us();
848 log_tstamps_us("A2DP Source tx timer", timestamp_us);
849
850 if (!btif_a2dp_source_cb.media_alarm.IsScheduled()) {
851 LOG_ERROR(LOG_TAG, "%s: ERROR Media task Scheduled after Suspend",
852 __func__);
853 return;
854 }
855 CHECK(btif_a2dp_source_cb.encoder_interface != nullptr);
856 size_t transmit_queue_length =
857 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
858 #ifndef OS_GENERIC
859 ATRACE_INT("btif TX queue", transmit_queue_length);
860 #endif
861 if (btif_a2dp_source_cb.encoder_interface->set_transmit_queue_length !=
862 nullptr) {
863 btif_a2dp_source_cb.encoder_interface->set_transmit_queue_length(
864 transmit_queue_length);
865 }
866 btif_a2dp_source_cb.encoder_interface->send_frames(timestamp_us);
867 bta_av_ci_src_data_ready(BTA_AV_CHNL_AUDIO);
868 update_scheduling_stats(&btif_a2dp_source_cb.stats.tx_queue_enqueue_stats,
869 timestamp_us,
870 btif_a2dp_source_cb.encoder_interval_ms * 1000);
871 }
872
btif_a2dp_source_read_callback(uint8_t * p_buf,uint32_t len)873 static uint32_t btif_a2dp_source_read_callback(uint8_t* p_buf, uint32_t len) {
874 uint16_t event;
875 uint32_t bytes_read = 0;
876
877 if (bluetooth::audio::a2dp::is_hal_2_0_enabled()) {
878 bytes_read = bluetooth::audio::a2dp::read(p_buf, len);
879 } else if (a2dp_uipc != nullptr) {
880 bytes_read = UIPC_Read(*a2dp_uipc, UIPC_CH_ID_AV_AUDIO, &event, p_buf, len);
881 }
882
883 if (bytes_read < len) {
884 LOG_WARN(LOG_TAG, "%s: UNDERFLOW: ONLY READ %d BYTES OUT OF %d", __func__,
885 bytes_read, len);
886 btif_a2dp_source_cb.stats.media_read_total_underflow_bytes +=
887 (len - bytes_read);
888 btif_a2dp_source_cb.stats.media_read_total_underflow_count++;
889 btif_a2dp_source_cb.stats.media_read_last_underflow_us =
890 bluetooth::common::time_get_os_boottime_us();
891 bluetooth::common::LogA2dpAudioUnderrunEvent(
892 btif_av_source_active_peer(), btif_a2dp_source_cb.encoder_interval_ms,
893 len - bytes_read);
894 }
895
896 return bytes_read;
897 }
898
btif_a2dp_source_enqueue_callback(BT_HDR * p_buf,size_t frames_n,uint32_t bytes_read)899 static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n,
900 uint32_t bytes_read) {
901 uint64_t now_us = bluetooth::common::time_get_os_boottime_us();
902 btif_a2dp_control_log_bytes_read(bytes_read);
903
904 /* Check if timer was stopped (media task stopped) */
905 if (!btif_a2dp_source_cb.media_alarm.IsScheduled()) {
906 osi_free(p_buf);
907 return false;
908 }
909
910 /* Check if the transmission queue has been flushed */
911 if (btif_a2dp_source_cb.tx_flush) {
912 LOG_VERBOSE(LOG_TAG, "%s: tx suspended, discarded frame", __func__);
913
914 btif_a2dp_source_cb.stats.tx_queue_total_flushed_messages +=
915 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
916 btif_a2dp_source_cb.stats.tx_queue_last_flushed_us = now_us;
917 fixed_queue_flush(btif_a2dp_source_cb.tx_audio_queue, osi_free);
918
919 osi_free(p_buf);
920 return false;
921 }
922
923 // Check for TX queue overflow
924 // TODO: Using frames_n here is probably wrong: should be "+ 1" instead.
925 if (fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue) + frames_n >
926 MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ) {
927 LOG_WARN(LOG_TAG, "%s: TX queue buffer size now=%u adding=%u max=%d",
928 __func__,
929 (uint32_t)fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue),
930 (uint32_t)frames_n, MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ);
931 // Keep track of drop-outs
932 btif_a2dp_source_cb.stats.tx_queue_dropouts++;
933 btif_a2dp_source_cb.stats.tx_queue_last_dropouts_us = now_us;
934
935 // Flush all queued buffers
936 size_t drop_n = fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
937 btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages = std::max(
938 drop_n, btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages);
939 int num_dropped_encoded_bytes = 0;
940 int num_dropped_encoded_frames = 0;
941 while (fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue)) {
942 btif_a2dp_source_cb.stats.tx_queue_total_dropped_messages++;
943 void* p_data =
944 fixed_queue_try_dequeue(btif_a2dp_source_cb.tx_audio_queue);
945 if (p_data != nullptr) {
946 auto p_dropped_buf = static_cast<BT_HDR*>(p_data);
947 num_dropped_encoded_bytes += p_dropped_buf->len;
948 num_dropped_encoded_frames += p_dropped_buf->layer_specific;
949 osi_free(p_data);
950 }
951 }
952 bluetooth::common::LogA2dpAudioOverrunEvent(
953 btif_av_source_active_peer(), drop_n,
954 btif_a2dp_source_cb.encoder_interval_ms, num_dropped_encoded_frames,
955 num_dropped_encoded_bytes);
956
957 // Request additional debug info if we had to flush buffers
958 RawAddress peer_bda = btif_av_source_active_peer();
959 tBTM_STATUS status = BTM_ReadRSSI(peer_bda, btm_read_rssi_cb);
960 if (status != BTM_CMD_STARTED) {
961 LOG_WARN(LOG_TAG, "%s: Cannot read RSSI: status %d", __func__, status);
962 }
963 status = BTM_ReadFailedContactCounter(peer_bda,
964 btm_read_failed_contact_counter_cb);
965 if (status != BTM_CMD_STARTED) {
966 LOG_WARN(LOG_TAG, "%s: Cannot read Failed Contact Counter: status %d",
967 __func__, status);
968 }
969 status = BTM_ReadAutomaticFlushTimeout(peer_bda,
970 btm_read_automatic_flush_timeout_cb);
971 if (status != BTM_CMD_STARTED) {
972 LOG_WARN(LOG_TAG, "%s: Cannot read Automatic Flush Timeout: status %d",
973 __func__, status);
974 }
975 status =
976 BTM_ReadTxPower(peer_bda, BT_TRANSPORT_BR_EDR, btm_read_tx_power_cb);
977 if (status != BTM_CMD_STARTED) {
978 LOG_WARN(LOG_TAG, "%s: Cannot read Tx Power: status %d", __func__,
979 status);
980 }
981 }
982
983 /* Update the statistics */
984 btif_a2dp_source_cb.stats.tx_queue_total_frames += frames_n;
985 btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet = std::max(
986 frames_n, btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet);
987 CHECK(btif_a2dp_source_cb.encoder_interface != nullptr);
988
989 fixed_queue_enqueue(btif_a2dp_source_cb.tx_audio_queue, p_buf);
990
991 return true;
992 }
993
btif_a2dp_source_audio_tx_flush_event(void)994 static void btif_a2dp_source_audio_tx_flush_event(void) {
995 /* Flush all enqueued audio buffers (encoded) */
996 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
997 btif_a2dp_source_cb.StateStr().c_str());
998 if (btif_av_is_a2dp_offload_enabled()) return;
999
1000 if (btif_a2dp_source_cb.encoder_interface != nullptr)
1001 btif_a2dp_source_cb.encoder_interface->feeding_flush();
1002
1003 btif_a2dp_source_cb.stats.tx_queue_total_flushed_messages +=
1004 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
1005 btif_a2dp_source_cb.stats.tx_queue_last_flushed_us =
1006 bluetooth::common::time_get_os_boottime_us();
1007 fixed_queue_flush(btif_a2dp_source_cb.tx_audio_queue, osi_free);
1008
1009 if (!bluetooth::audio::a2dp::is_hal_2_0_enabled() && a2dp_uipc != nullptr) {
1010 UIPC_Ioctl(*a2dp_uipc, UIPC_CH_ID_AV_AUDIO, UIPC_REQ_RX_FLUSH, nullptr);
1011 }
1012 }
1013
btif_a2dp_source_audio_tx_flush_req(void)1014 static bool btif_a2dp_source_audio_tx_flush_req(void) {
1015 LOG_INFO(LOG_TAG, "%s: state=%s", __func__,
1016 btif_a2dp_source_cb.StateStr().c_str());
1017
1018 btif_a2dp_source_thread.DoInThread(
1019 FROM_HERE, base::Bind(&btif_a2dp_source_audio_tx_flush_event));
1020 return true;
1021 }
1022
btif_a2dp_source_audio_readbuf(void)1023 BT_HDR* btif_a2dp_source_audio_readbuf(void) {
1024 uint64_t now_us = bluetooth::common::time_get_os_boottime_us();
1025 BT_HDR* p_buf =
1026 (BT_HDR*)fixed_queue_try_dequeue(btif_a2dp_source_cb.tx_audio_queue);
1027
1028 btif_a2dp_source_cb.stats.tx_queue_total_readbuf_calls++;
1029 btif_a2dp_source_cb.stats.tx_queue_last_readbuf_us = now_us;
1030 if (p_buf != nullptr) {
1031 // Update the statistics
1032 update_scheduling_stats(&btif_a2dp_source_cb.stats.tx_queue_dequeue_stats,
1033 now_us,
1034 btif_a2dp_source_cb.encoder_interval_ms * 1000);
1035 }
1036
1037 return p_buf;
1038 }
1039
log_tstamps_us(const char * comment,uint64_t timestamp_us)1040 static void log_tstamps_us(const char* comment, uint64_t timestamp_us) {
1041 static uint64_t prev_us = 0;
1042 APPL_TRACE_DEBUG("%s: [%s] ts %08" PRIu64 ", diff : %08" PRIu64
1043 ", queue sz %zu",
1044 __func__, comment, timestamp_us, timestamp_us - prev_us,
1045 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue));
1046 prev_us = timestamp_us;
1047 }
1048
update_scheduling_stats(SchedulingStats * stats,uint64_t now_us,uint64_t expected_delta)1049 static void update_scheduling_stats(SchedulingStats* stats, uint64_t now_us,
1050 uint64_t expected_delta) {
1051 uint64_t last_us = stats->last_update_us;
1052
1053 stats->total_updates++;
1054 stats->last_update_us = now_us;
1055
1056 if (last_us == 0) return; // First update: expected delta doesn't apply
1057
1058 uint64_t deadline_us = last_us + expected_delta;
1059 if (deadline_us < now_us) {
1060 // Overdue scheduling
1061 uint64_t delta_us = now_us - deadline_us;
1062 // Ignore extreme outliers
1063 if (delta_us < 10 * expected_delta) {
1064 stats->max_overdue_scheduling_delta_us =
1065 std::max(delta_us, stats->max_overdue_scheduling_delta_us);
1066 stats->total_overdue_scheduling_delta_us += delta_us;
1067 stats->overdue_scheduling_count++;
1068 stats->total_scheduling_time_us += now_us - last_us;
1069 }
1070 } else if (deadline_us > now_us) {
1071 // Premature scheduling
1072 uint64_t delta_us = deadline_us - now_us;
1073 // Ignore extreme outliers
1074 if (delta_us < 10 * expected_delta) {
1075 stats->max_premature_scheduling_delta_us =
1076 std::max(delta_us, stats->max_premature_scheduling_delta_us);
1077 stats->total_premature_scheduling_delta_us += delta_us;
1078 stats->premature_scheduling_count++;
1079 stats->total_scheduling_time_us += now_us - last_us;
1080 }
1081 } else {
1082 // On-time scheduling
1083 stats->exact_scheduling_count++;
1084 stats->total_scheduling_time_us += now_us - last_us;
1085 }
1086 }
1087
btif_a2dp_source_debug_dump(int fd)1088 void btif_a2dp_source_debug_dump(int fd) {
1089 btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats,
1090 &btif_a2dp_source_cb.accumulated_stats);
1091 uint64_t now_us = bluetooth::common::time_get_os_boottime_us();
1092 BtifMediaStats* accumulated_stats = &btif_a2dp_source_cb.accumulated_stats;
1093 SchedulingStats* enqueue_stats = &accumulated_stats->tx_queue_enqueue_stats;
1094 SchedulingStats* dequeue_stats = &accumulated_stats->tx_queue_dequeue_stats;
1095 size_t ave_size;
1096 uint64_t ave_time_us;
1097
1098 dprintf(fd, "\nA2DP State:\n");
1099 dprintf(fd, " TxQueue:\n");
1100
1101 dprintf(fd,
1102 " Counts (enqueue/dequeue/readbuf) : %zu / "
1103 "%zu / %zu\n",
1104 enqueue_stats->total_updates, dequeue_stats->total_updates,
1105 accumulated_stats->tx_queue_total_readbuf_calls);
1106
1107 dprintf(
1108 fd,
1109 " Last update time ago in ms (enqueue/dequeue/readbuf) : %llu / %llu "
1110 "/ %llu\n",
1111 (enqueue_stats->last_update_us > 0)
1112 ? (unsigned long long)(now_us - enqueue_stats->last_update_us) / 1000
1113 : 0,
1114 (dequeue_stats->last_update_us > 0)
1115 ? (unsigned long long)(now_us - dequeue_stats->last_update_us) / 1000
1116 : 0,
1117 (accumulated_stats->tx_queue_last_readbuf_us > 0)
1118 ? (unsigned long long)(now_us -
1119 accumulated_stats->tx_queue_last_readbuf_us) /
1120 1000
1121 : 0);
1122
1123 ave_size = 0;
1124 if (enqueue_stats->total_updates != 0)
1125 ave_size =
1126 accumulated_stats->tx_queue_total_frames / enqueue_stats->total_updates;
1127 dprintf(fd,
1128 " Frames per packet (total/max/ave) : %zu / "
1129 "%zu / %zu\n",
1130 accumulated_stats->tx_queue_total_frames,
1131 accumulated_stats->tx_queue_max_frames_per_packet, ave_size);
1132
1133 dprintf(fd,
1134 " Counts (flushed/dropped/dropouts) : %zu / "
1135 "%zu / %zu\n",
1136 accumulated_stats->tx_queue_total_flushed_messages,
1137 accumulated_stats->tx_queue_total_dropped_messages,
1138 accumulated_stats->tx_queue_dropouts);
1139
1140 dprintf(fd,
1141 " Counts (max dropped) : %zu\n",
1142 accumulated_stats->tx_queue_max_dropped_messages);
1143
1144 dprintf(
1145 fd,
1146 " Last update time ago in ms (flushed/dropped) : %llu / "
1147 "%llu\n",
1148 (accumulated_stats->tx_queue_last_flushed_us > 0)
1149 ? (unsigned long long)(now_us -
1150 accumulated_stats->tx_queue_last_flushed_us) /
1151 1000
1152 : 0,
1153 (accumulated_stats->tx_queue_last_dropouts_us > 0)
1154 ? (unsigned long long)(now_us -
1155 accumulated_stats->tx_queue_last_dropouts_us) /
1156 1000
1157 : 0);
1158
1159 dprintf(fd,
1160 " Counts (underflow) : %zu\n",
1161 accumulated_stats->media_read_total_underflow_count);
1162
1163 dprintf(fd,
1164 " Bytes (underflow) : %zu\n",
1165 accumulated_stats->media_read_total_underflow_bytes);
1166
1167 dprintf(fd,
1168 " Last update time ago in ms (underflow) : %llu\n",
1169 (accumulated_stats->media_read_last_underflow_us > 0)
1170 ? (unsigned long long)(now_us -
1171 accumulated_stats
1172 ->media_read_last_underflow_us) /
1173 1000
1174 : 0);
1175
1176 //
1177 // TxQueue enqueue stats
1178 //
1179 dprintf(
1180 fd,
1181 " Enqueue deviation counts (overdue/premature) : %zu / %zu\n",
1182 enqueue_stats->overdue_scheduling_count,
1183 enqueue_stats->premature_scheduling_count);
1184
1185 ave_time_us = 0;
1186 if (enqueue_stats->overdue_scheduling_count != 0) {
1187 ave_time_us = enqueue_stats->total_overdue_scheduling_delta_us /
1188 enqueue_stats->overdue_scheduling_count;
1189 }
1190 dprintf(
1191 fd,
1192 " Enqueue overdue scheduling time in ms (total/max/ave) : %llu / %llu "
1193 "/ %llu\n",
1194 (unsigned long long)enqueue_stats->total_overdue_scheduling_delta_us /
1195 1000,
1196 (unsigned long long)enqueue_stats->max_overdue_scheduling_delta_us / 1000,
1197 (unsigned long long)ave_time_us / 1000);
1198
1199 ave_time_us = 0;
1200 if (enqueue_stats->premature_scheduling_count != 0) {
1201 ave_time_us = enqueue_stats->total_premature_scheduling_delta_us /
1202 enqueue_stats->premature_scheduling_count;
1203 }
1204 dprintf(
1205 fd,
1206 " Enqueue premature scheduling time in ms (total/max/ave) : %llu / %llu "
1207 "/ %llu\n",
1208 (unsigned long long)enqueue_stats->total_premature_scheduling_delta_us /
1209 1000,
1210 (unsigned long long)enqueue_stats->max_premature_scheduling_delta_us /
1211 1000,
1212 (unsigned long long)ave_time_us / 1000);
1213
1214 //
1215 // TxQueue dequeue stats
1216 //
1217 dprintf(
1218 fd,
1219 " Dequeue deviation counts (overdue/premature) : %zu / %zu\n",
1220 dequeue_stats->overdue_scheduling_count,
1221 dequeue_stats->premature_scheduling_count);
1222
1223 ave_time_us = 0;
1224 if (dequeue_stats->overdue_scheduling_count != 0) {
1225 ave_time_us = dequeue_stats->total_overdue_scheduling_delta_us /
1226 dequeue_stats->overdue_scheduling_count;
1227 }
1228 dprintf(
1229 fd,
1230 " Dequeue overdue scheduling time in ms (total/max/ave) : %llu / %llu "
1231 "/ %llu\n",
1232 (unsigned long long)dequeue_stats->total_overdue_scheduling_delta_us /
1233 1000,
1234 (unsigned long long)dequeue_stats->max_overdue_scheduling_delta_us / 1000,
1235 (unsigned long long)ave_time_us / 1000);
1236
1237 ave_time_us = 0;
1238 if (dequeue_stats->premature_scheduling_count != 0) {
1239 ave_time_us = dequeue_stats->total_premature_scheduling_delta_us /
1240 dequeue_stats->premature_scheduling_count;
1241 }
1242 dprintf(
1243 fd,
1244 " Dequeue premature scheduling time in ms (total/max/ave) : %llu / %llu "
1245 "/ %llu\n",
1246 (unsigned long long)dequeue_stats->total_premature_scheduling_delta_us /
1247 1000,
1248 (unsigned long long)dequeue_stats->max_premature_scheduling_delta_us /
1249 1000,
1250 (unsigned long long)ave_time_us / 1000);
1251 }
1252
btif_a2dp_source_update_metrics(void)1253 static void btif_a2dp_source_update_metrics(void) {
1254 BtifMediaStats stats = btif_a2dp_source_cb.stats;
1255 SchedulingStats enqueue_stats = stats.tx_queue_enqueue_stats;
1256 A2dpSessionMetrics metrics;
1257 metrics.codec_index = stats.codec_index;
1258 metrics.is_a2dp_offload = btif_av_is_a2dp_offload_enabled();
1259 // session_start_us is 0 when btif_a2dp_source_start_audio_req() is not called
1260 // mark the metric duration as invalid (-1) in this case
1261 if (stats.session_start_us != 0) {
1262 int64_t session_end_us = stats.session_end_us == 0
1263 ? bluetooth::common::time_get_os_boottime_us()
1264 : stats.session_end_us;
1265 if (static_cast<uint64_t>(session_end_us) > stats.session_start_us) {
1266 metrics.audio_duration_ms =
1267 (session_end_us - stats.session_start_us) / 1000;
1268 }
1269 }
1270
1271 if (enqueue_stats.total_updates > 1) {
1272 metrics.media_timer_min_ms =
1273 btif_a2dp_source_cb.encoder_interval_ms -
1274 (enqueue_stats.max_premature_scheduling_delta_us / 1000);
1275 metrics.media_timer_max_ms =
1276 btif_a2dp_source_cb.encoder_interval_ms +
1277 (enqueue_stats.max_overdue_scheduling_delta_us / 1000);
1278
1279 metrics.total_scheduling_count = enqueue_stats.overdue_scheduling_count +
1280 enqueue_stats.premature_scheduling_count +
1281 enqueue_stats.exact_scheduling_count;
1282 if (metrics.total_scheduling_count > 0) {
1283 metrics.media_timer_avg_ms = enqueue_stats.total_scheduling_time_us /
1284 (1000 * metrics.total_scheduling_count);
1285 }
1286
1287 metrics.buffer_overruns_max_count = stats.tx_queue_max_dropped_messages;
1288 metrics.buffer_overruns_total = stats.tx_queue_total_dropped_messages;
1289 metrics.buffer_underruns_count = stats.media_read_total_underflow_count;
1290 metrics.buffer_underruns_average = 0;
1291 if (metrics.buffer_underruns_count > 0) {
1292 metrics.buffer_underruns_average =
1293 stats.media_read_total_underflow_bytes /
1294 metrics.buffer_underruns_count;
1295 }
1296 }
1297 BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics);
1298 }
1299
btm_read_rssi_cb(void * data)1300 static void btm_read_rssi_cb(void* data) {
1301 if (data == nullptr) {
1302 LOG_ERROR(LOG_TAG, "%s: Read RSSI request timed out", __func__);
1303 return;
1304 }
1305
1306 tBTM_RSSI_RESULT* result = (tBTM_RSSI_RESULT*)data;
1307 if (result->status != BTM_SUCCESS) {
1308 LOG_ERROR(LOG_TAG, "%s: unable to read remote RSSI (status %d)", __func__,
1309 result->status);
1310 return;
1311 }
1312 bluetooth::common::LogReadRssiResult(
1313 result->rem_bda, bluetooth::common::kUnknownConnectionHandle,
1314 result->hci_status, result->rssi);
1315
1316 LOG_WARN(LOG_TAG, "%s: device: %s, rssi: %d", __func__,
1317 result->rem_bda.ToString().c_str(), result->rssi);
1318 }
1319
btm_read_failed_contact_counter_cb(void * data)1320 static void btm_read_failed_contact_counter_cb(void* data) {
1321 if (data == nullptr) {
1322 LOG_ERROR(LOG_TAG, "%s: Read Failed Contact Counter request timed out",
1323 __func__);
1324 return;
1325 }
1326
1327 tBTM_FAILED_CONTACT_COUNTER_RESULT* result =
1328 (tBTM_FAILED_CONTACT_COUNTER_RESULT*)data;
1329 if (result->status != BTM_SUCCESS) {
1330 LOG_ERROR(LOG_TAG, "%s: unable to read Failed Contact Counter (status %d)",
1331 __func__, result->status);
1332 return;
1333 }
1334 bluetooth::common::LogReadFailedContactCounterResult(
1335 result->rem_bda, bluetooth::common::kUnknownConnectionHandle,
1336 result->hci_status, result->failed_contact_counter);
1337
1338 LOG_WARN(LOG_TAG, "%s: device: %s, Failed Contact Counter: %u", __func__,
1339 result->rem_bda.ToString().c_str(), result->failed_contact_counter);
1340 }
1341
btm_read_automatic_flush_timeout_cb(void * data)1342 static void btm_read_automatic_flush_timeout_cb(void* data) {
1343 if (data == nullptr) {
1344 LOG_ERROR(LOG_TAG, "%s: Read Automatic Flush Timeout request timed out",
1345 __func__);
1346 return;
1347 }
1348
1349 tBTM_AUTOMATIC_FLUSH_TIMEOUT_RESULT* result =
1350 (tBTM_AUTOMATIC_FLUSH_TIMEOUT_RESULT*)data;
1351 if (result->status != BTM_SUCCESS) {
1352 LOG_ERROR(LOG_TAG, "%s: unable to read Automatic Flush Timeout (status %d)",
1353 __func__, result->status);
1354 return;
1355 }
1356
1357 LOG_WARN(LOG_TAG, "%s: device: %s, Automatic Flush Timeout: %u", __func__,
1358 result->rem_bda.ToString().c_str(), result->automatic_flush_timeout);
1359 }
1360
btm_read_tx_power_cb(void * data)1361 static void btm_read_tx_power_cb(void* data) {
1362 if (data == nullptr) {
1363 LOG_ERROR(LOG_TAG, "%s: Read Tx Power request timed out", __func__);
1364 return;
1365 }
1366
1367 tBTM_TX_POWER_RESULT* result = (tBTM_TX_POWER_RESULT*)data;
1368 if (result->status != BTM_SUCCESS) {
1369 LOG_ERROR(LOG_TAG, "%s: unable to read Tx Power (status %d)", __func__,
1370 result->status);
1371 return;
1372 }
1373 bluetooth::common::LogReadTxPowerLevelResult(
1374 result->rem_bda, bluetooth::common::kUnknownConnectionHandle,
1375 result->hci_status, result->tx_power);
1376
1377 LOG_WARN(LOG_TAG, "%s: device: %s, Tx Power: %d", __func__,
1378 result->rem_bda.ToString().c_str(), result->tx_power);
1379 }
1380