CRAS: a2dp - Log A2DP throttle time and severe throttle event

This log in audio thread dump would help observe the schedule time
shift due to failure in A2DP packet consumption by BT controller.

Ideally this THROTTLE time shoud vary in a reasonable range, say
[0, 300ms]. If one observe thie THROTTLE time reaches to 5000ms
then there's a possible bug somewhere.

If the throttle causes schedule miss to reach like seconds high
send an event to main thread so this snapshot can be analyzed
later in --dump_event.

BUG=b:140845724
TEST=cras_test_client --dump_a | grep THROTTLE

Change-Id: I2eb7cd5886767571004f76057c86c5020d3154f3
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/adhd/+/2160231
Tested-by: Hsinyu Chao <hychao@chromium.org>
Commit-Queue: Hsinyu Chao <hychao@chromium.org>
Reviewed-by: Chih-Yang Hsia <paulhsia@chromium.org>

6 files changed, 47 insertions, 1 deletions

diff --git a/cras/src/common/cras_types.h b/cras/src/common/cras_types.h
index 829ff987..b424222f 100644
--- a/cras/src/common/cras_types.h
+++ b/cras/src/common/cras_types.h
@@ -273,6 +273,7 @@ enum AUDIO_THREAD_LOG_EVENTS {
 	AUDIO_THREAD_STREAM_ADDED,
 	AUDIO_THREAD_STREAM_REMOVED,
 	AUDIO_THREAD_A2DP_FLUSH,
+	AUDIO_THREAD_A2DP_THROTTLE_TIME,
 	AUDIO_THREAD_A2DP_WRITE,
 	AUDIO_THREAD_DEV_STREAM_MIX,
 	AUDIO_THREAD_CAPTURE_POST,
@@ -418,6 +419,7 @@ struct __attribute__((__packed__)) cras_bt_debug_info {
  * or they will be ignored by the handler.
  */
 enum CRAS_AUDIO_THREAD_EVENT_TYPE {
+	AUDIO_THREAD_EVENT_A2DP_THROTTLE,
 	AUDIO_THREAD_EVENT_BUSYLOOP,
 	AUDIO_THREAD_EVENT_DEBUG,
 	AUDIO_THREAD_EVENT_SEVERE_UNDERRUN,
diff --git a/cras/src/server/cras_a2dp_iodev.c b/cras/src/server/cras_a2dp_iodev.c
index 20a949dc..ab369782 100644
--- a/cras/src/server/cras_a2dp_iodev.c
+++ b/cras/src/server/cras_a2dp_iodev.c
@@ -20,6 +20,7 @@
 #include "cras_a2dp_info.h"
 #include "cras_a2dp_iodev.h"
 #include "cras_audio_area.h"
+#include "cras_audio_thread_monitor.h"
 #include "cras_bt_device.h"
 #include "cras_iodev.h"
 #include "cras_util.h"
@@ -30,6 +31,16 @@
 #define PCM_BUF_MAX_SIZE_FRAMES (4096 * 4)
 #define PCM_BUF_MAX_SIZE_BYTES (PCM_BUF_MAX_SIZE_FRAMES * 4)
 
+/* Threshold for reasonable a2dp throttle log in audio dump. */
+static const struct timespec throttle_log_threshold = {
+	0, 20000000 /* 20ms */
+};
+
+/* Threshold for severe a2dp throttle event. */
+static const struct timespec throttle_event_threshold = {
+	2, 0 /* 2s */
+};
+
 /* Child of cras_iodev to handle bluetooth A2DP streaming.
  * Members:
  *    base - The cras_iodev structure "base class"
@@ -386,7 +397,7 @@ static int encode_and_flush(const struct cras_iodev *iodev)
 	unsigned int queued_frames;
 	struct a2dp_io *a2dpio;
 	struct cras_bt_device *device;
-	struct timespec now;
+	struct timespec now, ts;
 	static const struct timespec flush_wake_fuzz_ts = {
 		0, 1000000 /* 1ms */
 	};
@@ -419,6 +430,18 @@ do_flush:
 	if (!timespec_after(&now, &a2dpio->next_flush_time))
 		return 0;
 
+	/* If the A2DP write schedule miss exceeds a small threshold, log it for
+	 * debug purpose. */
+	subtract_timespecs(&now, &a2dpio->next_flush_time, &ts);
+	if (timespec_after(&ts, &throttle_log_threshold))
+		ATLOG(atlog, AUDIO_THREAD_A2DP_THROTTLE_TIME, ts.tv_sec,
+		      ts.tv_nsec, bt_local_queued_frames(iodev));
+
+	/* Log an event if the A2DP write schedule miss exceeds a large threshold
+	 * that we consider it as something severe. */
+	if (timespec_after(&ts, &throttle_event_threshold))
+		cras_audio_thread_event_a2dp_throttle();
+
 	written = a2dp_write(&a2dpio->a2dp,
 			     cras_bt_transport_fd(a2dpio->transport),
 			     cras_bt_transport_write_mtu(a2dpio->transport));
diff --git a/cras/src/server/cras_audio_thread_monitor.c b/cras/src/server/cras_audio_thread_monitor.c
index 59212459..c4f3e64e 100644
--- a/cras/src/server/cras_audio_thread_monitor.c
+++ b/cras/src/server/cras_audio_thread_monitor.c
@@ -50,6 +50,11 @@ int cras_audio_thread_event_send(enum CRAS_AUDIO_THREAD_EVENT_TYPE event_type)
 	return cras_main_message_send(&msg.header);
 }
 
+int cras_audio_thread_event_a2dp_throttle()
+{
+	return cras_audio_thread_event_send(AUDIO_THREAD_EVENT_A2DP_THROTTLE);
+}
+
 int cras_audio_thread_event_debug()
 {
 	return cras_audio_thread_event_send(AUDIO_THREAD_EVENT_DEBUG);
diff --git a/cras/src/server/cras_audio_thread_monitor.h b/cras/src/server/cras_audio_thread_monitor.h
index b7355caa..a5390a06 100644
--- a/cras/src/server/cras_audio_thread_monitor.h
+++ b/cras/src/server/cras_audio_thread_monitor.h
@@ -7,6 +7,11 @@
 #define CRAS_AUDIO_THREAD_MONITOR_H_
 
 /*
+ * Notifies the main thread when A2DP packet transmittion throttles.
+ */
+int cras_audio_thread_event_a2dp_throttle();
+
+/*
  * Sends a debug event to the audio thread for debugging.
  */
 int cras_audio_thread_event_debug();
diff --git a/cras/src/tests/a2dp_iodev_unittest.cc b/cras/src/tests/a2dp_iodev_unittest.cc
index 1f6d991f..4ce12df7 100644
--- a/cras/src/tests/a2dp_iodev_unittest.cc
+++ b/cras/src/tests/a2dp_iodev_unittest.cc
@@ -815,3 +815,7 @@ int audio_thread_rm_callback_sync(struct audio_thread* thread, int fd) {
 
 void audio_thread_enable_callback(int fd, int enabled) {}
 }
+
+int cras_audio_thread_event_a2dp_throttle() {
+  return 0;
+}
diff --git a/cras/src/tools/cras_test_client/cras_test_client.c b/cras/src/tools/cras_test_client/cras_test_client.c
index 150eb756..ac3855a6 100644
--- a/cras/src/tools/cras_test_client/cras_test_client.c
+++ b/cras/src/tools/cras_test_client/cras_test_client.c
@@ -583,6 +583,10 @@ static void show_alog_tag(const struct audio_thread_event_log *log,
 		printf("%-30s state %u next flush time:%s.%09u\n", "A2DP_FLUSH",
 		       data1, time_str, nsec);
 		break;
+	case AUDIO_THREAD_A2DP_THROTTLE_TIME:
+		printf("%-30s %u ms, queued:%u\n", "A2DP_THROTTLE_TIME",
+		       data1 * 1000 + data2 / 1000000, data3);
+		break;
 	case AUDIO_THREAD_A2DP_WRITE:
 		printf("%-30s written:%d queued:%u\n", "A2DP_WRITE", data1,
 		       data2);
@@ -954,6 +958,9 @@ static void print_cras_audio_thread_snapshot(
 
 	printf("Event type: ");
 	switch (snapshot->event_type) {
+	case AUDIO_THREAD_EVENT_A2DP_THROTTLE:
+		printf("a2dp throttle\n");
+		break;
 	case AUDIO_THREAD_EVENT_BUSYLOOP:
 		printf("busyloop\n");
 		break;