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 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 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 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 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 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 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 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 337 bool btif_a2dp_source_media_task_is_running(void) { 338 return (btif_a2dp_source_state == BTIF_A2DP_SOURCE_STATE_RUNNING); 339 } 340 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 345 bool btif_a2dp_source_is_streaming(void) { 346 return alarm_is_scheduled(btif_a2dp_source_cb.media_alarm); 347 } 348 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 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 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 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 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 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 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 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 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 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 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 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 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 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 */ 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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 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
