CRAS: audio_thread - Log when input stream overruns

Fix cras_shm_check_write_overrun() function in detecting when
unread data is overwritten, and return the result so audio
thread can ATLOG this problem.

BUG=chromium:662886
TEST=Use 'cras_test_client --capture_file /tmp/1' and hit
'p','enter' a few times to emulate a bad client. Check audio
dump to veriy there's AUDIO_OVERRUN logged.

Change-Id: Ib5b90ce05d957487b29639dffbbe3067ab5f6915
Reviewed-on: https://chromium-review.googlesource.com/412428
Commit-Ready: Nicolas Boichat <drinkcat@chromium.org>
Tested-by: Hsinyu Chao <hychao@chromium.org>
Reviewed-by: Dylan Reid <dgreid@chromium.org>

5 files changed, 46 insertions, 6 deletions

diff --git a/cras/src/common/cras_shm.h b/cras/src/common/cras_shm.h
index 849c368a..a81106ed 100644
--- a/cras/src/common/cras_shm.h
+++ b/cras/src/common/cras_shm.h
@@ -258,23 +258,27 @@ size_t cras_shm_get_num_writeable(const struct cras_audio_shm *shm)
 	return shm->config.used_size / shm->config.frame_bytes;
 }
 
-/* Flags an overrun if writing would cause one. */
-static inline void cras_shm_check_write_overrun(struct cras_audio_shm *shm)
+/* Flags an overrun if writing would cause one and reset the write offset.
+ * Return 1 if overrun happens, otherwise return 0. */
+static inline int cras_shm_check_write_overrun(struct cras_audio_shm *shm)
 {
+	int ret = 0;
 	size_t write_buf_idx = shm->area->write_buf_idx & CRAS_SHM_BUFFERS_MASK;
-	size_t read_buf_idx = shm->area->read_buf_idx & CRAS_SHM_BUFFERS_MASK;
 
 	if (!shm->area->write_in_progress[write_buf_idx]) {
 		unsigned int used_size = shm->config.used_size;
 
-		if (write_buf_idx != read_buf_idx)
+		if (shm->area->write_offset[write_buf_idx]) {
 			shm->area->num_overruns++; /* Will over-write unread */
+			ret = 1;
+		}
 
 		memset(cras_shm_buff_for_idx(shm, write_buf_idx), 0, used_size);
 
 		shm->area->write_in_progress[write_buf_idx] = 1;
 		shm->area->write_offset[write_buf_idx] = 0;
 	}
+	return ret;
 }
 
 /* Increment the write pointer for the current buffer. */
diff --git a/cras/src/common/cras_types.h b/cras/src/common/cras_types.h
index 4c074ad8..2321b6cb 100644
--- a/cras/src/common/cras_types.h
+++ b/cras/src/common/cras_types.h
@@ -156,6 +156,7 @@ enum AUDIO_THREAD_LOG_EVENTS {
 	AUDIO_THREAD_READ_AUDIO,
 	AUDIO_THREAD_READ_AUDIO_TSTAMP,
 	AUDIO_THREAD_READ_AUDIO_DONE,
+	AUDIO_THREAD_READ_OVERRUN,
 	AUDIO_THREAD_FILL_AUDIO,
 	AUDIO_THREAD_FILL_AUDIO_TSTAMP,
 	AUDIO_THREAD_FILL_AUDIO_DONE,
diff --git a/cras/src/server/audio_thread.c b/cras/src/server/audio_thread.c
index a84e82a3..f45f45a4 100644
--- a/cras/src/server/audio_thread.c
+++ b/cras/src/server/audio_thread.c
@@ -1253,7 +1253,10 @@ static unsigned int get_stream_limit_set_delay(struct open_dev *adev,
 		rstream = stream->stream;
 
 		shm = cras_rstream_input_shm(rstream);
-		cras_shm_check_write_overrun(shm);
+		if (cras_shm_check_write_overrun(shm))
+			ATLOG(atlog, AUDIO_THREAD_READ_OVERRUN,
+			      adev->dev->info.idx, rstream->stream_id,
+			      shm->area->num_overruns);
 		dev_stream_set_delay(stream, delay);
 		avail = dev_stream_capture_avail(stream);
 		write_limit = MIN(write_limit, avail);
diff --git a/cras/src/tests/cras_test_client.c b/cras/src/tests/cras_test_client.c
index 983a42f5..4e69ff5f 100644
--- a/cras/src/tests/cras_test_client.c
+++ b/cras/src/tests/cras_test_client.c
@@ -416,6 +416,10 @@ static void show_alog_tag(const struct audio_thread_event_log *log,
 	case AUDIO_THREAD_READ_AUDIO_DONE:
 		printf("%-30s read_remainder:%u\n", "READ_AUDIO_DONE", data1);
 		break;
+	case AUDIO_THREAD_READ_OVERRUN:
+		printf("%-30s dev:%x stream:%x num_overruns:%u\n",
+		       "READ_AUDIO_OVERRUN", data1, data2, data3);
+		break;
 	case AUDIO_THREAD_FILL_AUDIO:
 		printf("%-30s dev:%x hw_level:%u\n",
 		       "FILL_AUDIO", data1, data2);
diff --git a/cras/src/tests/shm_unittest.cc b/cras/src/tests/shm_unittest.cc
index e1bdc7dc..c0bec890 100644
--- a/cras/src/tests/shm_unittest.cc
+++ b/cras/src/tests/shm_unittest.cc
@@ -17,7 +17,8 @@ class ShmTestSuite : public testing::Test{
     virtual void SetUp() {
       memset(&shm_, 0, sizeof(shm_));
       shm_.area =
-          static_cast<cras_audio_shm_area *>(calloc(1, sizeof(*shm_.area)));
+          static_cast<cras_audio_shm_area *>(
+              calloc(1, sizeof(*shm_.area) + 2048));
       cras_shm_set_frame_bytes(&shm_, 4);
       cras_shm_set_used_size(&shm_, 1024);
       memcpy(&shm_.area->config, &shm_.config, sizeof(shm_.config));
@@ -223,6 +224,33 @@ TEST_F(ShmTestSuite, InvalidReadAndWriteOffset) {
   EXPECT_EQ(shm_.config.used_size / 4, frames_);
 }
 
+TEST_F(ShmTestSuite, InputBufferOverrun) {
+  int rc;
+  shm_.area->write_offset[0] = 0;
+  shm_.area->read_offset[0] = 0;
+  shm_.area->write_offset[1] = 0;
+  shm_.area->read_offset[1] = 0;
+
+  shm_.area->write_buf_idx = 0;
+  shm_.area->read_buf_idx = 0;
+
+  EXPECT_EQ(0, cras_shm_num_overruns(&shm_));
+  rc = cras_shm_check_write_overrun(&shm_);
+  EXPECT_EQ(0, rc);
+  cras_shm_buffer_written(&shm_, 100);
+  cras_shm_buffer_write_complete(&shm_);
+
+  rc = cras_shm_check_write_overrun(&shm_);
+  EXPECT_EQ(0, rc);
+  cras_shm_buffer_written(&shm_, 100);
+  cras_shm_buffer_write_complete(&shm_);
+
+  // Assert two consecutive writes causes overrun.
+  rc = cras_shm_check_write_overrun(&shm_);
+  EXPECT_EQ(1, rc);
+  EXPECT_EQ(1, cras_shm_num_overruns(&shm_));
+}
+
 }  //  namespace
 
 int main(int argc, char **argv) {