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