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