CRAS: cras_server_metrics - Log the fetch delay clearly

This change does:
1. Move the position of logging fetch delay from the audio thread to the
main thread.
2. Logs the longest fetch delay for each client type and stream type.
e.g. We will be able to see
Cras.StreamTimeoutMilliSeconds.Chrome.VoiceCommunication

BUG=b:177185438
TEST=Verified the UMA is logged correcly in chrome://histograms

Change-Id: I67b4181a0799f73e4f32cdddf5deb33cc6b264ea
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/adhd/+/2620904
Reviewed-by: Cheng-Yi Chiang <cychiang@chromium.org>
Tested-by: Yu-Hsuan Hsu <yuhsuan@chromium.org>
Commit-Queue: Yu-Hsuan Hsu <yuhsuan@chromium.org>

4 files changed, 52 insertions, 38 deletions

diff --git a/cras/src/server/cras_server_metrics.c b/cras/src/server/cras_server_metrics.c
index 6def6a37..05d156e9 100644
--- a/cras/src/server/cras_server_metrics.c
+++ b/cras/src/server/cras_server_metrics.c
@@ -698,13 +698,31 @@ int cras_server_metrics_highest_hw_level(unsigned hw_level,
 	return 0;
 }
 
-int cras_server_metrics_longest_fetch_delay(unsigned delay_msec)
+/* Logs longest fetch delay of a stream. */
+int cras_server_metrics_longest_fetch_delay(const struct cras_rstream *stream)
 {
 	struct cras_server_metrics_message msg;
 	union cras_server_metrics_data data;
 	int err;
 
-	data.value = delay_msec;
+	data.stream_data.client_type = stream->client_type;
+	data.stream_data.stream_type = stream->stream_type;
+	data.stream_data.direction = stream->direction;
+
+	/*
+	 * There is no delay when the sleep_interval_ts larger than the
+	 * longest_fetch_interval.
+	 */
+	if (!timespec_after(&stream->longest_fetch_interval,
+			    &stream->sleep_interval_ts)) {
+		data.stream_data.runtime.tv_sec = 0;
+		data.stream_data.runtime.tv_nsec = 0;
+	} else {
+		subtract_timespecs(&stream->longest_fetch_interval,
+				   &stream->sleep_interval_ts,
+				   &data.stream_data.runtime);
+	}
+
 	init_server_metrics_msg(&msg, LONGEST_FETCH_DELAY, data);
 	err = cras_server_metrics_message_send(
 		(struct cras_main_message *)&msg);
@@ -958,7 +976,9 @@ int cras_server_metrics_stream_destroy(const struct cras_rstream *stream)
 	if (rc < 0)
 		return rc;
 	rc = cras_server_metrics_stream_runtime(stream);
-	return rc;
+	if (rc < 0)
+		return rc;
+	return cras_server_metrics_longest_fetch_delay(stream);
 }
 
 int cras_server_metrics_busyloop(struct timespec *ts, unsigned count)
@@ -1028,6 +1048,17 @@ static void metrics_device_volume(struct cras_server_metrics_device_data data)
 	cras_metrics_log_histogram(metrics_name, data.value, 0, 100, 20);
 }
 
+static void
+metrics_longest_fetch_delay(struct cras_server_metrics_stream_data data)
+{
+	int fetch_delay_msec =
+		data.runtime.tv_sec * 1000 + data.runtime.tv_nsec / 1000000;
+	log_sparse_histogram_each_level(
+		3, fetch_delay_msec, kStreamTimeoutMilliSeconds,
+		metrics_client_type_str(data.client_type),
+		metrics_stream_type_str(data.stream_type));
+}
+
 static void metrics_stream_runtime(struct cras_server_metrics_stream_data data)
 {
 	char metrics_name[METRICS_NAME_BUFFER_SIZE];
@@ -1153,9 +1184,7 @@ static void handle_metrics_message(struct cras_main_message *msg, void *arg)
 					   20);
 		break;
 	case LONGEST_FETCH_DELAY:
