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