/* Copyright (c) 2013 The Chromium OS Authors. All rights reserved. * Use of this source code is governed by a BSD-style license that can be * found in the LICENSE file. */ #include #include #include #include #include #ifdef CRAS_DBUS #include "cras_bt_io.h" #endif #include "cras_iodev.h" #include "cras_metrics.h" #include "cras_main_message.h" #include "cras_rstream.h" #include "cras_server_metrics.h" #include "cras_system_state.h" #define METRICS_NAME_BUFFER_SIZE 100 const char kBusyloop[] = "Cras.Busyloop"; const char kBusyloopLength[] = "Cras.BusyloopLength"; const char kDeviceTypeInput[] = "Cras.DeviceTypeInput"; const char kDeviceTypeOutput[] = "Cras.DeviceTypeOutput"; const char kDeviceGain[] = "Cras.DeviceGain"; const char kDeviceVolume[] = "Cras.DeviceVolume"; const char kFetchDelayMilliSeconds[] = "Cras.FetchDelayMilliSeconds"; const char kHighestDeviceDelayInput[] = "Cras.HighestDeviceDelayInput"; const char kHighestDeviceDelayOutput[] = "Cras.HighestDeviceDelayOutput"; const char kHighestInputHardwareLevel[] = "Cras.HighestInputHardwareLevel"; const char kHighestOutputHardwareLevel[] = "Cras.HighestOutputHardwareLevel"; const char kMissedCallbackFirstTimeInput[] = "Cras.MissedCallbackFirstTimeInput"; const char kMissedCallbackFirstTimeOutput[] = "Cras.MissedCallbackFirstTimeOutput"; const char kMissedCallbackFrequencyInput[] = "Cras.MissedCallbackFrequencyInput"; const char kMissedCallbackFrequencyOutput[] = "Cras.MissedCallbackFrequencyOutput"; const char kMissedCallbackFrequencyAfterReschedulingInput[] = "Cras.MissedCallbackFrequencyAfterReschedulingInput"; const char kMissedCallbackFrequencyAfterReschedulingOutput[] = "Cras.MissedCallbackFrequencyAfterReschedulingOutput"; const char kMissedCallbackSecondTimeInput[] = "Cras.MissedCallbackSecondTimeInput"; const char kMissedCallbackSecondTimeOutput[] = "Cras.MissedCallbackSecondTimeOutput"; const char kNoCodecsFoundMetric[] = "Cras.NoCodecsFoundAtBoot"; const char kStreamCallbackThreshold[] = "Cras.StreamCallbackThreshold"; const char kStreamClientTypeInput[] = "Cras.StreamClientTypeInput"; const char kStreamClientTypeOutput[] = "Cras.StreamClientTypeOutput"; const char kStreamFlags[] = "Cras.StreamFlags"; const char kStreamEffects[] = "Cras.StreamEffects"; const char kStreamRuntime[] = "Cras.StreamRuntime"; const char kStreamSamplingFormat[] = "Cras.StreamSamplingFormat"; const char kStreamSamplingRate[] = "Cras.StreamSamplingRate"; const char kUnderrunsPerDevice[] = "Cras.UnderrunsPerDevice"; const char kHfpScoConnectionError[] = "Cras.HfpScoConnectionError"; const char kHfpBatteryIndicatorSupported[] = "Cras.HfpBatteryIndicatorSupported"; const char kHfpBatteryReport[] = "Cras.HfpBatteryReport"; const char kHfpWidebandSpeechSupported[] = "Cras.HfpWidebandSpeechSupported"; const char kHfpWidebandSpeechPacketLoss[] = "Cras.HfpWidebandSpeechPacketLoss"; const char kHfpWidebandSpeechSelectedCodec[] = "Cras.kHfpWidebandSpeechSelectedCodec"; /* * Records missed callback frequency only when the runtime of stream is larger * than the threshold. */ const double MISSED_CB_FREQUENCY_SECONDS_MIN = 10.0; const time_t CRAS_METRICS_SHORT_PERIOD_THRESHOLD_SECONDS = 600; const time_t CRAS_METRICS_LONG_PERIOD_THRESHOLD_SECONDS = 3600; static const char *get_timespec_period_str(struct timespec ts) { if (ts.tv_sec < CRAS_METRICS_SHORT_PERIOD_THRESHOLD_SECONDS) return "ShortPeriod"; if (ts.tv_sec < CRAS_METRICS_LONG_PERIOD_THRESHOLD_SECONDS) return "MediumPeriod"; return "LongPeriod"; } /* Type of metrics to log. */ enum CRAS_SERVER_METRICS_TYPE { BT_BATTERY_INDICATOR_SUPPORTED, BT_BATTERY_REPORT, BT_SCO_CONNECTION_ERROR, BT_WIDEBAND_PACKET_LOSS, BT_WIDEBAND_SUPPORTED, BT_WIDEBAND_SELECTED_CODEC, BUSYLOOP, BUSYLOOP_LENGTH, DEVICE_GAIN, DEVICE_RUNTIME, DEVICE_VOLUME, HIGHEST_DEVICE_DELAY_INPUT, HIGHEST_DEVICE_DELAY_OUTPUT, HIGHEST_INPUT_HW_LEVEL, HIGHEST_OUTPUT_HW_LEVEL, LONGEST_FETCH_DELAY, MISSED_CB_FIRST_TIME_INPUT, MISSED_CB_FIRST_TIME_OUTPUT, MISSED_CB_FREQUENCY_INPUT, MISSED_CB_FREQUENCY_OUTPUT, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT, MISSED_CB_SECOND_TIME_INPUT, MISSED_CB_SECOND_TIME_OUTPUT, NUM_UNDERRUNS, STREAM_CONFIG, STREAM_RUNTIME }; enum CRAS_METRICS_DEVICE_TYPE { /* Output devices. */ CRAS_METRICS_DEVICE_INTERNAL_SPEAKER, CRAS_METRICS_DEVICE_HEADPHONE, CRAS_METRICS_DEVICE_HDMI, CRAS_METRICS_DEVICE_HAPTIC, CRAS_METRICS_DEVICE_LINEOUT, /* Input devices. */ CRAS_METRICS_DEVICE_INTERNAL_MIC, CRAS_METRICS_DEVICE_FRONT_MIC, CRAS_METRICS_DEVICE_REAR_MIC, CRAS_METRICS_DEVICE_KEYBOARD_MIC, CRAS_METRICS_DEVICE_MIC, CRAS_METRICS_DEVICE_HOTWORD, CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK, CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK, /* Devices supporting input and output function. */ CRAS_METRICS_DEVICE_USB, CRAS_METRICS_DEVICE_A2DP, CRAS_METRICS_DEVICE_HFP, CRAS_METRICS_DEVICE_HSP, CRAS_METRICS_DEVICE_BLUETOOTH, CRAS_METRICS_DEVICE_BLUETOOTH_NB_MIC, CRAS_METRICS_DEVICE_NO_DEVICE, CRAS_METRICS_DEVICE_NORMAL_FALLBACK, CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK, CRAS_METRICS_DEVICE_SILENT_HOTWORD, CRAS_METRICS_DEVICE_UNKNOWN, CRAS_METRICS_DEVICE_BLUETOOTH_WB_MIC, CRAS_METRICS_DEVICE_ALSA_LOOPBACK, }; struct cras_server_metrics_stream_config { enum CRAS_STREAM_DIRECTION direction; unsigned cb_threshold; unsigned flags; unsigned effects; int format; unsigned rate; enum CRAS_CLIENT_TYPE client_type; }; struct cras_server_metrics_device_data { enum CRAS_METRICS_DEVICE_TYPE type; enum CRAS_STREAM_DIRECTION direction; struct timespec runtime; unsigned value; }; struct cras_server_metrics_stream_data { enum CRAS_CLIENT_TYPE client_type; enum CRAS_STREAM_TYPE stream_type; enum CRAS_STREAM_DIRECTION direction; struct timespec runtime; }; struct cras_server_metrics_timespec_data { struct timespec runtime; unsigned count; }; union cras_server_metrics_data { unsigned value; struct cras_server_metrics_stream_config stream_config; struct cras_server_metrics_device_data device_data; struct cras_server_metrics_stream_data stream_data; struct cras_server_metrics_timespec_data timespec_data; }; /* * Make sure the size of message in the acceptable range. Otherwise, it may * be split into mutiple packets while sending. */ static_assert(sizeof(union cras_server_metrics_data) <= 256, "The size is too large."); struct cras_server_metrics_message { struct cras_main_message header; enum CRAS_SERVER_METRICS_TYPE metrics_type; union cras_server_metrics_data data; }; static void init_server_metrics_msg(struct cras_server_metrics_message *msg, enum CRAS_SERVER_METRICS_TYPE type, union cras_server_metrics_data data) { memset(msg, 0, sizeof(*msg)); msg->header.type = CRAS_MAIN_METRICS; msg->header.length = sizeof(*msg); msg->metrics_type = type; msg->data = data; } static void handle_metrics_message(struct cras_main_message *msg, void *arg); /* The wrapper function of cras_main_message_send. */ static int cras_server_metrics_message_send(struct cras_main_message *msg) { /* If current function is in the main thread, call handler directly. */ if (cras_system_state_in_main_thread()) { handle_metrics_message(msg, NULL); return 0; } return cras_main_message_send(msg); } static inline const char * metrics_device_type_str(enum CRAS_METRICS_DEVICE_TYPE device_type) { switch (device_type) { case CRAS_METRICS_DEVICE_INTERNAL_SPEAKER: return "InternalSpeaker"; case CRAS_METRICS_DEVICE_HEADPHONE: return "Headphone"; case CRAS_METRICS_DEVICE_HDMI: return "HDMI"; case CRAS_METRICS_DEVICE_HAPTIC: return "Haptic"; case CRAS_METRICS_DEVICE_LINEOUT: return "Lineout"; /* Input devices. */ case CRAS_METRICS_DEVICE_INTERNAL_MIC: return "InternalMic"; case CRAS_METRICS_DEVICE_FRONT_MIC: return "FrontMic"; case CRAS_METRICS_DEVICE_REAR_MIC: return "RearMic"; case CRAS_METRICS_DEVICE_KEYBOARD_MIC: return "KeyboardMic"; case CRAS_METRICS_DEVICE_MIC: return "Mic"; case CRAS_METRICS_DEVICE_HOTWORD: return "Hotword"; case CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK: return "PostMixLoopback"; case CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK: return "PostDspLoopback"; /* Devices supporting input and output function. */ case CRAS_METRICS_DEVICE_USB: return "USB"; case CRAS_METRICS_DEVICE_A2DP: return "A2DP"; case CRAS_METRICS_DEVICE_HFP: return "HFP"; case CRAS_METRICS_DEVICE_HSP: return "HSP"; case CRAS_METRICS_DEVICE_BLUETOOTH: return "Bluetooth"; case CRAS_METRICS_DEVICE_BLUETOOTH_NB_MIC: return "BluetoothNarrowBandMic"; case CRAS_METRICS_DEVICE_BLUETOOTH_WB_MIC: return "BluetoothWideBandMic"; case CRAS_METRICS_DEVICE_NO_DEVICE: return "NoDevice"; case CRAS_METRICS_DEVICE_ALSA_LOOPBACK: return "AlsaLoopback"; /* Other fallback devices. */ case CRAS_METRICS_DEVICE_NORMAL_FALLBACK: return "NormalFallback"; case CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK: return "AbnormalFallback"; case CRAS_METRICS_DEVICE_SILENT_HOTWORD: return "SilentHotword"; case CRAS_METRICS_DEVICE_UNKNOWN: return "Unknown"; default: return "InvalidType"; } } static inline const char * metrics_client_type_str(enum CRAS_CLIENT_TYPE client_type) { switch (client_type) { case CRAS_CLIENT_TYPE_UNKNOWN: return "Unknown"; case CRAS_CLIENT_TYPE_LEGACY: return "Legacy"; case CRAS_CLIENT_TYPE_TEST: return "Test"; case CRAS_CLIENT_TYPE_PCM: return "PCM"; case CRAS_CLIENT_TYPE_CHROME: return "Chrome"; case CRAS_CLIENT_TYPE_ARC: return "ARC"; case CRAS_CLIENT_TYPE_CROSVM: return "CrOSVM"; case CRAS_CLIENT_TYPE_SERVER_STREAM: return "ServerStream"; case CRAS_CLIENT_TYPE_LACROS: return "LaCrOS"; case CRAS_CLIENT_TYPE_PLUGIN: return "PluginVM"; case CRAS_CLIENT_TYPE_ARCVM: return "ARCVM"; default: return "InvalidType"; } } static inline const char * metrics_stream_type_str(enum CRAS_STREAM_TYPE stream_type) { switch (stream_type) { case CRAS_STREAM_TYPE_DEFAULT: return "Default"; case CRAS_STREAM_TYPE_MULTIMEDIA: return "Multimedia"; case CRAS_STREAM_TYPE_VOICE_COMMUNICATION: return "VoiceCommunication"; case CRAS_STREAM_TYPE_SPEECH_RECOGNITION: return "SpeechRecognition"; case CRAS_STREAM_TYPE_PRO_AUDIO: return "ProAudio"; case CRAS_STREAM_TYPE_ACCESSIBILITY: return "Accessibility"; default: return "InvalidType"; } } static enum CRAS_METRICS_DEVICE_TYPE get_metrics_device_type(struct cras_iodev *iodev) { /* Check whether it is a special device. */ if (iodev->info.idx < MAX_SPECIAL_DEVICE_IDX) { switch (iodev->info.idx) { case NO_DEVICE: syslog(LOG_ERR, "The invalid device has been used."); return CRAS_METRICS_DEVICE_NO_DEVICE; case SILENT_RECORD_DEVICE: case SILENT_PLAYBACK_DEVICE: if (iodev->active_node->type == CRAS_NODE_TYPE_FALLBACK_NORMAL) return CRAS_METRICS_DEVICE_NORMAL_FALLBACK; else return CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK; case SILENT_HOTWORD_DEVICE: return CRAS_METRICS_DEVICE_SILENT_HOTWORD; } } switch (iodev->active_node->type) { case CRAS_NODE_TYPE_INTERNAL_SPEAKER: return CRAS_METRICS_DEVICE_INTERNAL_SPEAKER; case CRAS_NODE_TYPE_HEADPHONE: return CRAS_METRICS_DEVICE_HEADPHONE; case CRAS_NODE_TYPE_HDMI: return CRAS_METRICS_DEVICE_HDMI; case CRAS_NODE_TYPE_HAPTIC: return CRAS_METRICS_DEVICE_HAPTIC; case CRAS_NODE_TYPE_LINEOUT: return CRAS_METRICS_DEVICE_LINEOUT; case CRAS_NODE_TYPE_MIC: switch (iodev->active_node->position) { case NODE_POSITION_INTERNAL: return CRAS_METRICS_DEVICE_INTERNAL_MIC; case NODE_POSITION_FRONT: return CRAS_METRICS_DEVICE_FRONT_MIC; case NODE_POSITION_REAR: return CRAS_METRICS_DEVICE_REAR_MIC; case NODE_POSITION_KEYBOARD: return CRAS_METRICS_DEVICE_KEYBOARD_MIC; case NODE_POSITION_EXTERNAL: default: return CRAS_METRICS_DEVICE_MIC; } case CRAS_NODE_TYPE_HOTWORD: return CRAS_METRICS_DEVICE_HOTWORD; case CRAS_NODE_TYPE_POST_MIX_PRE_DSP: return CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK; case CRAS_NODE_TYPE_POST_DSP: return CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK; case CRAS_NODE_TYPE_USB: return CRAS_METRICS_DEVICE_USB; case CRAS_NODE_TYPE_BLUETOOTH: { #ifdef CRAS_DBUS enum cras_bt_device_profile profile = cras_bt_io_profile_to_log(iodev); switch (profile) { case CRAS_BT_DEVICE_PROFILE_A2DP_SOURCE: return CRAS_METRICS_DEVICE_A2DP; case CRAS_BT_DEVICE_PROFILE_HFP_AUDIOGATEWAY: /* HFP narrow band has its own node type so we know * this is wideband mic for sure. */ return (iodev->direction == CRAS_STREAM_INPUT) ? CRAS_METRICS_DEVICE_BLUETOOTH_WB_MIC : CRAS_METRICS_DEVICE_HFP; case CRAS_BT_DEVICE_PROFILE_HSP_AUDIOGATEWAY: return CRAS_METRICS_DEVICE_HSP; default: break; } #endif return CRAS_METRICS_DEVICE_BLUETOOTH; } case CRAS_NODE_TYPE_BLUETOOTH_NB_MIC: return CRAS_METRICS_DEVICE_BLUETOOTH_NB_MIC; case CRAS_NODE_TYPE_ALSA_LOOPBACK: return CRAS_METRICS_DEVICE_ALSA_LOOPBACK; case CRAS_NODE_TYPE_UNKNOWN: default: return CRAS_METRICS_DEVICE_UNKNOWN; } } /* * Logs metrics for each group it belongs to. The UMA does not merge subgroups * automatically so we need to log them separately. * * For example, if we call this function with argument (3, 48000, * Cras.StreamSamplingRate, Input, Chrome), it will send 48000 to below * metrics: * Cras.StreamSamplingRate.Input.Chrome * Cras.StreamSamplingRate.Input * Cras.StreamSamplingRate */ static void log_sparse_histogram_each_level(int num, int sample, ...) { char metrics_name[METRICS_NAME_BUFFER_SIZE] = {}; va_list valist; int i, len = 0; va_start(valist, sample); for (i = 0; i < num && len < METRICS_NAME_BUFFER_SIZE; i++) { int metric_len = snprintf(metrics_name + len, METRICS_NAME_BUFFER_SIZE - len, "%s%s", i ? "." : "", va_arg(valist, char *)); // Exit early on error or running out of bufferspace. Avoids // logging partial or corrupted strings. if (metric_len < 0 || metric_len > METRICS_NAME_BUFFER_SIZE - len) break; len += metric_len; cras_metrics_log_sparse_histogram(metrics_name, sample); } va_end(valist); } static void log_histogram_each_level(int num, int sample, int min, int max, int nbuckets, ...) { char metrics_name[METRICS_NAME_BUFFER_SIZE] = {}; va_list valist; int i, len = 0; va_start(valist, nbuckets); for (i = 0; i < num && len < METRICS_NAME_BUFFER_SIZE; i++) { int metric_len = snprintf(metrics_name + len, METRICS_NAME_BUFFER_SIZE - len, "%s%s", i ? "." : "", va_arg(valist, char *)); // Exit early on error or running out of bufferspace. Avoids // logging partial or corrupted strings. if (metric_len < 0 || metric_len > METRICS_NAME_BUFFER_SIZE - len) break; len += metric_len; cras_metrics_log_histogram(metrics_name, sample, min, max, nbuckets); } va_end(valist); } int cras_server_metrics_hfp_sco_connection_error( enum CRAS_METRICS_BT_SCO_ERROR_TYPE type) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = type; init_server_metrics_msg(&msg, BT_SCO_CONNECTION_ERROR, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "BT_SCO_CONNECTION_ERROR"); return err; } return 0; } int cras_server_metrics_hfp_battery_indicator(int battery_indicator_support) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = battery_indicator_support; init_server_metrics_msg(&msg, BT_BATTERY_INDICATOR_SUPPORTED, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "BT_BATTERY_INDICATOR_SUPPORTED"); return err; } return 0; } int cras_server_metrics_hfp_battery_report(int battery_report) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = battery_report; init_server_metrics_msg(&msg, BT_BATTERY_REPORT, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "BT_BATTERY_REPORT"); return err; } return 0; } int cras_server_metrics_hfp_packet_loss(float packet_loss_ratio) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; /* Percentage is too coarse for packet loss, so we use number of bad * packets per thousand packets instead. */ data.value = (unsigned)(round(packet_loss_ratio * 1000)); init_server_metrics_msg(&msg, BT_WIDEBAND_PACKET_LOSS, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: BT_WIDEBAND_PACKET_LOSS"); return err; } return 0; } int cras_server_metrics_hfp_wideband_support(bool supported) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = supported; init_server_metrics_msg(&msg, BT_WIDEBAND_SUPPORTED, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: BT_WIDEBAND_SUPPORTED"); return err; } return 0; } int cras_server_metrics_hfp_wideband_selected_codec(int codec) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = codec; init_server_metrics_msg(&msg, BT_WIDEBAND_SELECTED_CODEC, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "BT_WIDEBAND_SELECTED_CODEC"); return err; } return 0; } int cras_server_metrics_device_runtime(struct cras_iodev *iodev) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; struct timespec now; int err; data.device_data.type = get_metrics_device_type(iodev); data.device_data.direction = iodev->direction; clock_gettime(CLOCK_MONOTONIC_RAW, &now); subtract_timespecs(&now, &iodev->open_ts, &data.device_data.runtime); init_server_metrics_msg(&msg, DEVICE_RUNTIME, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: DEVICE_RUNTIME"); return err; } return 0; } int cras_server_metrics_device_gain(struct cras_iodev *iodev) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; if (iodev->direction == CRAS_STREAM_OUTPUT) return 0; data.device_data.type = get_metrics_device_type(iodev); data.device_data.value = (unsigned)100 * iodev->active_node->ui_gain_scaler; init_server_metrics_msg(&msg, DEVICE_GAIN, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: DEVICE_GAIN"); return err; } return 0; } int cras_server_metrics_device_volume(struct cras_iodev *iodev) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; if (iodev->direction == CRAS_STREAM_INPUT) return 0; data.device_data.type = get_metrics_device_type(iodev); data.device_data.value = iodev->active_node->volume; init_server_metrics_msg(&msg, DEVICE_VOLUME, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: DEVICE_VOLUME"); return err; } return 0; } int cras_server_metrics_highest_device_delay( unsigned int hw_level, unsigned int largest_cb_level, enum CRAS_STREAM_DIRECTION direction) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; if (largest_cb_level == 0) { syslog(LOG_ERR, "Failed to record device delay: devided by zero"); return -1; } /* * Because the latency depends on the callback threshold of streams, it * should be calculated as dividing the highest hardware level by largest * callback threshold of streams. For output device, this value should fall * around 2 because CRAS 's scheduling maintain device buffer level around * 1~2 minimum callback level. For input device, this value should be around * 1 because the device buffer level is around 0~1 minimum callback level. * Besides, UMA cannot record float so this ratio is multiplied by 1000. */ data.value = hw_level * 1000 / largest_cb_level; switch (direction) { case CRAS_STREAM_INPUT: init_server_metrics_msg(&msg, HIGHEST_DEVICE_DELAY_INPUT, data); break; case CRAS_STREAM_OUTPUT: init_server_metrics_msg(&msg, HIGHEST_DEVICE_DELAY_OUTPUT, data); break; default: return 0; } err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: HIGHEST_DEVICE_DELAY"); return err; } return 0; } int cras_server_metrics_highest_hw_level(unsigned hw_level, enum CRAS_STREAM_DIRECTION direction) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = hw_level; switch (direction) { case CRAS_STREAM_INPUT: init_server_metrics_msg(&msg, HIGHEST_INPUT_HW_LEVEL, data); break; case CRAS_STREAM_OUTPUT: init_server_metrics_msg(&msg, HIGHEST_OUTPUT_HW_LEVEL, data); break; default: return 0; } err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: HIGHEST_HW_LEVEL"); return err; } return 0; } /* 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.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); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: LONGEST_FETCH_DELAY"); return err; } return 0; } int cras_server_metrics_num_underruns(unsigned num_underruns) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = num_underruns; init_server_metrics_msg(&msg, NUM_UNDERRUNS, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: NUM_UNDERRUNS"); return err; } return 0; } /* Logs the frequency of missed callback. */ static int cras_server_metrics_missed_cb_frequency(const struct cras_rstream *stream) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; struct timespec now, time_since; double seconds, frequency; int err; clock_gettime(CLOCK_MONOTONIC_RAW, &now); subtract_timespecs(&now, &stream->start_ts, &time_since); seconds = (double)time_since.tv_sec + time_since.tv_nsec / 1000000000.0; /* Ignore streams which do not have enough runtime. */ if (seconds < MISSED_CB_FREQUENCY_SECONDS_MIN) return 0; /* Compute how many callbacks are missed in a day. */ frequency = (double)stream->num_missed_cb * 86400.0 / seconds; data.value = (unsigned)(round(frequency) + 1e-9); if (stream->direction == CRAS_STREAM_INPUT) init_server_metrics_msg(&msg, MISSED_CB_FREQUENCY_INPUT, data); else init_server_metrics_msg(&msg, MISSED_CB_FREQUENCY_OUTPUT, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: MISSED_CB_FREQUENCY"); return err; } /* * If missed callback happened at least once, also record frequncy after * rescheduling. */ if (!stream->num_missed_cb) return 0; subtract_timespecs(&now, &stream->first_missed_cb_ts, &time_since); seconds = (double)time_since.tv_sec + time_since.tv_nsec / 1000000000.0; /* Compute how many callbacks are missed in a day. */ frequency = (double)(stream->num_missed_cb - 1) * 86400.0 / seconds; data.value = (unsigned)(round(frequency) + 1e-9); if (stream->direction == CRAS_STREAM_INPUT) { init_server_metrics_msg( &msg, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT, data); } else { init_server_metrics_msg( &msg, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT, data); } err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: MISSED_CB_FREQUENCY"); return err; } return 0; } /* * Logs the duration between stream starting time and the first missed * callback. */ static int cras_server_metrics_missed_cb_first_time(const struct cras_rstream *stream) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; struct timespec time_since; int err; subtract_timespecs(&stream->first_missed_cb_ts, &stream->start_ts, &time_since); data.value = (unsigned)time_since.tv_sec; if (stream->direction == CRAS_STREAM_INPUT) { init_server_metrics_msg(&msg, MISSED_CB_FIRST_TIME_INPUT, data); } else { init_server_metrics_msg(&msg, MISSED_CB_FIRST_TIME_OUTPUT, data); } err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "MISSED_CB_FIRST_TIME"); return err; } return 0; } /* Logs the duration between the first and the second missed callback events. */ static int cras_server_metrics_missed_cb_second_time(const struct cras_rstream *stream) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; struct timespec now, time_since; int err; clock_gettime(CLOCK_MONOTONIC_RAW, &now); subtract_timespecs(&now, &stream->first_missed_cb_ts, &time_since); data.value = (unsigned)time_since.tv_sec; if (stream->direction == CRAS_STREAM_INPUT) { init_server_metrics_msg(&msg, MISSED_CB_SECOND_TIME_INPUT, data); } else { init_server_metrics_msg(&msg, MISSED_CB_SECOND_TIME_OUTPUT, data); } err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: " "MISSED_CB_SECOND_TIME"); return err; } return 0; } int cras_server_metrics_missed_cb_event(struct cras_rstream *stream) { int rc = 0; stream->num_missed_cb += 1; if (stream->num_missed_cb == 1) clock_gettime(CLOCK_MONOTONIC_RAW, &stream->first_missed_cb_ts); /* Do not record missed cb if the stream has these flags. */ if (stream->flags & (BULK_AUDIO_OK | USE_DEV_TIMING | TRIGGER_ONLY)) return 0; /* Only record the first and the second events. */ if (stream->num_missed_cb == 1) rc = cras_server_metrics_missed_cb_first_time(stream); else if (stream->num_missed_cb == 2) rc = cras_server_metrics_missed_cb_second_time(stream); return rc; } /* Logs the stream configurations from clients. */ static int cras_server_metrics_stream_config(const struct cras_rstream_config *config) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.stream_config.direction = config->direction; data.stream_config.cb_threshold = (unsigned)config->cb_threshold; data.stream_config.flags = (unsigned)config->flags; data.stream_config.effects = (unsigned)config->effects; data.stream_config.format = (int)config->format->format; data.stream_config.rate = (unsigned)config->format->frame_rate; data.stream_config.client_type = config->client_type; init_server_metrics_msg(&msg, STREAM_CONFIG, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: STREAM_CONFIG"); return err; } return 0; } /* Logs runtime of a stream. */ int cras_server_metrics_stream_runtime(const struct cras_rstream *stream) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; struct timespec now; int err; data.stream_data.client_type = stream->client_type; data.stream_data.stream_type = stream->stream_type; data.stream_data.direction = stream->direction; clock_gettime(CLOCK_MONOTONIC_RAW, &now); subtract_timespecs(&now, &stream->start_ts, &data.stream_data.runtime); init_server_metrics_msg(&msg, STREAM_RUNTIME, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: STREAM_RUNTIME"); return err; } return 0; } int cras_server_metrics_stream_create(const struct cras_rstream_config *config) { return cras_server_metrics_stream_config(config); } int cras_server_metrics_stream_destroy(const struct cras_rstream *stream) { int rc; rc = cras_server_metrics_missed_cb_frequency(stream); if (rc < 0) return rc; rc = cras_server_metrics_stream_runtime(stream); if (rc < 0) return rc; return cras_server_metrics_longest_fetch_delay(stream); } int cras_server_metrics_busyloop(struct timespec *ts, unsigned count) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.timespec_data.runtime = *ts; data.timespec_data.count = count; init_server_metrics_msg(&msg, BUSYLOOP, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: BUSYLOOP"); return err; } return 0; } int cras_server_metrics_busyloop_length(unsigned length) { struct cras_server_metrics_message msg; union cras_server_metrics_data data; int err; data.value = length; init_server_metrics_msg(&msg, BUSYLOOP_LENGTH, data); err = cras_server_metrics_message_send( (struct cras_main_message *)&msg); if (err < 0) { syslog(LOG_ERR, "Failed to send metrics message: BUSYLOOP_LENGTH"); return err; } return 0; } static void metrics_device_runtime(struct cras_server_metrics_device_data data) { char metrics_name[METRICS_NAME_BUFFER_SIZE]; snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "Cras.%sDevice%sRuntime", data.direction == CRAS_STREAM_INPUT ? "Input" : "Output", metrics_device_type_str(data.type)); cras_metrics_log_histogram(metrics_name, (unsigned)data.runtime.tv_sec, 0, 10000, 20); /* Logs the usage of each device. */ if (data.direction == CRAS_STREAM_INPUT) cras_metrics_log_sparse_histogram(kDeviceTypeInput, data.type); else cras_metrics_log_sparse_histogram(kDeviceTypeOutput, data.type); } static void metrics_device_gain(struct cras_server_metrics_device_data data) { char metrics_name[METRICS_NAME_BUFFER_SIZE]; snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "%s.%s", kDeviceGain, metrics_device_type_str(data.type)); cras_metrics_log_histogram(metrics_name, data.value, 0, 2000, 20); } static void metrics_device_volume(struct cras_server_metrics_device_data data) { char metrics_name[METRICS_NAME_BUFFER_SIZE]; snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "%s.%s", kDeviceVolume, metrics_device_type_str(data.type)); 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_histogram_each_level(3, fetch_delay_msec, 0, 10000, 20, kFetchDelayMilliSeconds, 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) { log_histogram_each_level( 4, (int)data.runtime.tv_sec, 0, 10000, 20, kStreamRuntime, data.direction == CRAS_STREAM_INPUT ? "Input" : "Output", metrics_client_type_str(data.client_type), metrics_stream_type_str(data.stream_type)); } static void metrics_busyloop(struct cras_server_metrics_timespec_data data) { char metrics_name[METRICS_NAME_BUFFER_SIZE]; snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "%s.%s", kBusyloop, get_timespec_period_str(data.runtime)); cras_metrics_log_histogram(metrics_name, data.count, 0, 1000, 20); } static void metrics_stream_config(struct cras_server_metrics_stream_config config) { const char *direction; if (config.direction == CRAS_STREAM_INPUT) direction = "Input"; else direction = "Output"; /* Logs stream callback threshold. */ log_sparse_histogram_each_level( 3, config.cb_threshold, kStreamCallbackThreshold, direction, metrics_client_type_str(config.client_type)); /* Logs stream flags. */ log_sparse_histogram_each_level( 3, config.flags, kStreamFlags, direction, metrics_client_type_str(config.client_type)); /* Logs stream effects. */ log_sparse_histogram_each_level( 3, config.effects, kStreamEffects, direction, metrics_client_type_str(config.client_type)); /* Logs stream sampling format. */ log_sparse_histogram_each_level( 3, config.format, kStreamSamplingFormat, direction, metrics_client_type_str(config.client_type)); /* Logs stream sampling rate. */ log_sparse_histogram_each_level( 3, config.rate, kStreamSamplingRate, direction, metrics_client_type_str(config.client_type)); /* Logs stream client type. */ if (config.direction == CRAS_STREAM_INPUT) cras_metrics_log_sparse_histogram(kStreamClientTypeInput, config.client_type); else cras_metrics_log_sparse_histogram(kStreamClientTypeOutput, config.client_type); } static void handle_metrics_message(struct cras_main_message *msg, void *arg) { struct cras_server_metrics_message *metrics_msg = (struct cras_server_metrics_message *)msg; switch (metrics_msg->metrics_type) { case BT_SCO_CONNECTION_ERROR: cras_metrics_log_sparse_histogram(kHfpScoConnectionError, metrics_msg->data.value); break; case BT_BATTERY_INDICATOR_SUPPORTED: cras_metrics_log_sparse_histogram(kHfpBatteryIndicatorSupported, metrics_msg->data.value); break; case BT_BATTERY_REPORT: cras_metrics_log_sparse_histogram(kHfpBatteryReport, metrics_msg->data.value); break; case BT_WIDEBAND_PACKET_LOSS: cras_metrics_log_histogram(kHfpWidebandSpeechPacketLoss, metrics_msg->data.value, 0, 1000, 20); break; case BT_WIDEBAND_SUPPORTED: cras_metrics_log_sparse_histogram(kHfpWidebandSpeechSupported, metrics_msg->data.value); break; case BT_WIDEBAND_SELECTED_CODEC: cras_metrics_log_sparse_histogram( kHfpWidebandSpeechSelectedCodec, metrics_msg->data.value); break; case DEVICE_GAIN: metrics_device_gain(metrics_msg->data.device_data); break; case DEVICE_RUNTIME: metrics_device_runtime(metrics_msg->data.device_data); break; case DEVICE_VOLUME: metrics_device_volume(metrics_msg->data.device_data); break; case HIGHEST_DEVICE_DELAY_INPUT: cras_metrics_log_histogram(kHighestDeviceDelayInput, metrics_msg->data.value, 1, 10000, 20); break; case HIGHEST_DEVICE_DELAY_OUTPUT: cras_metrics_log_histogram(kHighestDeviceDelayOutput, metrics_msg->data.value, 1, 10000, 20); break; case HIGHEST_INPUT_HW_LEVEL: cras_metrics_log_histogram(kHighestInputHardwareLevel, metrics_msg->data.value, 1, 10000, 20); break; case HIGHEST_OUTPUT_HW_LEVEL: cras_metrics_log_histogram(kHighestOutputHardwareLevel, metrics_msg->data.value, 1, 10000, 20); break; case LONGEST_FETCH_DELAY: metrics_longest_fetch_delay(metrics_msg->data.stream_data); break; case MISSED_CB_FIRST_TIME_INPUT: cras_metrics_log_histogram(kMissedCallbackFirstTimeInput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_FIRST_TIME_OUTPUT: cras_metrics_log_histogram(kMissedCallbackFirstTimeOutput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_FREQUENCY_INPUT: cras_metrics_log_histogram(kMissedCallbackFrequencyInput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_FREQUENCY_OUTPUT: cras_metrics_log_histogram(kMissedCallbackFrequencyOutput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT: cras_metrics_log_histogram( kMissedCallbackFrequencyAfterReschedulingInput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT: cras_metrics_log_histogram( kMissedCallbackFrequencyAfterReschedulingOutput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_SECOND_TIME_INPUT: cras_metrics_log_histogram(kMissedCallbackSecondTimeInput, metrics_msg->data.value, 0, 90000, 20); break; case MISSED_CB_SECOND_TIME_OUTPUT: cras_metrics_log_histogram(kMissedCallbackSecondTimeOutput, metrics_msg->data.value, 0, 90000, 20); break; case NUM_UNDERRUNS: cras_metrics_log_histogram(kUnderrunsPerDevice, metrics_msg->data.value, 0, 1000, 10); break; case STREAM_CONFIG: metrics_stream_config(metrics_msg->data.stream_config); break; case STREAM_RUNTIME: metrics_stream_runtime(metrics_msg->data.stream_data); break; case BUSYLOOP: metrics_busyloop(metrics_msg->data.timespec_data); break; case BUSYLOOP_LENGTH: cras_metrics_log_histogram( kBusyloopLength, metrics_msg->data.value, 0, 1000, 50); break; default: syslog(LOG_ERR, "Unknown metrics type %u", metrics_msg->metrics_type); break; } } int cras_server_metrics_init() { cras_main_message_add_handler(CRAS_MAIN_METRICS, handle_metrics_message, NULL); return 0; }