path: root/cras/src/server/cras_server_metrics.c

/* 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_system_state.h"

#define METRICS_NAME_BUFFER_SIZE 50

const char kBusyloop[] = "Cras.Busyloop";
const char kDeviceTypeInput[] = "Cras.DeviceTypeInput";
const char kDeviceTypeOutput[] = "Cras.DeviceTypeOutput";
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 kStreamTimeoutMilliSeconds[] = "Cras.StreamTimeoutMilliSeconds";
const char kStreamCallbackThreshold[] = "Cras.StreamCallbackThreshold";
const char kStreamClientTypeInput[] = "Cras.StreamClientTypeInput";
const char kStreamClientTypeOutput[] = "Cras.StreamClientTypeOutput";
const char kStreamFlags[] = "Cras.StreamFlags";
const char kStreamSamplingFormat[] = "Cras.StreamSamplingFormat";
const char kStreamSamplingRate[] = "Cras.StreamSamplingRate";
const char kUnderrunsPerDevice[] = "Cras.UnderrunsPerDevice";
const char kHfpWidebandSpeechSupported[] = "Cras.HfpWidebandSpeechSupported";
const char kHfpWidebandSpeechPacketLoss[] = "Cras.HfpWidebandSpeechPacketLoss";

/*
 * 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_WIDEBAND_PACKET_LOSS,
	BT_WIDEBAND_SUPPORTED,
	BUSYLOOP,
	DEVICE_RUNTIME,
	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
};

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_NO_DEVICE,
	CRAS_METRICS_DEVICE_NORMAL_FALLBACK,
	CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK,
	CRAS_METRICS_DEVICE_SILENT_HOTWORD,
	CRAS_METRICS_DEVICE_UNKNOWN,
};

struct cras_server_metrics_stream_config {
	enum CRAS_STREAM_DIRECTION direction;
	unsigned cb_threshold;
	unsigned flags;
	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;
};

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_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_NO_DEVICE:
		return "NoDevice";
	/* Other dummy 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 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
		if (cras_bt_io_on_profile(iodev,
					  CRAS_BT_DEVICE_PROFILE_A2DP_SOURCE))
			return CRAS_METRICS_DEVICE_A2DP;
		if (cras_bt_io_on_profile(
			    iodev, CRAS_BT_DEVICE_PROFILE_HFP_AUDIOGATEWAY))
			return CRAS_METRICS_DEVICE_HFP;
		if (cras_bt_io_on_profile(
			    iodev, CRAS_BT_DEVICE_PROFILE_HSP_AUDIOGATEWAY))
			return CRAS_METRICS_DEVICE_HSP;
#endif
		return CRAS_METRICS_DEVICE_BLUETOOTH;
	case CRAS_NODE_TYPE_UNKNOWN:
	default:
		return CRAS_METRICS_DEVICE_UNKNOWN;
	}
}

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_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_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;
}

int cras_server_metrics_longest_fetch_delay(unsigned delay_msec)
{
	struct cras_server_metrics_message msg;
	union cras_server_metrics_data data;
	int err;

	data.value = delay_msec;
	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;
}

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;
}

int cras_server_metrics_stream_config(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.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;
}

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;
}

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_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)
{
	/* Logs stream callback threshold. */
	cras_metrics_log_sparse_histogram(kStreamCallbackThreshold,
					  config.cb_threshold);

	/* Logs stream flags. */
	cras_metrics_log_sparse_histogram(kStreamFlags, config.flags);

	/* Logs stream sampling format. */
	cras_metrics_log_sparse_histogram(kStreamSamplingFormat, config.format);

	/* Logs stream sampling rate. */
	cras_metrics_log_sparse_histogram(kStreamSamplingRate, config.rate);

	/* 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_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 DEVICE_RUNTIME:
		metrics_device_runtime(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:
		cras_metrics_log_histogram(kStreamTimeoutMilliSeconds,
					   metrics_msg->data.value, 1, 20000,
					   10);
		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 BUSYLOOP:
		metrics_busyloop(metrics_msg->data.timespec_data);
		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;
}