cras: add perfetto logs for hw_level, {write, read}_frames, overrun, …

…underrun

Add perfetto counters:
 * CRAS_SPK_HW_LEVEL,
 * CRAS_FLOOP_OUT_HW_LEVEL,
 * CRAS_INTERNAL_MIC_HW_LEVEL
 * CRAS_FLOOP_IN_HW_LEVEL,
 * CRAS_SPK_WRITE_FRAMES,
 * CRAS_FLOOP_OUT_WRITE_FRAMES,
 * CRAS_FLOOP_IN_READ_FRAMES,
 * CRAS_INTERNAL_MIC_READ_FRAMES

Add perfetto TRACE_INSTANT:
 * ${NODE_TYPE}_UNDERRUN
 * ${NODE_TYPE}_OVERERRUN

It's for debugging floop overrun issue.
It only support logs for One pair of floop device.

BUG=b:362679648
TEST=1. Enable Chrome: Audio and audio category in https://ui.perfetto.dev/
     2. record the perfetto log and verify these log out exists.

Change-Id: I55a7e1d3bce14c98ff65b43c08dad5be0419a03a
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/adhd/+/5859818
Reviewed-by: Curtis Malainey <cujomalainey@chromium.org>
Tested-by: Judy Hsiao <judyhsiao@google.com>
Commit-Queue: Judy Hsiao <judyhsiao@google.com>
Tested-by: chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com <chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com>

cras/server/BUILD.bazel

@@ -59,7 +59,9 @@ cc_library(
         "//cras/src/server:__pkg__",
         "//cras/src/tests:__pkg__",
     ],
