cras: dsp_offload: add status recordings

Records DSP offload status by main log and UMA.

BUG=b:188647460
TEST=unittest

Change-Id: Id992e7147336d430525fc26cf238e1c670df58a4
Reviewed-on: https://chromium-review.googlesource.com/c/chromiumos/third_party/adhd/+/5061755
Reviewed-by: Li-Yu Yu <aaronyu@google.com>
Tested-by: chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com <chromeos-cop-builder@chromeos-cop.iam.gserviceaccount.com>
Commit-Queue: Pin-chih Lin <johnylin@chromium.org>
Reviewed-by: Yu-Hsuan Hsu <yuhsuan@chromium.org>
Auto-Submit: Pin-chih Lin <johnylin@chromium.org>

cras/include/cras_types.h

@@ -369,6 +369,8 @@ enum MAIN_THREAD_LOG_EVENTS {
   MAIN_THREAD_SUSPEND_DEVS,
   // When NC-blockage related flags are toggled.
   MAIN_THREAD_NC_BLOCK_STATE,
+  // When an iodev enabling/disabling DSP offload is failed/ok.
+  MAIN_THREAD_DEV_DSP_OFFLOAD,
   // stream related
   // When an audio stream is added.
   MAIN_THREAD_STREAM_ADDED,

cras/src/server/cras_dsp.c

@@ -16,8 +16,12 @@
 #include "cras/src/server/cras_dsp_ini.h"
 #include "cras/src/server/cras_dsp_pipeline.h"
 #include "cras/src/server/cras_expr.h"
+#include "cras/src/server/cras_iodev.h"
+#include "cras/src/server/cras_main_thread_log.h"
+#include "cras/src/server/cras_server_metrics.h"
 #include "cras_audio_format.h"
 #include "cras_iodev_info.h"
+#include "cras_types.h"
 #include "third_party/utlist/utlist.h"
 
 /* We have a dsp_context for each pipeline. The context records the
@@ -134,13 +138,19 @@ static struct pipeline* prepare_pipeline(struct cras_dsp_context* ctx,
  */
 static bool possibly_offload_pipeline(struct dsp_offload_map* offload_map,
                                       struct pipeline* pipe) {
+  bool fallback = false;
   int rc;
 
   if (!offload_map) {
     // The DSP offload doesn't support for the device running this pipeline.
     return false;
   }
 
+  if (!offload_map->parent_dev) {
+    syslog(LOG_ERR, "cras_dsp: invalid parent_dev in offload_map");
+    return false;
+  }
+
   // If supports, check if the DSP offload is applicable, i.e. the pattern for
   // the CRAS pipeline is matched with the offload map. The pipeline can be NULL
   // when the current active node has no DSP config specified, which will be
@@ -173,16 +183,26 @@ static bool possibly_offload_pipeline(struct dsp_offload_map* offload_map,
     rc = cras_dsp_pipeline_config_offload(offload_map, pipe);
     if (rc) {
       syslog(LOG_ERR, "cras_dsp: Failed to config offload blobs, rc: %d", rc);
+      MAINLOG(main_log, MAIN_THREAD_DEV_DSP_OFFLOAD,
+              offload_map->parent_dev->info.idx, 1 /* enable */, 1 /* error */);
+      fallback = true;
       goto disable_offload;  // fallback to process on CRAS
     }
 
     rc = cras_dsp_offload_set_state(offload_map, true);
     if (rc) {
       syslog(LOG_ERR, "cras_dsp: Failed to enable offload, rc: %d", rc);
+      MAINLOG(main_log, MAIN_THREAD_DEV_DSP_OFFLOAD,
+              offload_map->parent_dev->info.idx, 1 /* enable */, 1 /* error */);
+      fallback = true;
       goto disable_offload;  // fallback to process on CRAS
     }
 
     syslog(LOG_DEBUG, "cras_dsp: offload is applied on success.");
+    MAINLOG(main_log, MAIN_THREAD_DEV_DSP_OFFLOAD,
+            offload_map->parent_dev->info.idx, 1 /* enable */, 0 /* ok */);
+    cras_server_metrics_device_dsp_offload_status(
+        offload_map->parent_dev, CRAS_DEVICE_DSP_OFFLOAD_SUCCESS);
     return true;
   }
 
@@ -192,6 +212,22 @@ static bool possibly_offload_pipeline(struct dsp_offload_map* offload_map,
     // TODO(b/188647460): Consider better error handlings e.g. N-time retries,
     //                    report up to CRAS server, and etc.
     syslog(LOG_ERR, "cras_dsp: Failed to disable offload, rc: %d", rc);
+    MAINLOG(main_log, MAIN_THREAD_DEV_DSP_OFFLOAD,
+            offload_map->parent_dev->info.idx, 0 /* disable */, 1 /* error */);
+    if (fallback) {
+      cras_server_metrics_device_dsp_offload_status(
+          offload_map->parent_dev, CRAS_DEVICE_DSP_OFFLOAD_FALLBACK_ERROR);
+    } else {
+      cras_server_metrics_device_dsp_offload_status(
+          offload_map->parent_dev, CRAS_DEVICE_DSP_OFFLOAD_ERROR);
+    }
+  } else {
+    MAINLOG(main_log, MAIN_THREAD_DEV_DSP_OFFLOAD,
+            offload_map->parent_dev->info.idx, 0 /* disable */, 0 /* ok */);
+    if (fallback) {
+      cras_server_metrics_device_dsp_offload_status(
+          offload_map->parent_dev, CRAS_DEVICE_DSP_OFFLOAD_FALLBACK_SUCCESS);
+    }
   }
   return false;
 }

cras/src/server/cras_server_metrics.c

@@ -41,6 +41,7 @@ const char kDeviceVolume[] = "Cras.DeviceVolume";
 const char kDeviceNoiseCancellationStatus[] =
     "Cras.DeviceNoiseCancellationStatus";
 const char kDeviceSampleRate[] = "Cras.DeviceSampleRate";
+const char kDeviceDspOffloadStatus[] = "Cras.DeviceDspOffloadStatus";
 const char kFetchDelayMilliSeconds[] = "Cras.FetchDelayMilliSeconds";
 const char kHighestDeviceDelayInput[] = "Cras.HighestDeviceDelayInput";
 const char kHighestDeviceDelayOutput[] = "Cras.HighestDeviceDelayOutput";
@@ -135,6 +136,7 @@ enum CRAS_SERVER_METRICS_TYPE {
   DEVICE_VOLUME,
   DEVICE_NOISE_CANCELLATION_STATUS,
   DEVICE_SAMPLE_RATE,
+  DEVICE_DSP_OFFLOAD_STATUS,
   DLC_MANAGER_STATUS,
   HIGHEST_DEVICE_DELAY_INPUT,
   HIGHEST_DEVICE_DELAY_OUTPUT,
@@ -1426,6 +1428,27 @@ int cras_server_metrics_device_open_status(struct cras_iodev* iodev,
   return 0;
 }
 
+int cras_server_metrics_device_dsp_offload_status(
+    const struct cras_iodev* iodev,
+    enum CRAS_DEVICE_DSP_OFFLOAD_STATUS code) {
+  struct cras_server_metrics_message msg = CRAS_MAIN_MESSAGE_INIT;
+  union cras_server_metrics_data data;
+  int err;
+
+  data.device_data.type = get_metrics_device_type(iodev);
+  data.device_data.value = code;
+
+  init_server_metrics_msg(&msg, DEVICE_DSP_OFFLOAD_STATUS, data);
+
+  err = cras_server_metrics_message_send((struct cras_main_message*)&msg);
+  if (err < 0) {
+    syslog(LOG_WARNING,
+           "Failed to send metrics message: DEVICE_DSP_OFFLOAD_STATUS");
+    return err;
+  }
+  return 0;
+}
+
 int cras_server_metrics_internal_soundcard_status(bool detected, int sec) {
   int err;
   enum CRAS_SERVER_METRICS_TYPE metric;
@@ -1561,6 +1584,15 @@ static void metrics_device_sample_rate(
       metrics_device_type_str(data.type));
 }
 
+static void metrics_device_dsp_offload_status(
+    struct cras_server_metrics_device_data data) {
+  char metrics_name[METRICS_NAME_BUFFER_SIZE];
+
+  snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "%s.%s",
+           kDeviceDspOffloadStatus, metrics_device_type_str(data.type));
+  cras_metrics_log_sparse_histogram(metrics_name, data.value);
+}
+
 static void metrics_hfp_mic_sr_status(
     struct cras_server_metrics_device_data data) {
   char metrics_name[METRICS_NAME_BUFFER_SIZE];
@@ -1752,6 +1784,9 @@ static void handle_metrics_message(struct cras_main_message* msg, void* arg) {
     case DEVICE_SAMPLE_RATE:
       metrics_device_sample_rate(metrics_msg->data.device_data);
       break;
+    case DEVICE_DSP_OFFLOAD_STATUS:
+      metrics_device_dsp_offload_status(metrics_msg->data.device_data);
+      break;
     case DLC_MANAGER_STATUS:
       metrics_dlc_install_retried_times_on_success(
           metrics_msg->data.dlc_manager_data);

cras/src/server/cras_server_metrics.h

@@ -52,6 +52,13 @@ enum CRAS_DEVICE_OPEN_STATUS {
   CRAS_DEVICE_OPEN_ERROR_CONFIGURE,
 };
 
+enum CRAS_DEVICE_DSP_OFFLOAD_STATUS {
+  CRAS_DEVICE_DSP_OFFLOAD_SUCCESS,
+  CRAS_DEVICE_DSP_OFFLOAD_FALLBACK_SUCCESS,
+  CRAS_DEVICE_DSP_OFFLOAD_FALLBACK_ERROR,
+  CRAS_DEVICE_DSP_OFFLOAD_ERROR,
+};
+
 enum CRAS_STREAM_CONNECT_STATUS {
   CRAS_STREAM_CONN_SUCCESS,
   CRAS_STREAM_CONN_INVALID_FORMAT,
@@ -222,6 +229,11 @@ int cras_server_metrics_ap_nc_runtime(unsigned runtime_second);
 int cras_server_metrics_device_open_status(struct cras_iodev* iodev,
                                            enum CRAS_DEVICE_OPEN_STATUS code);
 
+// Logs DSP offload status for devices.
+int cras_server_metrics_device_dsp_offload_status(
+    const struct cras_iodev* iodev,
+    enum CRAS_DEVICE_DSP_OFFLOAD_STATUS code);
+
 // Logs whether there is an internal soundcard detected.
 int cras_server_metrics_internal_soundcard_status(bool detected, int sec);
 

cras/src/tests/dsp_unittest.cc

@@ -10,6 +10,7 @@
 #include "cras/src/server/cras_dsp_module.h"
 #include "cras/src/server/cras_dsp_offload.h"
 #include "cras/src/server/cras_iodev.h"
+#include "cras/src/server/cras_server_metrics.h"
 #include "cras/src/server/cras_system_state.h"
 
 #define FILENAME_TEMPLATE "DspTest.XXXXXX"
@@ -433,6 +434,7 @@ static void empty_init_module(struct dsp_module* module) {
 }  //  namespace
 
 extern "C" {
+struct main_thread_event_log* main_log;
 struct dsp_module* cras_dsp_module_load_builtin(struct plugin* plugin) {
   struct dsp_module* module;
   module = (struct dsp_module*)calloc(1, sizeof(struct dsp_module));
@@ -487,4 +489,10 @@ const char* cras_system_get_dsp_offload_map_str() {
   return system_get_dsp_offload_map_str_ret;
 }
 
+int cras_server_metrics_device_dsp_offload_status(
+    const struct cras_iodev* iodev,
+    enum CRAS_DEVICE_DSP_OFFLOAD_STATUS code) {
+  return 0;
+}
+
 }  // extern "C"

cras/src/tests/metrics_stub.cc

@@ -77,4 +77,10 @@ int cras_server_metrics_device_open_status(struct cras_iodev* iodev,
   return 0;
 }
 
+int cras_server_metrics_device_dsp_offload_status(
+    const struct cras_iodev* iodev,
+    enum CRAS_DEVICE_DSP_OFFLOAD_STATUS code) {
+  return 0;
+}
+
 }  // extern "C"

cras/src/tools/cras_test_client/cras_test_client.c

@@ -1332,6 +1332,10 @@ static void show_mainlog_tag(const struct main_thread_event_log* log,
       printf("%-30s %s: non_echo=%u disallow=%u\n", "NC_BLOCK_STATE",
              (data1 ? "NC deactivated" : "NC activated"), data2, data3);
       break;
+    case MAIN_THREAD_DEV_DSP_OFFLOAD:
+      printf("%-30s dev %u %s %s\n", "DEV_DSP_OFFLOAD", data1,
+             data2 ? "enable" : "disable", data3 ? "failed" : "ok");
+      break;
     case MAIN_THREAD_STREAM_ADDED:
       printf("%-30s %s stream 0x%x buffer frames %u\n", "STREAM_ADDED",
              (data2 == CRAS_STREAM_OUTPUT ? "output" : "input"), data1, data3);