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