-    deps = select({
+    deps = [
+        "//cras/src/common:cras_types",
+    ] + select({
         "@adhd//:system_percetto_build": ["@pkg_config//percetto"],
         "//conditions:default": ["@percetto"],
     }),

cras/server/cras_trace.c

@@ -6,6 +6,78 @@
 
 PERCETTO_CATEGORY_DEFINE(CRAS_PERCETTO_CATEGORIES);
 
+PERCETTO_TRACK_DEFINE(CRAS_SPK_HW_LEVEL, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_FLOOP_OUT_HW_LEVEL, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_INTERNAL_MIC_HW_LEVEL, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_FLOOP_IN_HW_LEVEL, PERCETTO_TRACK_COUNTER);
+
+PERCETTO_TRACK_DEFINE(CRAS_SPK_WRITE_FRAMES, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_FLOOP_OUT_WRITE_FRAMES, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_FLOOP_IN_READ_FRAMES, PERCETTO_TRACK_COUNTER);
+PERCETTO_TRACK_DEFINE(CRAS_INTERNAL_MIC_READ_FRAMES, PERCETTO_TRACK_COUNTER);
+
 int cras_trace_init() {
-  return PERCETTO_INIT(PERCETTO_CLOCK_DONT_CARE);
+  PERCETTO_INIT(PERCETTO_CLOCK_DONT_CARE);
+  PERCETTO_REGISTER_TRACK(CRAS_SPK_HW_LEVEL);
+  PERCETTO_REGISTER_TRACK(CRAS_FLOOP_OUT_HW_LEVEL);
+  PERCETTO_REGISTER_TRACK(CRAS_INTERNAL_MIC_HW_LEVEL);
+  PERCETTO_REGISTER_TRACK(CRAS_FLOOP_IN_HW_LEVEL);
+
+  PERCETTO_REGISTER_TRACK(CRAS_SPK_WRITE_FRAMES);
+  PERCETTO_REGISTER_TRACK(CRAS_FLOOP_OUT_WRITE_FRAMES);
+  PERCETTO_REGISTER_TRACK(CRAS_FLOOP_IN_READ_FRAMES);
+  PERCETTO_REGISTER_TRACK(CRAS_INTERNAL_MIC_READ_FRAMES);
+  return 0;
+}
+
+void cras_trace_hw_level(enum CRAS_NODE_TYPE type, unsigned int hw_level) {
+  switch (type) {
+    case CRAS_NODE_TYPE_INTERNAL_SPEAKER:
+      TRACE_COUNTER(audio, CRAS_SPK_HW_LEVEL, hw_level);
+      break;
+    case CRAS_NODE_TYPE_FLOOP:
+      TRACE_COUNTER(audio, CRAS_FLOOP_IN_HW_LEVEL, hw_level);
+      break;
+    case CRAS_NODE_TYPE_FLOOP_INTERNAL:
+      TRACE_COUNTER(audio, CRAS_FLOOP_OUT_HW_LEVEL, hw_level);
+      break;
+    case CRAS_NODE_TYPE_MIC:
+      TRACE_COUNTER(audio, CRAS_INTERNAL_MIC_HW_LEVEL, hw_level);
+      break;
+    default:
+      break;
+  }
 }
+
+void cras_trace_frames(enum CRAS_NODE_TYPE type, unsigned int nframes) {
+  switch (type) {
+    case CRAS_NODE_TYPE_INTERNAL_SPEAKER:
+      TRACE_COUNTER(audio, CRAS_SPK_WRITE_FRAMES, nframes);
+      break;
+    case CRAS_NODE_TYPE_FLOOP:
+      TRACE_COUNTER(audio, CRAS_FLOOP_OUT_WRITE_FRAMES, nframes);
+      break;
+    case CRAS_NODE_TYPE_MIC:
+      TRACE_COUNTER(audio, CRAS_INTERNAL_MIC_READ_FRAMES, nframes);
+      break;
+    case CRAS_NODE_TYPE_FLOOP_INTERNAL:
+      TRACE_COUNTER(audio, CRAS_FLOOP_IN_READ_FRAMES, nframes);
+      break;
+    default:
+      break;
+  }
+}
+
+void cras_trace_underrun(enum CRAS_NODE_TYPE type,
+                         enum CRAS_NODE_POSITION position) {
+  char event[50];
+  snprintf(event, 50, "%s_UNDERRUN", cras_node_type_to_str(type, position));
+  TRACE_INSTANT(audio, event);
+}
+
+void cras_trace_overrun(enum CRAS_NODE_TYPE type,
+                        enum CRAS_NODE_POSITION position) {
+  char event[50];
+  snprintf(event, 50, "%s_UNDERRUN", cras_node_type_to_str(type, position));
+  TRACE_INSTANT(audio, event);
+}

cras/server/cras_trace.h

@@ -7,6 +7,8 @@
 
 #include <percetto.h>
 
+#include "cras_types.h"
+
 #ifdef __cplusplus
 extern "C" {
 #endif
@@ -15,6 +17,16 @@ extern "C" {
 
 PERCETTO_CATEGORY_DECLARE(CRAS_PERCETTO_CATEGORIES);
 
+PERCETTO_TRACK_DECLARE(CRAS_SPK_HW_LEVEL);
+PERCETTO_TRACK_DECLARE(CRAS_FLOOP_OUT_HW_LEVEL);
+PERCETTO_TRACK_DECLARE(CRAS_INTERNAL_MIC_HW_LEVEL);
+PERCETTO_TRACK_DECLARE(CRAS_FLOOP_IN_HW_LEVEL);
+
+PERCETTO_TRACK_DECLARE(CRAS_SPK_WRITE_FRAMES);
+PERCETTO_TRACK_DECLARE(CRAS_FLOOP_OUT_WRITE_FRAMES);
+PERCETTO_TRACK_DECLARE(CRAS_FLOOP_IN_READ_FRAMES);
+PERCETTO_TRACK_DECLARE(CRAS_INTERNAL_MIC_READ_FRAMES);
+
 // https://github.com/olvaffe/percetto/pull/34
 #ifdef NPERCETTO
 #define TRACE_EVENT_DATA(category, str_name, ...)
@@ -24,6 +36,18 @@ PERCETTO_CATEGORY_DECLARE(CRAS_PERCETTO_CATEGORIES);
 // See PERCETTO_INIT.
 int cras_trace_init();
 
+// Log the hw_level.
+void cras_trace_hw_level(enum CRAS_NODE_TYPE type, unsigned int hw_level);
+
+// Log the nframes write to or read from the hardware buffer.
+void cras_trace_frames(enum CRAS_NODE_TYPE type, unsigned int nframes);
+
+// Log the underrun event.
+void cras_trace_underrun(enum CRAS_NODE_TYPE type, enum CRAS_NODE_POSITION);
+
+// Log the overrun event.
+void cras_trace_overrun(enum CRAS_NODE_TYPE type, enum CRAS_NODE_POSITION);
+
 #ifdef __cplusplus
 }  // extern "C"
 #endif

cras/src/common/BUILD.bazel

@@ -151,6 +151,7 @@ cc_library(
     ],
     visibility = [
         "//cras/benchmark:__pkg__",
+        "//cras/server:__pkg__",
         "//cras/src/dsp:__pkg__",
         "//cras/src/libcras:__pkg__",
         "//cras/src/server:__pkg__",

cras/src/server/cras_alsa_io.c

@@ -21,6 +21,7 @@
 #include <unistd.h>
 
 #include "cras/common/check.h"
+#include "cras/server/cras_trace.h"
 #include "cras/src/common/cras_alsa_card_info.h"
 #include "cras/src/common/cras_log.h"
 #include "cras/src/common/cras_string.h"
@@ -457,6 +458,9 @@ static int get_buffer(struct cras_iodev* iodev,
         syslog(LOG_WARNING, "sample_buf is NULL");
         return -EINVAL;
       }
+      if (iodev->active_node) {
+        cras_trace_frames(iodev->active_node->type, nframes);
+      }
       memcpy(aio->common.sample_buf + iodev->input_dsp_offset * format_bytes,
              aio->common.mmap_buf + iodev->input_dsp_offset * format_bytes,
              (nframes - iodev->input_dsp_offset) * format_bytes);
@@ -488,6 +492,10 @@ static int put_buffer(struct cras_iodev* iodev, unsigned nwritten) {
       return -EINVAL;
     }
 
+    if (iodev->active_node) {
+      cras_trace_frames(iodev->active_node->type, nwritten);
+    }
+
     // Perform the copy byte-by-byte
     size_t total_size = (size_t)nwritten * (size_t)format_bytes;
     char* src = (char*)aio->common.sample_buf;

cras/src/server/cras_floop_iodev.c

@@ -13,6 +13,7 @@
 #include <sys/param.h>
 #include <time.h>
 
+#include "cras/server/cras_trace.h"
 #include "cras/src/common/byte_buffer.h"
 #include "cras/src/server/cras_audio_area.h"
 #include "cras/src/server/cras_iodev.h"
@@ -183,6 +184,9 @@ static int input_put_buffer(struct cras_iodev* iodev, unsigned nframes) {
   struct byte_buffer* buf = floop->buffer;
   unsigned int frame_bytes = cras_get_format_bytes(iodev->format);
 
+  if (iodev->active_node) {
+    cras_trace_frames(iodev->active_node->type, nframes);
+  }
   floop->read_frames += nframes;
   buf_increment_read(buf, (size_t)nframes * (size_t)frame_bytes);
   return 0;
@@ -249,6 +253,10 @@ static int output_put_buffer(struct cras_iodev* iodev, unsigned nframes) {
   struct byte_buffer* buf = floop->buffer;
   size_t frame_bytes = cras_get_format_bytes(iodev->format);
 
+  if (iodev->active_node) {
+    cras_trace_frames(iodev->active_node->type, nframes);
+  }
+
   buf_increment_write(buf, (size_t)nframes * frame_bytes);
   return 0;
 }

cras/src/server/cras_iodev.c

@@ -18,6 +18,7 @@
 #include <time.h>
 
 #include "cras/common/check.h"
+#include "cras/server/cras_trace.h"
 #include "cras/server/platform/features/features.h"
 #include "cras/server/s2/s2.h"
 #include "cras/src/common/cras_hats.h"
@@ -1687,6 +1688,11 @@ int cras_iodev_output_underrun(struct cras_iodev* odev,
                                unsigned int hw_level,
                                unsigned int frames_written) {
   int rc;
+
+  if (odev->active_node) {
+    cras_trace_underrun(odev->active_node->type, odev->active_node->position);
+  }
+
   ATLOG(atlog, AUDIO_THREAD_UNDERRUN, odev->info.idx, hw_level, frames_written);
   odev->num_underruns++;
   if (cras_apm_state_get_num_nc()) {
@@ -2009,6 +2015,11 @@ void cras_iodev_update_highest_hw_level(struct cras_iodev* iodev,
    */
   if (hw_level == iodev->buffer_size &&
       iodev->largest_cb_level * 3 < iodev->buffer_size) {
+    if (iodev->active_node) {
+      cras_trace_overrun(iodev->active_node->type,
+                         iodev->active_node->position);
+    }
+
     ATLOG(atlog, AUDIO_THREAD_DEV_OVERRUN, iodev->info.idx, hw_level, 0);
     // Only log the event when the first time it happens.
     if (iodev->highest_hw_level != hw_level) {

cras/src/server/cras_iodev_list.c

@@ -15,6 +15,7 @@
 #include <time.h>
 
 #include "cras/common/rust_common.h"
+#include "cras/server/cras_trace.h"
 #include "cras/server/platform/features/features.h"
 #include "cras/server/s2/s2.h"
 #include "cras/src/common/cras_hats.h"

cras/src/server/dev_io.c

@@ -562,6 +562,10 @@ static int capture_to_streams(struct open_dev* adev,
 
   cras_iodev_update_highest_hw_level(idev, hw_level);
 
+  if (idev->active_node) {
+    cras_trace_hw_level(idev->active_node->type, hw_level);
+  }
+
   ATLOG(atlog, AUDIO_THREAD_READ_AUDIO_TSTAMP, idev->info.idx, hw_tstamp.tv_sec,
         hw_tstamp.tv_nsec);
   if (timespec_is_nonzero(&hw_tstamp)) {
@@ -994,6 +998,10 @@ int write_output_samples(struct open_dev** odevs,
     }
   }
 
+  if (odev->active_node) {
+    cras_trace_hw_level(odev->active_node->type, hw_level);
+  }
+
   ATLOG(atlog, AUDIO_THREAD_FILL_AUDIO_DONE, hw_level, total_written,
         get_ewma_power_as_int(&odev->ewma));
 

cras/src/tests/BUILD.bazel

@@ -191,6 +191,7 @@ cc_test(
     deps = [
         ":test_support",
         "//cras/common:check",
+        "//cras/server:cras_trace",
         "//cras/server/platform/dlc:cc",
         "//cras/src/common:all_headers",
         "//cras/src/common:cras_log",
@@ -1236,6 +1237,7 @@ cc_test(
     ],
     deps = [
         ":test_support",
+        "//cras/server:cras_trace",
         "//cras/src/common",
         "//cras/src/common:all_headers",
         "//cras/src/server:all_headers",
@@ -1439,6 +1441,7 @@ cc_test(
         ":test_support",
         ":test_util",
         "//cras/common:rust_common_cc",
+        "//cras/server:cras_trace",
         "//cras/server/platform/dlc:cc",
         "//cras/server/s2:cc",
         "//cras/src/common:all_headers",
@@ -1469,6 +1472,7 @@ cc_test(
         ":test_support",
         "//cras/common:check",
         "//cras/common:rust_common_cc",
+        "//cras/server:cras_trace",
         "//cras/server/platform/dlc:cc",
         "//cras/server/platform/features:override",
         "//cras/server/s2:cc",

cras/src/tests/floop_iodev_unittest.cc

@@ -2,9 +2,15 @@
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
 
+// To ensure proper linkage when headers are included in both C and C++ code:
+// 1. Include headers *outside* of any `extern "C"` block.
+// 2. Within headers, use `#ifdef __cplusplus` to enclose function declarations
+//    within an `extern "C"` block. This ensures C++ code sees C linkage,
+//    while C code remains unaffected.
+#include "cras/server/cras_trace.h"
+#include "cras/src/server/cras_iodev.h"
 extern "C" {
 #include "cras/src/server/cras_floop_iodev.c"
-#include "cras/src/server/cras_iodev.h"
 }
 
 #include <gtest/gtest.h>

cras/src/tests/iodev_unittest.cc

@@ -2786,7 +2786,7 @@ TEST(IoDev, AecOnDspUseCaseCheck) {
 }
 
 TEST(IoDev, DeviceOverrun) {
-  struct cras_iodev iodev;
+  struct cras_iodev iodev = {};
 
   iodev.buffer_size = 4096;
   iodev.largest_cb_level = 2048;