-		cras_metrics_log_histogram(kStreamTimeoutMilliSeconds,
-					   metrics_msg->data.value, 1, 20000,
-					   10);
+		metrics_longest_fetch_delay(metrics_msg->data.stream_data);
 		break;
 	case MISSED_CB_FIRST_TIME_INPUT:
 		cras_metrics_log_histogram(kMissedCallbackFirstTimeInput,
diff --git a/cras/src/server/cras_server_metrics.h b/cras/src/server/cras_server_metrics.h
index 91f13c3c..90b40d4e 100644
--- a/cras/src/server/cras_server_metrics.h
+++ b/cras/src/server/cras_server_metrics.h
@@ -61,9 +61,6 @@ int cras_server_metrics_highest_device_delay(
 int cras_server_metrics_highest_hw_level(unsigned hw_level,
 					 enum CRAS_STREAM_DIRECTION direction);
 
-/* Logs the longest fetch delay of a stream in millisecond. */
-int cras_server_metrics_longest_fetch_delay(unsigned delay_msec);
-
 /* Logs the number of underruns of a device. */
 int cras_server_metrics_num_underruns(unsigned num_underruns);
 
diff --git a/cras/src/server/dev_io.c b/cras/src/server/dev_io.c
index 42fe9558..aea2244a 100644
--- a/cras/src/server/dev_io.c
+++ b/cras/src/server/dev_io.c
@@ -1418,20 +1418,6 @@ int dev_io_remove_stream(struct open_dev **dev_list,
 			 struct cras_rstream *stream, struct cras_iodev *dev)
 {
 	struct open_dev *open_dev;
-	struct timespec delay;
-	unsigned fetch_delay_msec;
-
-	/* Metrics log the longest fetch delay of this stream. */
-	if (timespec_after(&stream->longest_fetch_interval,
-			   &stream->sleep_interval_ts)) {
-		subtract_timespecs(&stream->longest_fetch_interval,
-				   &stream->sleep_interval_ts, &delay);
-		fetch_delay_msec =
-			delay.tv_sec * 1000 + delay.tv_nsec / 1000000;
-		if (fetch_delay_msec)
-			cras_server_metrics_longest_fetch_delay(
-				fetch_delay_msec);
-	}
 
 	ATLOG(atlog, AUDIO_THREAD_STREAM_REMOVED, stream->stream_id, 0, 0);
 
diff --git a/cras/src/tests/server_metrics_unittest.cc b/cras/src/tests/server_metrics_unittest.cc
index a01e1e0e..e23906ec 100644
--- a/cras/src/tests/server_metrics_unittest.cc
+++ b/cras/src/tests/server_metrics_unittest.cc
@@ -132,20 +132,6 @@ TEST(ServerMetricsTestSuite, SetMetricHighestHardwareLevel) {
   EXPECT_EQ(sent_msgs[0].data.value, hw_level);
 }
 
-TEST(ServerMetricsTestSuite, SetMetricsLongestFetchDelay) {
-  ResetStubData();
-  unsigned int delay = 100;
-
-  cras_server_metrics_longest_fetch_delay(delay);
-
-  EXPECT_EQ(sent_msgs.size(), 1);
-  EXPECT_EQ(sent_msgs[0].header.type, CRAS_MAIN_METRICS);
-  EXPECT_EQ(sent_msgs[0].header.length,
-            sizeof(struct cras_server_metrics_message));
-  EXPECT_EQ(sent_msgs[0].metrics_type, LONGEST_FETCH_DELAY);
-  EXPECT_EQ(sent_msgs[0].data.value, delay);
-}
-
 TEST(ServerMetricsTestSuite, SetMetricsNumUnderruns) {
   ResetStubData();
   unsigned int underrun = 10;
@@ -283,6 +269,10 @@ TEST(ServerMetricsTestSuite, SetMetricsStreamDestroy) {
   stream.num_missed_cb = 5;
   stream.first_missed_cb_ts.tv_sec = 100;
   stream.first_missed_cb_ts.tv_nsec = 0;
+  stream.longest_fetch_interval.tv_sec = 1;
+  stream.longest_fetch_interval.tv_nsec = 0;
+  stream.sleep_interval_ts.tv_sec = 0;
+  stream.sleep_interval_ts.tv_nsec = 5000000;
 
   stream.direction = CRAS_STREAM_INPUT;
   stream.client_type = CRAS_CLIENT_TYPE_TEST;
@@ -290,7 +280,7 @@ TEST(ServerMetricsTestSuite, SetMetricsStreamDestroy) {
   cras_server_metrics_stream_destroy(&stream);
 
   subtract_timespecs(&clock_gettime_retspec, &stream.start_ts, &diff_ts);
-  EXPECT_EQ(sent_msgs.size(), 3);
+  EXPECT_EQ(sent_msgs.size(), 4);
 
   // Log missed cb frequency.
   EXPECT_EQ(sent_msgs[0].header.type, CRAS_MAIN_METRICS);
@@ -321,6 +311,18 @@ TEST(ServerMetricsTestSuite, SetMetricsStreamDestroy) {
             CRAS_STREAM_TYPE_DEFAULT);
   EXPECT_EQ(sent_msgs[2].data.stream_data.direction, CRAS_STREAM_INPUT);
   EXPECT_EQ(sent_msgs[2].data.stream_data.runtime.tv_sec, 1000);
+
+  // Log longest fetch delay.
+  EXPECT_EQ(sent_msgs[3].header.type, CRAS_MAIN_METRICS);
+  EXPECT_EQ(sent_msgs[3].header.length,
+            sizeof(struct cras_server_metrics_message));
+  EXPECT_EQ(sent_msgs[3].metrics_type, LONGEST_FETCH_DELAY);
+  EXPECT_EQ(sent_msgs[3].data.stream_data.client_type, CRAS_CLIENT_TYPE_TEST);
+  EXPECT_EQ(sent_msgs[3].data.stream_data.stream_type,
+            CRAS_STREAM_TYPE_DEFAULT);
+  EXPECT_EQ(sent_msgs[3].data.stream_data.direction, CRAS_STREAM_INPUT);
+  EXPECT_EQ(sent_msgs[3].data.stream_data.runtime.tv_sec, 0);
+  EXPECT_EQ(sent_msgs[3].data.stream_data.runtime.tv_nsec, 995000000);
 }
 
 TEST(ServerMetricsTestSuite, SetMetricsBusyloop) {