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