diff options
Diffstat (limited to 'cras/src/server/cras_server_metrics.c')
| -rw-r--r-- | cras/src/server/cras_server_metrics.c | 1326 |
1 files changed, 0 insertions, 1326 deletions
diff --git a/cras/src/server/cras_server_metrics.c b/cras/src/server/cras_server_metrics.c deleted file mode 100644 index 7e487107..00000000 --- a/cras/src/server/cras_server_metrics.c +++ /dev/null @@ -1,1326 +0,0 @@ -/* 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 <errno.h> -#include <math.h> -#include <stdio.h> -#include <string.h> -#include <syslog.h> - -#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; -} |