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