1 /******************************************************************************
2 *
3 * Copyright (C) 2016 The Android Open Source Project
4 * Copyright (C) 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
22 #include <base/logging.h>
23 #include <limits.h>
24 #include <string.h>
25 #include <algorithm>
26
27 #include "audio_a2dp_hw/include/audio_a2dp_hw.h"
28 #include "bt_common.h"
29 #include "bta_av_ci.h"
30 #include "btcore/include/bdaddr.h"
31 #include "btif_a2dp.h"
32 #include "btif_a2dp_control.h"
33 #include "btif_a2dp_source.h"
34 #include "btif_av.h"
35 #include "btif_av_co.h"
36 #include "btif_util.h"
37 #include "osi/include/fixed_queue.h"
38 #include "osi/include/log.h"
39 #include "osi/include/metrics.h"
40 #include "osi/include/mutex.h"
41 #include "osi/include/osi.h"
42 #include "osi/include/thread.h"
43 #include "osi/include/time.h"
44 #include "uipc.h"
45
46 using system_bt_osi::BluetoothMetricsLogger;
47 using system_bt_osi::A2dpSessionMetrics;
48
49 /**
50 * The typical runlevel of the tx queue size is ~1 buffer
51 * but due to link flow control or thread preemption in lower
52 * layers we might need to temporarily buffer up data.
53 */
54 #define MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ (MAX_PCM_FRAME_NUM_PER_TICK * 2)
55
56 enum {
57 BTIF_A2DP_SOURCE_STATE_OFF,
58 BTIF_A2DP_SOURCE_STATE_STARTING_UP,
59 BTIF_A2DP_SOURCE_STATE_RUNNING,
60 BTIF_A2DP_SOURCE_STATE_SHUTTING_DOWN
61 };
62
63 /* BTIF Media Source event definition */
64 enum {
65 BTIF_MEDIA_AUDIO_TX_START = 1,
66 BTIF_MEDIA_AUDIO_TX_STOP,
67 BTIF_MEDIA_AUDIO_TX_FLUSH,
68 BTIF_MEDIA_SOURCE_ENCODER_INIT,
69 BTIF_MEDIA_SOURCE_ENCODER_USER_CONFIG_UPDATE,
70 BTIF_MEDIA_AUDIO_FEEDING_UPDATE
71 };
72
73 /* tBTIF_A2DP_SOURCE_ENCODER_INIT msg structure */
74 typedef struct {
75 BT_HDR hdr;
76 tA2DP_ENCODER_INIT_PEER_PARAMS peer_params;
77 } tBTIF_A2DP_SOURCE_ENCODER_INIT;
78
79 /* tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE msg structure */
80 typedef struct {
81 BT_HDR hdr;
82 btav_a2dp_codec_config_t user_config;
83 } tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE;
84
85 /* tBTIF_A2DP_AUDIO_FEEDING_UPDATE msg structure */
86 typedef struct {
87 BT_HDR hdr;
88 btav_a2dp_codec_config_t feeding_params;
89 } tBTIF_A2DP_AUDIO_FEEDING_UPDATE;
90
91 typedef struct {
92 // Counter for total updates
93 size_t total_updates;
94
95 // Last update timestamp (in us)
96 uint64_t last_update_us;
97
98 // Counter for overdue scheduling
99 size_t overdue_scheduling_count;
100
101 // Accumulated overdue scheduling deviations (in us)
102 uint64_t total_overdue_scheduling_delta_us;
103
104 // Max. overdue scheduling delta time (in us)
105 uint64_t max_overdue_scheduling_delta_us;
106
107 // Counter for premature scheduling
108 size_t premature_scheduling_count;
109
110 // Accumulated premature scheduling deviations (in us)
111 uint64_t total_premature_scheduling_delta_us;
112
113 // Max. premature scheduling delta time (in us)
114 uint64_t max_premature_scheduling_delta_us;
115
116 // Counter for exact scheduling
117 size_t exact_scheduling_count;
118
119 // Accumulated and counted scheduling time (in us)
120 uint64_t total_scheduling_time_us;
121 } scheduling_stats_t;
122
123 typedef struct {
124 uint64_t session_start_us;
125 uint64_t session_end_us;
126
127 scheduling_stats_t tx_queue_enqueue_stats;
128 scheduling_stats_t tx_queue_dequeue_stats;
129
130 size_t tx_queue_total_frames;
131 size_t tx_queue_max_frames_per_packet;
132
133 uint64_t tx_queue_total_queueing_time_us;
134 uint64_t tx_queue_max_queueing_time_us;
135
136 size_t tx_queue_total_readbuf_calls;
137 uint64_t tx_queue_last_readbuf_us;
138
139 size_t tx_queue_total_flushed_messages;
140 uint64_t tx_queue_last_flushed_us;
141
142 size_t tx_queue_total_dropped_messages;
143 size_t tx_queue_max_dropped_messages;
144 size_t tx_queue_dropouts;
145 uint64_t tx_queue_last_dropouts_us;
146
147 size_t media_read_total_underflow_bytes;
148 size_t media_read_total_underflow_count;
149 uint64_t media_read_last_underflow_us;
150 } btif_media_stats_t;
151
152 typedef struct {
153 thread_t* worker_thread;
154 fixed_queue_t* cmd_msg_queue;
155 fixed_queue_t* tx_audio_queue;
156 bool tx_flush; /* Discards any outgoing data when true */
157 alarm_t* media_alarm;
158 const tA2DP_ENCODER_INTERFACE* encoder_interface;
159 period_ms_t encoder_interval_ms; /* Local copy of the encoder interval */
160 btif_media_stats_t stats;
161 btif_media_stats_t accumulated_stats;
162 } tBTIF_A2DP_SOURCE_CB;
163
164 static tBTIF_A2DP_SOURCE_CB btif_a2dp_source_cb;
165 static int btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_OFF;
166
167 static void btif_a2dp_source_command_ready(fixed_queue_t* queue, void* context);
168 static void btif_a2dp_source_startup_delayed(void* context);
169 static void btif_a2dp_source_shutdown_delayed(void* context);
170 static void btif_a2dp_source_audio_tx_start_event(void);
171 static void btif_a2dp_source_audio_tx_stop_event(void);
172 static void btif_a2dp_source_audio_tx_flush_event(BT_HDR* p_msg);
173 static void btif_a2dp_source_encoder_init_event(BT_HDR* p_msg);
174 static void btif_a2dp_source_encoder_user_config_update_event(BT_HDR* p_msg);
175 static void btif_a2dp_source_audio_feeding_update_event(BT_HDR* p_msg);
176 static void btif_a2dp_source_encoder_init(void);
177 static void btif_a2dp_source_encoder_init_req(
178 tBTIF_A2DP_SOURCE_ENCODER_INIT* p_msg);
179 static bool btif_a2dp_source_audio_tx_flush_req(void);
180 static void btif_a2dp_source_alarm_cb(void* context);
181 static void btif_a2dp_source_audio_handle_timer(void* context);
182 static uint32_t btif_a2dp_source_read_callback(uint8_t* p_buf, uint32_t len);
183 static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n);
184 static void log_tstamps_us(const char* comment, uint64_t timestamp_us);
185 static void update_scheduling_stats(scheduling_stats_t* stats, uint64_t now_us,
186 uint64_t expected_delta);
187 static void btm_read_rssi_cb(void* data);
188
dump_media_event(uint16_t event)189 UNUSED_ATTR static const char* dump_media_event(uint16_t event) {
190 switch (event) {
191 CASE_RETURN_STR(BTIF_MEDIA_AUDIO_TX_START)
192 CASE_RETURN_STR(BTIF_MEDIA_AUDIO_TX_STOP)
193 CASE_RETURN_STR(BTIF_MEDIA_AUDIO_TX_FLUSH)
194 CASE_RETURN_STR(BTIF_MEDIA_SOURCE_ENCODER_INIT)
195 CASE_RETURN_STR(BTIF_MEDIA_SOURCE_ENCODER_USER_CONFIG_UPDATE)
196 CASE_RETURN_STR(BTIF_MEDIA_AUDIO_FEEDING_UPDATE)
197 default:
198 break;
199 }
200 return "UNKNOWN A2DP SOURCE EVENT";
201 }
202
btif_a2dp_source_accumulate_scheduling_stats(scheduling_stats_t * src,scheduling_stats_t * dst)203 void btif_a2dp_source_accumulate_scheduling_stats(scheduling_stats_t* src,
204 scheduling_stats_t* dst) {
205 dst->total_updates += src->total_updates;
206 dst->last_update_us = src->last_update_us;
207 dst->overdue_scheduling_count += src->overdue_scheduling_count;
208 dst->total_overdue_scheduling_delta_us +=
209 src->total_overdue_scheduling_delta_us;
210 dst->max_overdue_scheduling_delta_us =
211 std::max(dst->max_overdue_scheduling_delta_us,
212 src->max_overdue_scheduling_delta_us);
213 dst->premature_scheduling_count += src->premature_scheduling_count;
214 dst->total_premature_scheduling_delta_us +=
215 src->total_premature_scheduling_delta_us;
216 dst->max_premature_scheduling_delta_us =
217 std::max(dst->max_premature_scheduling_delta_us,
218 src->max_premature_scheduling_delta_us);
219 dst->exact_scheduling_count += src->exact_scheduling_count;
220 dst->total_scheduling_time_us += src->total_scheduling_time_us;
221 }
222
btif_a2dp_source_accumulate_stats(btif_media_stats_t * src,btif_media_stats_t * dst)223 void btif_a2dp_source_accumulate_stats(btif_media_stats_t* src,
224 btif_media_stats_t* dst) {
225 dst->tx_queue_total_frames += src->tx_queue_total_frames;
226 dst->tx_queue_max_frames_per_packet = std::max(
227 dst->tx_queue_max_frames_per_packet, src->tx_queue_max_frames_per_packet);
228 dst->tx_queue_total_queueing_time_us += src->tx_queue_total_queueing_time_us;
229 dst->tx_queue_max_queueing_time_us = std::max(
230 dst->tx_queue_max_queueing_time_us, src->tx_queue_max_queueing_time_us);
231 dst->tx_queue_total_readbuf_calls += src->tx_queue_total_readbuf_calls;
232 dst->tx_queue_last_readbuf_us = src->tx_queue_last_readbuf_us;
233 dst->tx_queue_total_flushed_messages += src->tx_queue_total_flushed_messages;
234 dst->tx_queue_last_flushed_us = src->tx_queue_last_flushed_us;
235 dst->tx_queue_total_dropped_messages += src->tx_queue_total_dropped_messages;
236 dst->tx_queue_max_dropped_messages = std::max(
237 dst->tx_queue_max_dropped_messages, src->tx_queue_max_dropped_messages);
238 dst->tx_queue_dropouts += src->tx_queue_dropouts;
239 dst->tx_queue_last_dropouts_us = src->tx_queue_last_dropouts_us;
240 dst->media_read_total_underflow_bytes +=
241 src->media_read_total_underflow_bytes;
242 dst->media_read_total_underflow_count +=
243 src->media_read_total_underflow_count;
244 dst->media_read_last_underflow_us = src->media_read_last_underflow_us;
245 btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_enqueue_stats,
246 &dst->tx_queue_enqueue_stats);
247 btif_a2dp_source_accumulate_scheduling_stats(&src->tx_queue_dequeue_stats,
248 &dst->tx_queue_dequeue_stats);
249 memset(src, 0, sizeof(btif_media_stats_t));
250 }
251
btif_a2dp_source_startup(void)252 bool btif_a2dp_source_startup(void) {
253 if (btif_a2dp_source_state != BTIF_A2DP_SOURCE_STATE_OFF) {
254 APPL_TRACE_ERROR("%s: A2DP Source media task already running", __func__);
255 return false;
256 }
257
258 memset(&btif_a2dp_source_cb, 0, sizeof(btif_a2dp_source_cb));
259 btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_STARTING_UP;
260
261 APPL_TRACE_EVENT("## A2DP SOURCE START MEDIA THREAD ##");
262
263 /* Start A2DP Source media task */
264 btif_a2dp_source_cb.worker_thread =
265 thread_new("btif_a2dp_source_worker_thread");
266 if (btif_a2dp_source_cb.worker_thread == NULL) {
267 APPL_TRACE_ERROR("%s: unable to start up media thread", __func__);
268 btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_OFF;
269 return false;
270 }
271
272 btif_a2dp_source_cb.tx_audio_queue = fixed_queue_new(SIZE_MAX);
273
274 btif_a2dp_source_cb.cmd_msg_queue = fixed_queue_new(SIZE_MAX);
275 fixed_queue_register_dequeue(
276 btif_a2dp_source_cb.cmd_msg_queue,
277 thread_get_reactor(btif_a2dp_source_cb.worker_thread),
278 btif_a2dp_source_command_ready, NULL);
279
280 APPL_TRACE_EVENT("## A2DP SOURCE MEDIA THREAD STARTED ##");
281
282 /* Schedule the rest of the startup operations */
283 thread_post(btif_a2dp_source_cb.worker_thread,
284 btif_a2dp_source_startup_delayed, NULL);
285
286 return true;
287 }
288
btif_a2dp_source_startup_delayed(UNUSED_ATTR void * context)289 static void btif_a2dp_source_startup_delayed(UNUSED_ATTR void* context) {
290 raise_priority_a2dp(TASK_HIGH_MEDIA);
291 btif_a2dp_control_init();
292 btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_RUNNING;
293 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionStart(
294 system_bt_osi::CONNECTION_TECHNOLOGY_TYPE_BREDR, 0);
295 }
296
btif_a2dp_source_shutdown(void)297 void btif_a2dp_source_shutdown(void) {
298 if ((btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_OFF) ||
299 (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_SHUTTING_DOWN)) {
300 return;
301 }
302
303 /* Make sure no channels are restarted while shutting down */
304 btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_SHUTTING_DOWN;
305
306 APPL_TRACE_EVENT("## A2DP SOURCE STOP MEDIA THREAD ##");
307
308 // Stop the timer
309 alarm_free(btif_a2dp_source_cb.media_alarm);
310 btif_a2dp_source_cb.media_alarm = NULL;
311
312 // Exit the thread
313 fixed_queue_free(btif_a2dp_source_cb.cmd_msg_queue, NULL);
314 btif_a2dp_source_cb.cmd_msg_queue = NULL;
315 thread_post(btif_a2dp_source_cb.worker_thread,
316 btif_a2dp_source_shutdown_delayed, NULL);
317 thread_free(btif_a2dp_source_cb.worker_thread);
318 btif_a2dp_source_cb.worker_thread = NULL;
319 }
320
btif_a2dp_source_shutdown_delayed(UNUSED_ATTR void * context)321 static void btif_a2dp_source_shutdown_delayed(UNUSED_ATTR void* context) {
322 btif_a2dp_control_cleanup();
323 fixed_queue_free(btif_a2dp_source_cb.tx_audio_queue, NULL);
324 btif_a2dp_source_cb.tx_audio_queue = NULL;
325
326 btif_a2dp_source_state = BTIF_A2DP_SOURCE_STATE_OFF;
327 BluetoothMetricsLogger::GetInstance()->LogBluetoothSessionEnd(
328 system_bt_osi::DISCONNECT_REASON_UNKNOWN, 0);
329 }
330
btif_a2dp_source_media_task_is_running(void)331 bool btif_a2dp_source_media_task_is_running(void) {
332 return (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_RUNNING);
333 }
334
btif_a2dp_source_media_task_is_shutting_down(void)335 bool btif_a2dp_source_media_task_is_shutting_down(void) {
336 return (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_SHUTTING_DOWN);
337 }
338
btif_a2dp_source_is_streaming(void)339 bool btif_a2dp_source_is_streaming(void) {
340 return alarm_is_scheduled(btif_a2dp_source_cb.media_alarm);
341 }
342
btif_a2dp_source_command_ready(fixed_queue_t * queue,UNUSED_ATTR void * context)343 static void btif_a2dp_source_command_ready(fixed_queue_t* queue,
344 UNUSED_ATTR void* context) {
345 BT_HDR* p_msg = (BT_HDR*)fixed_queue_dequeue(queue);
346
347 LOG_VERBOSE(LOG_TAG, "%s: event %d %s", __func__, p_msg->event,
348 dump_media_event(p_msg->event));
349
350 switch (p_msg->event) {
351 case BTIF_MEDIA_AUDIO_TX_START:
352 btif_a2dp_source_audio_tx_start_event();
353 break;
354 case BTIF_MEDIA_AUDIO_TX_STOP:
355 btif_a2dp_source_audio_tx_stop_event();
356 break;
357 case BTIF_MEDIA_AUDIO_TX_FLUSH:
358 btif_a2dp_source_audio_tx_flush_event(p_msg);
359 break;
360 case BTIF_MEDIA_SOURCE_ENCODER_INIT:
361 btif_a2dp_source_encoder_init_event(p_msg);
362 break;
363 case BTIF_MEDIA_SOURCE_ENCODER_USER_CONFIG_UPDATE:
364 btif_a2dp_source_encoder_user_config_update_event(p_msg);
365 break;
366 case BTIF_MEDIA_AUDIO_FEEDING_UPDATE:
367 btif_a2dp_source_audio_feeding_update_event(p_msg);
368 break;
369 default:
370 APPL_TRACE_ERROR("ERROR in %s unknown event %d", __func__, p_msg->event);
371 break;
372 }
373
374 osi_free(p_msg);
375 LOG_VERBOSE(LOG_TAG, "%s: %s DONE", __func__, dump_media_event(p_msg->event));
376 }
377
btif_a2dp_source_setup_codec(void)378 void btif_a2dp_source_setup_codec(void) {
379 APPL_TRACE_EVENT("## A2DP SOURCE SETUP CODEC ##");
380
381 mutex_global_lock();
382
383 /* Init the encoding task */
384 btif_a2dp_source_encoder_init();
385
386 mutex_global_unlock();
387 }
388
btif_a2dp_source_start_audio_req(void)389 void btif_a2dp_source_start_audio_req(void) {
390 BT_HDR* p_buf = (BT_HDR*)osi_malloc(sizeof(BT_HDR));
391
392 p_buf->event = BTIF_MEDIA_AUDIO_TX_START;
393 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
394 memset(&btif_a2dp_source_cb.stats, 0, sizeof(btif_media_stats_t));
395 // Assign session_start_us to 1 when time_get_os_boottime_us() is 0 to
396 // indicate btif_a2dp_source_start_audio_req() has been called
397 btif_a2dp_source_cb.stats.session_start_us = time_get_os_boottime_us();
398 if (btif_a2dp_source_cb.stats.session_start_us == 0) {
399 btif_a2dp_source_cb.stats.session_start_us = 1;
400 }
401 btif_a2dp_source_cb.stats.session_end_us = 0;
402 }
403
btif_a2dp_source_stop_audio_req(void)404 void btif_a2dp_source_stop_audio_req(void) {
405 BT_HDR* p_buf = (BT_HDR*)osi_malloc(sizeof(BT_HDR));
406
407 p_buf->event = BTIF_MEDIA_AUDIO_TX_STOP;
408
409 /*
410 * Explicitly check whether btif_a2dp_source_cb.cmd_msg_queue is not NULL
411 * to avoid a race condition during shutdown of the Bluetooth stack.
412 * This race condition is triggered when A2DP audio is streaming on
413 * shutdown:
414 * "btif_a2dp_source_on_stopped() -> btif_a2dp_source_stop_audio_req()"
415 * is called to stop the particular audio stream, and this happens right
416 * after the "BTIF_AV_CLEANUP_REQ_EVT -> btif_a2dp_source_shutdown()"
417 * processing during the shutdown of the Bluetooth stack.
418 */
419 if (btif_a2dp_source_cb.cmd_msg_queue != NULL) {
420 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
421 }
422 btif_a2dp_source_cb.stats.session_end_us = time_get_os_boottime_us();
423 btif_a2dp_source_update_metrics();
424 btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats,
425 &btif_a2dp_source_cb.accumulated_stats);
426 }
427
btif_a2dp_source_encoder_init(void)428 static void btif_a2dp_source_encoder_init(void) {
429 tBTIF_A2DP_SOURCE_ENCODER_INIT msg;
430
431 // Check to make sure the platform has 8 bits/byte since
432 // we're using that in frame size calculations now.
433 CHECK(CHAR_BIT == 8);
434
435 APPL_TRACE_DEBUG("%s", __func__);
436
437 bta_av_co_get_peer_params(&msg.peer_params);
438 btif_a2dp_source_encoder_init_req(&msg);
439 }
440
btif_a2dp_source_encoder_init_req(tBTIF_A2DP_SOURCE_ENCODER_INIT * p_msg)441 static void btif_a2dp_source_encoder_init_req(
442 tBTIF_A2DP_SOURCE_ENCODER_INIT* p_msg) {
443 tBTIF_A2DP_SOURCE_ENCODER_INIT* p_buf =
444 (tBTIF_A2DP_SOURCE_ENCODER_INIT*)osi_malloc(
445 sizeof(tBTIF_A2DP_SOURCE_ENCODER_INIT));
446
447 memcpy(p_buf, p_msg, sizeof(tBTIF_A2DP_SOURCE_ENCODER_INIT));
448 p_buf->hdr.event = BTIF_MEDIA_SOURCE_ENCODER_INIT;
449 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
450 }
451
btif_a2dp_source_encoder_init_event(BT_HDR * p_msg)452 static void btif_a2dp_source_encoder_init_event(BT_HDR* p_msg) {
453 tBTIF_A2DP_SOURCE_ENCODER_INIT* p_encoder_init =
454 (tBTIF_A2DP_SOURCE_ENCODER_INIT*)p_msg;
455
456 APPL_TRACE_DEBUG("%s", __func__);
457
458 btif_a2dp_source_cb.encoder_interface = bta_av_co_get_encoder_interface();
459 if (btif_a2dp_source_cb.encoder_interface == NULL) {
460 APPL_TRACE_ERROR("%s: Cannot stream audio: no source encoder interface",
461 __func__);
462 return;
463 }
464
465 A2dpCodecConfig* a2dp_codec_config = bta_av_get_a2dp_current_codec();
466 if (a2dp_codec_config == nullptr) {
467 APPL_TRACE_ERROR("%s: Cannot stream audio: current codec is not set",
468 __func__);
469 return;
470 }
471
472 btif_a2dp_source_cb.encoder_interface->encoder_init(
473 &p_encoder_init->peer_params, a2dp_codec_config,
474 btif_a2dp_source_read_callback, btif_a2dp_source_enqueue_callback);
475
476 // Save a local copy of the encoder_interval_ms
477 btif_a2dp_source_cb.encoder_interval_ms =
478 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms();
479 }
480
btif_a2dp_source_encoder_user_config_update_req(const btav_a2dp_codec_config_t & codec_user_config)481 void btif_a2dp_source_encoder_user_config_update_req(
482 const btav_a2dp_codec_config_t& codec_user_config) {
483 tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE* p_buf =
484 (tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE*)osi_malloc(
485 sizeof(tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE));
486
487 p_buf->user_config = codec_user_config;
488 p_buf->hdr.event = BTIF_MEDIA_SOURCE_ENCODER_USER_CONFIG_UPDATE;
489 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
490 }
491
btif_a2dp_source_encoder_user_config_update_event(BT_HDR * p_msg)492 static void btif_a2dp_source_encoder_user_config_update_event(BT_HDR* p_msg) {
493 tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE* p_user_config =
494 (tBTIF_A2DP_SOURCE_ENCODER_USER_CONFIG_UPDATE*)p_msg;
495
496 APPL_TRACE_DEBUG("%s", __func__);
497 if (!bta_av_co_set_codec_user_config(p_user_config->user_config)) {
498 APPL_TRACE_ERROR("%s: cannot update codec user configuration", __func__);
499 }
500 }
501
btif_a2dp_source_feeding_update_req(const btav_a2dp_codec_config_t & codec_audio_config)502 void btif_a2dp_source_feeding_update_req(
503 const btav_a2dp_codec_config_t& codec_audio_config) {
504 tBTIF_A2DP_AUDIO_FEEDING_UPDATE* p_buf =
505 (tBTIF_A2DP_AUDIO_FEEDING_UPDATE*)osi_malloc(
506 sizeof(tBTIF_A2DP_AUDIO_FEEDING_UPDATE));
507
508 p_buf->feeding_params = codec_audio_config;
509 p_buf->hdr.event = BTIF_MEDIA_AUDIO_FEEDING_UPDATE;
510 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
511 }
512
btif_a2dp_source_audio_feeding_update_event(BT_HDR * p_msg)513 static void btif_a2dp_source_audio_feeding_update_event(BT_HDR* p_msg) {
514 tBTIF_A2DP_AUDIO_FEEDING_UPDATE* p_feeding =
515 (tBTIF_A2DP_AUDIO_FEEDING_UPDATE*)p_msg;
516
517 APPL_TRACE_DEBUG("%s", __func__);
518 if (!bta_av_co_set_codec_audio_config(p_feeding->feeding_params)) {
519 APPL_TRACE_ERROR("%s: cannot update codec audio feeding parameters",
520 __func__);
521 }
522 }
523
btif_a2dp_source_on_idle(void)524 void btif_a2dp_source_on_idle(void) {
525 if (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_OFF) return;
526
527 /* Make sure media task is stopped */
528 btif_a2dp_source_stop_audio_req();
529 }
530
btif_a2dp_source_on_stopped(tBTA_AV_SUSPEND * p_av_suspend)531 void btif_a2dp_source_on_stopped(tBTA_AV_SUSPEND* p_av_suspend) {
532 APPL_TRACE_EVENT("## ON A2DP SOURCE STOPPED ##");
533
534 if (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_OFF) return;
535
536 /* allow using this api for other than suspend */
537 if (p_av_suspend != NULL) {
538 if (p_av_suspend->status != BTA_AV_SUCCESS) {
539 APPL_TRACE_EVENT("AV STOP FAILED (%d)", p_av_suspend->status);
540 if (p_av_suspend->initiator) {
541 APPL_TRACE_WARNING("%s: A2DP stop request failed: status = %d",
542 __func__, p_av_suspend->status);
543 btif_a2dp_command_ack(A2DP_CTRL_ACK_FAILURE);
544 }
545 return;
546 }
547 }
548
549 /* ensure tx frames are immediately suspended */
550 btif_a2dp_source_cb.tx_flush = true;
551
552 /* request to stop media task */
553 btif_a2dp_source_audio_tx_flush_req();
554 btif_a2dp_source_stop_audio_req();
555
556 /* once stream is fully stopped we will ack back */
557 }
558
btif_a2dp_source_on_suspended(tBTA_AV_SUSPEND * p_av_suspend)559 void btif_a2dp_source_on_suspended(tBTA_AV_SUSPEND* p_av_suspend) {
560 APPL_TRACE_EVENT("## ON A2DP SOURCE SUSPENDED ##");
561
562 if (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_OFF) return;
563
564 /* check for status failures */
565 if (p_av_suspend->status != BTA_AV_SUCCESS) {
566 if (p_av_suspend->initiator) {
567 APPL_TRACE_WARNING("%s: A2DP suspend request failed: status = %d",
568 __func__, p_av_suspend->status);
569 btif_a2dp_command_ack(A2DP_CTRL_ACK_FAILURE);
570 }
571 }
572
573 /* once stream is fully stopped we will ack back */
574
575 /* ensure tx frames are immediately flushed */
576 btif_a2dp_source_cb.tx_flush = true;
577
578 /* stop timer tick */
579 btif_a2dp_source_stop_audio_req();
580 }
581
582 /* when true media task discards any tx frames */
btif_a2dp_source_set_tx_flush(bool enable)583 void btif_a2dp_source_set_tx_flush(bool enable) {
584 APPL_TRACE_EVENT("## DROP TX %d ##", enable);
585 btif_a2dp_source_cb.tx_flush = enable;
586 }
587
btif_a2dp_source_audio_tx_start_event(void)588 static void btif_a2dp_source_audio_tx_start_event(void) {
589 APPL_TRACE_DEBUG(
590 "%s media_alarm is %srunning, streaming %s", __func__,
591 alarm_is_scheduled(btif_a2dp_source_cb.media_alarm) ? "" : "not ",
592 btif_a2dp_source_is_streaming() ? "true" : "false");
593
594 /* Reset the media feeding state */
595 CHECK(btif_a2dp_source_cb.encoder_interface != NULL);
596 btif_a2dp_source_cb.encoder_interface->feeding_reset();
597
598 APPL_TRACE_EVENT(
599 "starting timer %dms",
600 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms());
601
602 alarm_free(btif_a2dp_source_cb.media_alarm);
603 btif_a2dp_source_cb.media_alarm =
604 alarm_new_periodic("btif.a2dp_source_media_alarm");
605 if (btif_a2dp_source_cb.media_alarm == NULL) {
606 LOG_ERROR(LOG_TAG, "%s unable to allocate media alarm", __func__);
607 return;
608 }
609
610 alarm_set(btif_a2dp_source_cb.media_alarm,
611 btif_a2dp_source_cb.encoder_interface->get_encoder_interval_ms(),
612 btif_a2dp_source_alarm_cb, NULL);
613 }
614
btif_a2dp_source_audio_tx_stop_event(void)615 static void btif_a2dp_source_audio_tx_stop_event(void) {
616 APPL_TRACE_DEBUG(
617 "%s media_alarm is %srunning, streaming %s", __func__,
618 alarm_is_scheduled(btif_a2dp_source_cb.media_alarm) ? "" : "not ",
619 btif_a2dp_source_is_streaming() ? "true" : "false");
620
621 const bool send_ack = btif_a2dp_source_is_streaming();
622
623 /* Stop the timer first */
624 alarm_free(btif_a2dp_source_cb.media_alarm);
625 btif_a2dp_source_cb.media_alarm = NULL;
626
627 UIPC_Close(UIPC_CH_ID_AV_AUDIO);
628
629 /*
630 * Try to send acknowldegment once the media stream is
631 * stopped. This will make sure that the A2DP HAL layer is
632 * un-blocked on wait for acknowledgment for the sent command.
633 * This resolves a corner cases AVDTP SUSPEND collision
634 * when the DUT and the remote device issue SUSPEND simultaneously
635 * and due to the processing of the SUSPEND request from the remote,
636 * the media path is torn down. If the A2DP HAL happens to wait
637 * for ACK for the initiated SUSPEND, it would never receive it casuing
638 * a block/wait. Due to this acknowledgement, the A2DP HAL is guranteed
639 * to get the ACK for any pending command in such cases.
640 */
641
642 if (send_ack) btif_a2dp_command_ack(A2DP_CTRL_ACK_SUCCESS);
643
644 /* audio engine stopped, reset tx suspended flag */
645 btif_a2dp_source_cb.tx_flush = false;
646
647 /* Reset the media feeding state */
648 if (btif_a2dp_source_cb.encoder_interface != NULL)
649 btif_a2dp_source_cb.encoder_interface->feeding_reset();
650 }
651
btif_a2dp_source_alarm_cb(UNUSED_ATTR void * context)652 static void btif_a2dp_source_alarm_cb(UNUSED_ATTR void* context) {
653 thread_post(btif_a2dp_source_cb.worker_thread,
654 btif_a2dp_source_audio_handle_timer, NULL);
655 }
656
btif_a2dp_source_audio_handle_timer(UNUSED_ATTR void * context)657 static void btif_a2dp_source_audio_handle_timer(UNUSED_ATTR void* context) {
658 uint64_t timestamp_us = time_get_os_boottime_us();
659 log_tstamps_us("A2DP Source tx timer", timestamp_us);
660
661 if (alarm_is_scheduled(btif_a2dp_source_cb.media_alarm)) {
662 CHECK(btif_a2dp_source_cb.encoder_interface != NULL);
663 if (btif_a2dp_source_cb.encoder_interface->set_transmit_queue_length !=
664 NULL) {
665 size_t transmit_queue_length =
666 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
667 btif_a2dp_source_cb.encoder_interface->set_transmit_queue_length(
668 transmit_queue_length);
669 }
670 btif_a2dp_source_cb.encoder_interface->send_frames(timestamp_us);
671 bta_av_ci_src_data_ready(BTA_AV_CHNL_AUDIO);
672 update_scheduling_stats(&btif_a2dp_source_cb.stats.tx_queue_enqueue_stats,
673 timestamp_us,
674 btif_a2dp_source_cb.encoder_interval_ms * 1000);
675 } else {
676 APPL_TRACE_ERROR("ERROR Media task Scheduled after Suspend");
677 }
678 }
679
btif_a2dp_source_read_callback(uint8_t * p_buf,uint32_t len)680 static uint32_t btif_a2dp_source_read_callback(uint8_t* p_buf, uint32_t len) {
681 uint16_t event;
682 uint32_t bytes_read = UIPC_Read(UIPC_CH_ID_AV_AUDIO, &event, p_buf, len);
683
684 if (bytes_read < len) {
685 LOG_WARN(LOG_TAG, "%s: UNDERFLOW: ONLY READ %d BYTES OUT OF %d", __func__,
686 bytes_read, len);
687 btif_a2dp_source_cb.stats.media_read_total_underflow_bytes +=
688 (len - bytes_read);
689 btif_a2dp_source_cb.stats.media_read_total_underflow_count++;
690 btif_a2dp_source_cb.stats.media_read_last_underflow_us =
691 time_get_os_boottime_us();
692 }
693
694 return bytes_read;
695 }
696
btif_a2dp_source_enqueue_callback(BT_HDR * p_buf,size_t frames_n)697 static bool btif_a2dp_source_enqueue_callback(BT_HDR* p_buf, size_t frames_n) {
698 uint64_t now_us = time_get_os_boottime_us();
699
700 /* Check if timer was stopped (media task stopped) */
701 if (!alarm_is_scheduled(btif_a2dp_source_cb.media_alarm)) {
702 osi_free(p_buf);
703 return false;
704 }
705
706 /* Check if the transmission queue has been flushed */
707 if (btif_a2dp_source_cb.tx_flush) {
708 LOG_VERBOSE(LOG_TAG, "%s: tx suspended, discarded frame", __func__);
709
710 btif_a2dp_source_cb.stats.tx_queue_total_flushed_messages +=
711 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
712 btif_a2dp_source_cb.stats.tx_queue_last_flushed_us = now_us;
713 fixed_queue_flush(btif_a2dp_source_cb.tx_audio_queue, osi_free);
714
715 osi_free(p_buf);
716 return false;
717 }
718
719 // Check for TX queue overflow
720 // TODO: Using frames_n here is probably wrong: should be "+ 1" instead.
721 if (fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue) + frames_n >
722 MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ) {
723 LOG_WARN(LOG_TAG, "%s: TX queue buffer size now=%u adding=%u max=%d",
724 __func__,
725 (uint32_t)fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue),
726 (uint32_t)frames_n, MAX_OUTPUT_A2DP_FRAME_QUEUE_SZ);
727 // Keep track of drop-outs
728 btif_a2dp_source_cb.stats.tx_queue_dropouts++;
729 btif_a2dp_source_cb.stats.tx_queue_last_dropouts_us = now_us;
730
731 // Flush all queued buffers
732 size_t drop_n = fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
733 btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages = std::max(
734 drop_n, btif_a2dp_source_cb.stats.tx_queue_max_dropped_messages);
735 while (fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue)) {
736 btif_a2dp_source_cb.stats.tx_queue_total_dropped_messages++;
737 osi_free(fixed_queue_try_dequeue(btif_a2dp_source_cb.tx_audio_queue));
738 }
739
740 // Request RSSI for log purposes if we had to flush buffers
741 bt_bdaddr_t peer_bda = btif_av_get_addr();
742 BTM_ReadRSSI(peer_bda.address, btm_read_rssi_cb);
743 }
744
745 /* Update the statistics */
746 btif_a2dp_source_cb.stats.tx_queue_total_frames += frames_n;
747 btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet = std::max(
748 frames_n, btif_a2dp_source_cb.stats.tx_queue_max_frames_per_packet);
749 CHECK(btif_a2dp_source_cb.encoder_interface != NULL);
750
751 fixed_queue_enqueue(btif_a2dp_source_cb.tx_audio_queue, p_buf);
752
753 return true;
754 }
755
btif_a2dp_source_audio_tx_flush_event(UNUSED_ATTR BT_HDR * p_msg)756 static void btif_a2dp_source_audio_tx_flush_event(UNUSED_ATTR BT_HDR* p_msg) {
757 /* Flush all enqueued audio buffers (encoded) */
758 APPL_TRACE_DEBUG("%s", __func__);
759
760 if (btif_a2dp_source_cb.encoder_interface != NULL)
761 btif_a2dp_source_cb.encoder_interface->feeding_flush();
762
763 btif_a2dp_source_cb.stats.tx_queue_total_flushed_messages +=
764 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue);
765 btif_a2dp_source_cb.stats.tx_queue_last_flushed_us =
766 time_get_os_boottime_us();
767 fixed_queue_flush(btif_a2dp_source_cb.tx_audio_queue, osi_free);
768
769 UIPC_Ioctl(UIPC_CH_ID_AV_AUDIO, UIPC_REQ_RX_FLUSH, NULL);
770 }
771
btif_a2dp_source_audio_tx_flush_req(void)772 static bool btif_a2dp_source_audio_tx_flush_req(void) {
773 BT_HDR* p_buf = (BT_HDR*)osi_malloc(sizeof(BT_HDR));
774
775 p_buf->event = BTIF_MEDIA_AUDIO_TX_FLUSH;
776
777 /*
778 * Explicitly check whether the btif_a2dp_source_cb.cmd_msg_queue is not
779 * NULL to avoid a race condition during shutdown of the Bluetooth stack.
780 * This race condition is triggered when A2DP audio is streaming on
781 * shutdown:
782 * "btif_a2dp_source_on_stopped() -> btif_a2dp_source_audio_tx_flush_req()"
783 * is called to stop the particular audio stream, and this happens right
784 * after the "BTIF_AV_CLEANUP_REQ_EVT -> btif_a2dp_source_shutdown()"
785 * processing during the shutdown of the Bluetooth stack.
786 */
787 if (btif_a2dp_source_cb.cmd_msg_queue != NULL)
788 fixed_queue_enqueue(btif_a2dp_source_cb.cmd_msg_queue, p_buf);
789
790 return true;
791 }
792
btif_a2dp_source_audio_readbuf(void)793 BT_HDR* btif_a2dp_source_audio_readbuf(void) {
794 uint64_t now_us = time_get_os_boottime_us();
795 BT_HDR* p_buf =
796 (BT_HDR*)fixed_queue_try_dequeue(btif_a2dp_source_cb.tx_audio_queue);
797
798 btif_a2dp_source_cb.stats.tx_queue_total_readbuf_calls++;
799 btif_a2dp_source_cb.stats.tx_queue_last_readbuf_us = now_us;
800 if (p_buf != NULL) {
801 // Update the statistics
802 update_scheduling_stats(&btif_a2dp_source_cb.stats.tx_queue_dequeue_stats,
803 now_us,
804 btif_a2dp_source_cb.encoder_interval_ms * 1000);
805 }
806
807 return p_buf;
808 }
809
log_tstamps_us(const char * comment,uint64_t timestamp_us)810 static void log_tstamps_us(const char* comment, uint64_t timestamp_us) {
811 static uint64_t prev_us = 0;
812 APPL_TRACE_DEBUG("[%s] ts %08llu, diff : %08llu, queue sz %d", comment,
813 timestamp_us, timestamp_us - prev_us,
814 fixed_queue_length(btif_a2dp_source_cb.tx_audio_queue));
815 prev_us = timestamp_us;
816 }
817
update_scheduling_stats(scheduling_stats_t * stats,uint64_t now_us,uint64_t expected_delta)818 static void update_scheduling_stats(scheduling_stats_t* stats, uint64_t now_us,
819 uint64_t expected_delta) {
820 uint64_t last_us = stats->last_update_us;
821
822 stats->total_updates++;
823 stats->last_update_us = now_us;
824
825 if (last_us == 0) return; // First update: expected delta doesn't apply
826
827 uint64_t deadline_us = last_us + expected_delta;
828 if (deadline_us < now_us) {
829 // Overdue scheduling
830 uint64_t delta_us = now_us - deadline_us;
831 // Ignore extreme outliers
832 if (delta_us < 10 * expected_delta) {
833 stats->max_overdue_scheduling_delta_us =
834 std::max(delta_us, stats->max_overdue_scheduling_delta_us);
835 stats->total_overdue_scheduling_delta_us += delta_us;
836 stats->overdue_scheduling_count++;
837 stats->total_scheduling_time_us += now_us - last_us;
838 }
839 } else if (deadline_us > now_us) {
840 // Premature scheduling
841 uint64_t delta_us = deadline_us - now_us;
842 // Ignore extreme outliers
843 if (delta_us < 10 * expected_delta) {
844 stats->max_premature_scheduling_delta_us =
845 std::max(delta_us, stats->max_premature_scheduling_delta_us);
846 stats->total_premature_scheduling_delta_us += delta_us;
847 stats->premature_scheduling_count++;
848 stats->total_scheduling_time_us += now_us - last_us;
849 }
850 } else {
851 // On-time scheduling
852 stats->exact_scheduling_count++;
853 stats->total_scheduling_time_us += now_us - last_us;
854 }
855 }
856
btif_a2dp_source_debug_dump(int fd)857 void btif_a2dp_source_debug_dump(int fd) {
858 btif_a2dp_source_accumulate_stats(&btif_a2dp_source_cb.stats,
859 &btif_a2dp_source_cb.accumulated_stats);
860 uint64_t now_us = time_get_os_boottime_us();
861 btif_media_stats_t* accumulated_stats =
862 &btif_a2dp_source_cb.accumulated_stats;
863 scheduling_stats_t* enqueue_stats =
864 &accumulated_stats->tx_queue_enqueue_stats;
865 scheduling_stats_t* dequeue_stats =
866 &accumulated_stats->tx_queue_dequeue_stats;
867 size_t ave_size;
868 uint64_t ave_time_us;
869
870 dprintf(fd, "\nA2DP State:\n");
871 dprintf(fd, " TxQueue:\n");
872
873 dprintf(fd,
874 " Counts (enqueue/dequeue/readbuf) : %zu / "
875 "%zu / %zu\n",
876 enqueue_stats->total_updates, dequeue_stats->total_updates,
877 accumulated_stats->tx_queue_total_readbuf_calls);
878
879 dprintf(
880 fd,
881 " Last update time ago in ms (enqueue/dequeue/readbuf) : %llu / %llu "
882 "/ %llu\n",
883 (enqueue_stats->last_update_us > 0)
884 ? (unsigned long long)(now_us - enqueue_stats->last_update_us) / 1000
885 : 0,
886 (dequeue_stats->last_update_us > 0)
887 ? (unsigned long long)(now_us - dequeue_stats->last_update_us) / 1000
888 : 0,
889 (accumulated_stats->tx_queue_last_readbuf_us > 0)
890 ? (unsigned long long)(now_us -
891 accumulated_stats->tx_queue_last_readbuf_us) /
892 1000
893 : 0);
894
895 ave_size = 0;
896 if (enqueue_stats->total_updates != 0)
897 ave_size =
898 accumulated_stats->tx_queue_total_frames / enqueue_stats->total_updates;
899 dprintf(fd,
900 " Frames per packet (total/max/ave) : %zu / "
901 "%zu / %zu\n",
902 accumulated_stats->tx_queue_total_frames,
903 accumulated_stats->tx_queue_max_frames_per_packet, ave_size);
904
905 dprintf(fd,
906 " Counts (flushed/dropped/dropouts) : %zu / "
907 "%zu / %zu\n",
908 accumulated_stats->tx_queue_total_flushed_messages,
909 accumulated_stats->tx_queue_total_dropped_messages,
910 accumulated_stats->tx_queue_dropouts);
911
912 dprintf(fd,
913 " Counts (max dropped) : %zu\n",
914 accumulated_stats->tx_queue_max_dropped_messages);
915
916 dprintf(
917 fd,
918 " Last update time ago in ms (flushed/dropped) : %llu / "
919 "%llu\n",
920 (accumulated_stats->tx_queue_last_flushed_us > 0)
921 ? (unsigned long long)(now_us -
922 accumulated_stats->tx_queue_last_flushed_us) /
923 1000
924 : 0,
925 (accumulated_stats->tx_queue_last_dropouts_us > 0)
926 ? (unsigned long long)(now_us -
927 accumulated_stats->tx_queue_last_dropouts_us) /
928 1000
929 : 0);
930
931 dprintf(fd,
932 " Counts (underflow) : %zu\n",
933 accumulated_stats->media_read_total_underflow_count);
934
935 dprintf(fd,
936 " Bytes (underflow) : %zu\n",
937 accumulated_stats->media_read_total_underflow_bytes);
938
939 dprintf(fd,
940 " Last update time ago in ms (underflow) : %llu\n",
941 (accumulated_stats->media_read_last_underflow_us > 0)
942 ? (unsigned long long)(now_us -
943 accumulated_stats
944 ->media_read_last_underflow_us) /
945 1000
946 : 0);
947
948 //
949 // TxQueue enqueue stats
950 //
951 dprintf(
952 fd,
953 " Enqueue deviation counts (overdue/premature) : %zu / %zu\n",
954 enqueue_stats->overdue_scheduling_count,
955 enqueue_stats->premature_scheduling_count);
956
957 ave_time_us = 0;
958 if (enqueue_stats->overdue_scheduling_count != 0) {
959 ave_time_us = enqueue_stats->total_overdue_scheduling_delta_us /
960 enqueue_stats->overdue_scheduling_count;
961 }
962 dprintf(
963 fd,
964 " Enqueue overdue scheduling time in ms (total/max/ave) : %llu / %llu "
965 "/ %llu\n",
966 (unsigned long long)enqueue_stats->total_overdue_scheduling_delta_us /
967 1000,
968 (unsigned long long)enqueue_stats->max_overdue_scheduling_delta_us / 1000,
969 (unsigned long long)ave_time_us / 1000);
970
971 ave_time_us = 0;
972 if (enqueue_stats->premature_scheduling_count != 0) {
973 ave_time_us = enqueue_stats->total_premature_scheduling_delta_us /
974 enqueue_stats->premature_scheduling_count;
975 }
976 dprintf(
977 fd,
978 " Enqueue premature scheduling time in ms (total/max/ave) : %llu / %llu "
979 "/ %llu\n",
980 (unsigned long long)enqueue_stats->total_premature_scheduling_delta_us /
981 1000,
982 (unsigned long long)enqueue_stats->max_premature_scheduling_delta_us /
983 1000,
984 (unsigned long long)ave_time_us / 1000);
985
986 //
987 // TxQueue dequeue stats
988 //
989 dprintf(
990 fd,
991 " Dequeue deviation counts (overdue/premature) : %zu / %zu\n",
992 dequeue_stats->overdue_scheduling_count,
993 dequeue_stats->premature_scheduling_count);
994
995 ave_time_us = 0;
996 if (dequeue_stats->overdue_scheduling_count != 0) {
997 ave_time_us = dequeue_stats->total_overdue_scheduling_delta_us /
998 dequeue_stats->overdue_scheduling_count;
999 }
1000 dprintf(
1001 fd,
1002 " Dequeue overdue scheduling time in ms (total/max/ave) : %llu / %llu "
1003 "/ %llu\n",
1004 (unsigned long long)dequeue_stats->total_overdue_scheduling_delta_us /
1005 1000,
1006 (unsigned long long)dequeue_stats->max_overdue_scheduling_delta_us / 1000,
1007 (unsigned long long)ave_time_us / 1000);
1008
1009 ave_time_us = 0;
1010 if (dequeue_stats->premature_scheduling_count != 0) {
1011 ave_time_us = dequeue_stats->total_premature_scheduling_delta_us /
1012 dequeue_stats->premature_scheduling_count;
1013 }
1014 dprintf(
1015 fd,
1016 " Dequeue premature scheduling time in ms (total/max/ave) : %llu / %llu "
1017 "/ %llu\n",
1018 (unsigned long long)dequeue_stats->total_premature_scheduling_delta_us /
1019 1000,
1020 (unsigned long long)dequeue_stats->max_premature_scheduling_delta_us /
1021 1000,
1022 (unsigned long long)ave_time_us / 1000);
1023
1024 //
1025 // Codec-specific stats
1026 //
1027 A2dpCodecs* a2dp_codecs = bta_av_get_a2dp_codecs();
1028 if (a2dp_codecs != nullptr) {
1029 a2dp_codecs->debug_codec_dump(fd);
1030 }
1031 }
1032
btif_a2dp_source_update_metrics(void)1033 void btif_a2dp_source_update_metrics(void) {
1034 btif_media_stats_t* stats = &btif_a2dp_source_cb.stats;
1035 scheduling_stats_t* enqueue_stats = &stats->tx_queue_enqueue_stats;
1036 A2dpSessionMetrics metrics;
1037 // session_start_us is 0 when btif_a2dp_source_start_audio_req() is not called
1038 // mark the metric duration as invalid (-1) in this case
1039 if (stats->session_start_us != 0) {
1040 int64_t session_end_us = stats->session_end_us == 0
1041 ? time_get_os_boottime_us()
1042 : stats->session_end_us;
1043 metrics.audio_duration_ms =
1044 (session_end_us - stats->session_start_us) / 1000;
1045 }
1046
1047 if (enqueue_stats->total_updates > 1) {
1048 metrics.media_timer_min_ms =
1049 btif_a2dp_source_cb.encoder_interval_ms -
1050 (enqueue_stats->max_premature_scheduling_delta_us / 1000);
1051 metrics.media_timer_max_ms =
1052 btif_a2dp_source_cb.encoder_interval_ms +
1053 (enqueue_stats->max_overdue_scheduling_delta_us / 1000);
1054
1055 metrics.total_scheduling_count = enqueue_stats->overdue_scheduling_count +
1056 enqueue_stats->premature_scheduling_count +
1057 enqueue_stats->exact_scheduling_count;
1058 if (metrics.total_scheduling_count > 0) {
1059 metrics.media_timer_avg_ms = enqueue_stats->total_scheduling_time_us /
1060 (1000 * metrics.total_scheduling_count);
1061 }
1062
1063 metrics.buffer_overruns_max_count = stats->tx_queue_max_dropped_messages;
1064 metrics.buffer_overruns_total = stats->tx_queue_total_dropped_messages;
1065 metrics.buffer_underruns_count = stats->media_read_total_underflow_count;
1066 metrics.buffer_underruns_average = 0;
1067 if (metrics.buffer_underruns_count > 0) {
1068 metrics.buffer_underruns_average =
1069 stats->media_read_total_underflow_bytes /
1070 metrics.buffer_underruns_count;
1071 }
1072 }
1073 BluetoothMetricsLogger::GetInstance()->LogA2dpSession(metrics);
1074 }
1075
btm_read_rssi_cb(void * data)1076 static void btm_read_rssi_cb(void* data) {
1077 if (data == nullptr) {
1078 LOG_ERROR(LOG_TAG, "%s RSSI request timed out", __func__);
1079 return;
1080 }
1081
1082 tBTM_RSSI_RESULTS* result = (tBTM_RSSI_RESULTS*)data;
1083 if (result->status != BTM_SUCCESS) {
1084 LOG_ERROR(LOG_TAG, "%s unable to read remote RSSI (status %d)", __func__,
1085 result->status);
1086 return;
1087 }
1088
1089 char temp_buffer[20] = {0};
1090 LOG_WARN(LOG_TAG, "%s device: %s, rssi: %d", __func__,
1091 bdaddr_to_string((bt_bdaddr_t*)result->rem_bda, temp_buffer,
1092 sizeof(temp_buffer)),
1093 result->rssi);
1094 }
1095