1 /* Copyright (c) 2013 The Chromium OS Authors. All rights reserved.
2 * Use of this source code is governed by a BSD-style license that can be
3 * found in the LICENSE file.
4 */
5
6 #include <errno.h>
7 #include <math.h>
8 #include <stdio.h>
9 #include <string.h>
10 #include <syslog.h>
11
12 #ifdef CRAS_DBUS
13 #include "cras_bt_io.h"
14 #endif
15 #include "cras_iodev.h"
16 #include "cras_metrics.h"
17 #include "cras_main_message.h"
18 #include "cras_rstream.h"
19 #include "cras_system_state.h"
20
21 #define METRICS_NAME_BUFFER_SIZE 50
22
23 const char kBusyloop[] = "Cras.Busyloop";
24 const char kDeviceTypeInput[] = "Cras.DeviceTypeInput";
25 const char kDeviceTypeOutput[] = "Cras.DeviceTypeOutput";
26 const char kHighestDeviceDelayInput[] = "Cras.HighestDeviceDelayInput";
27 const char kHighestDeviceDelayOutput[] = "Cras.HighestDeviceDelayOutput";
28 const char kHighestInputHardwareLevel[] = "Cras.HighestInputHardwareLevel";
29 const char kHighestOutputHardwareLevel[] = "Cras.HighestOutputHardwareLevel";
30 const char kMissedCallbackFirstTimeInput[] =
31 "Cras.MissedCallbackFirstTimeInput";
32 const char kMissedCallbackFirstTimeOutput[] =
33 "Cras.MissedCallbackFirstTimeOutput";
34 const char kMissedCallbackFrequencyInput[] =
35 "Cras.MissedCallbackFrequencyInput";
36 const char kMissedCallbackFrequencyOutput[] =
37 "Cras.MissedCallbackFrequencyOutput";
38 const char kMissedCallbackFrequencyAfterReschedulingInput[] =
39 "Cras.MissedCallbackFrequencyAfterReschedulingInput";
40 const char kMissedCallbackFrequencyAfterReschedulingOutput[] =
41 "Cras.MissedCallbackFrequencyAfterReschedulingOutput";
42 const char kMissedCallbackSecondTimeInput[] =
43 "Cras.MissedCallbackSecondTimeInput";
44 const char kMissedCallbackSecondTimeOutput[] =
45 "Cras.MissedCallbackSecondTimeOutput";
46 const char kNoCodecsFoundMetric[] = "Cras.NoCodecsFoundAtBoot";
47 const char kStreamTimeoutMilliSeconds[] = "Cras.StreamTimeoutMilliSeconds";
48 const char kStreamCallbackThreshold[] = "Cras.StreamCallbackThreshold";
49 const char kStreamClientTypeInput[] = "Cras.StreamClientTypeInput";
50 const char kStreamClientTypeOutput[] = "Cras.StreamClientTypeOutput";
51 const char kStreamFlags[] = "Cras.StreamFlags";
52 const char kStreamSamplingFormat[] = "Cras.StreamSamplingFormat";
53 const char kStreamSamplingRate[] = "Cras.StreamSamplingRate";
54 const char kUnderrunsPerDevice[] = "Cras.UnderrunsPerDevice";
55 const char kHfpWidebandSpeechSupported[] = "Cras.HfpWidebandSpeechSupported";
56 const char kHfpWidebandSpeechPacketLoss[] = "Cras.HfpWidebandSpeechPacketLoss";
57
58 /*
59 * Records missed callback frequency only when the runtime of stream is larger
60 * than the threshold.
61 */
62 const double MISSED_CB_FREQUENCY_SECONDS_MIN = 10.0;
63
64 const time_t CRAS_METRICS_SHORT_PERIOD_THRESHOLD_SECONDS = 600;
65 const time_t CRAS_METRICS_LONG_PERIOD_THRESHOLD_SECONDS = 3600;
66
get_timespec_period_str(struct timespec ts)67 static const char *get_timespec_period_str(struct timespec ts)
68 {
69 if (ts.tv_sec < CRAS_METRICS_SHORT_PERIOD_THRESHOLD_SECONDS)
70 return "ShortPeriod";
71 if (ts.tv_sec < CRAS_METRICS_LONG_PERIOD_THRESHOLD_SECONDS)
72 return "MediumPeriod";
73 return "LongPeriod";
74 }
75
76 /* Type of metrics to log. */
77 enum CRAS_SERVER_METRICS_TYPE {
78 BT_WIDEBAND_PACKET_LOSS,
79 BT_WIDEBAND_SUPPORTED,
80 BUSYLOOP,
81 DEVICE_RUNTIME,
82 HIGHEST_DEVICE_DELAY_INPUT,
83 HIGHEST_DEVICE_DELAY_OUTPUT,
84 HIGHEST_INPUT_HW_LEVEL,
85 HIGHEST_OUTPUT_HW_LEVEL,
86 LONGEST_FETCH_DELAY,
87 MISSED_CB_FIRST_TIME_INPUT,
88 MISSED_CB_FIRST_TIME_OUTPUT,
89 MISSED_CB_FREQUENCY_INPUT,
90 MISSED_CB_FREQUENCY_OUTPUT,
91 MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT,
92 MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT,
93 MISSED_CB_SECOND_TIME_INPUT,
94 MISSED_CB_SECOND_TIME_OUTPUT,
95 NUM_UNDERRUNS,
96 STREAM_CONFIG
97 };
98
99 enum CRAS_METRICS_DEVICE_TYPE {
100 /* Output devices. */
101 CRAS_METRICS_DEVICE_INTERNAL_SPEAKER,
102 CRAS_METRICS_DEVICE_HEADPHONE,
103 CRAS_METRICS_DEVICE_HDMI,
104 CRAS_METRICS_DEVICE_HAPTIC,
105 CRAS_METRICS_DEVICE_LINEOUT,
106 /* Input devices. */
107 CRAS_METRICS_DEVICE_INTERNAL_MIC,
108 CRAS_METRICS_DEVICE_FRONT_MIC,
109 CRAS_METRICS_DEVICE_REAR_MIC,
110 CRAS_METRICS_DEVICE_KEYBOARD_MIC,
111 CRAS_METRICS_DEVICE_MIC,
112 CRAS_METRICS_DEVICE_HOTWORD,
113 CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK,
114 CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK,
115 /* Devices supporting input and output function. */
116 CRAS_METRICS_DEVICE_USB,
117 CRAS_METRICS_DEVICE_A2DP,
118 CRAS_METRICS_DEVICE_HFP,
119 CRAS_METRICS_DEVICE_HSP,
120 CRAS_METRICS_DEVICE_BLUETOOTH,
121 CRAS_METRICS_DEVICE_NO_DEVICE,
122 CRAS_METRICS_DEVICE_NORMAL_FALLBACK,
123 CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK,
124 CRAS_METRICS_DEVICE_SILENT_HOTWORD,
125 CRAS_METRICS_DEVICE_UNKNOWN,
126 };
127
128 struct cras_server_metrics_stream_config {
129 enum CRAS_STREAM_DIRECTION direction;
130 unsigned cb_threshold;
131 unsigned flags;
132 int format;
133 unsigned rate;
134 enum CRAS_CLIENT_TYPE client_type;
135 };
136
137 struct cras_server_metrics_device_data {
138 enum CRAS_METRICS_DEVICE_TYPE type;
139 enum CRAS_STREAM_DIRECTION direction;
140 struct timespec runtime;
141 };
142
143 struct cras_server_metrics_timespec_data {
144 struct timespec runtime;
145 unsigned count;
146 };
147
148 union cras_server_metrics_data {
149 unsigned value;
150 struct cras_server_metrics_stream_config stream_config;
151 struct cras_server_metrics_device_data device_data;
152 struct cras_server_metrics_timespec_data timespec_data;
153 };
154
155 /*
156 * Make sure the size of message in the acceptable range. Otherwise, it may
157 * be split into mutiple packets while sending.
158 */
159 static_assert(sizeof(union cras_server_metrics_data) <= 256,
160 "The size is too large.");
161
162 struct cras_server_metrics_message {
163 struct cras_main_message header;
164 enum CRAS_SERVER_METRICS_TYPE metrics_type;
165 union cras_server_metrics_data data;
166 };
167
init_server_metrics_msg(struct cras_server_metrics_message * msg,enum CRAS_SERVER_METRICS_TYPE type,union cras_server_metrics_data data)168 static void init_server_metrics_msg(struct cras_server_metrics_message *msg,
169 enum CRAS_SERVER_METRICS_TYPE type,
170 union cras_server_metrics_data data)
171 {
172 memset(msg, 0, sizeof(*msg));
173 msg->header.type = CRAS_MAIN_METRICS;
174 msg->header.length = sizeof(*msg);
175 msg->metrics_type = type;
176 msg->data = data;
177 }
178
179 static void handle_metrics_message(struct cras_main_message *msg, void *arg);
180
181 /* The wrapper function of cras_main_message_send. */
cras_server_metrics_message_send(struct cras_main_message * msg)182 static int cras_server_metrics_message_send(struct cras_main_message *msg)
183 {
184 /* If current function is in the main thread, call handler directly. */
185 if (cras_system_state_in_main_thread()) {
186 handle_metrics_message(msg, NULL);
187 return 0;
188 }
189 return cras_main_message_send(msg);
190 }
191
192 static inline const char *
metrics_device_type_str(enum CRAS_METRICS_DEVICE_TYPE device_type)193 metrics_device_type_str(enum CRAS_METRICS_DEVICE_TYPE device_type)
194 {
195 switch (device_type) {
196 case CRAS_METRICS_DEVICE_INTERNAL_SPEAKER:
197 return "InternalSpeaker";
198 case CRAS_METRICS_DEVICE_HEADPHONE:
199 return "Headphone";
200 case CRAS_METRICS_DEVICE_HDMI:
201 return "HDMI";
202 case CRAS_METRICS_DEVICE_HAPTIC:
203 return "Haptic";
204 case CRAS_METRICS_DEVICE_LINEOUT:
205 return "Lineout";
206 /* Input devices. */
207 case CRAS_METRICS_DEVICE_INTERNAL_MIC:
208 return "InternalMic";
209 case CRAS_METRICS_DEVICE_FRONT_MIC:
210 return "FrontMic";
211 case CRAS_METRICS_DEVICE_REAR_MIC:
212 return "RearMic";
213 case CRAS_METRICS_DEVICE_KEYBOARD_MIC:
214 return "KeyboardMic";
215 case CRAS_METRICS_DEVICE_MIC:
216 return "Mic";
217 case CRAS_METRICS_DEVICE_HOTWORD:
218 return "Hotword";
219 case CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK:
220 return "PostMixLoopback";
221 case CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK:
222 return "PostDspLoopback";
223 /* Devices supporting input and output function. */
224 case CRAS_METRICS_DEVICE_USB:
225 return "USB";
226 case CRAS_METRICS_DEVICE_A2DP:
227 return "A2DP";
228 case CRAS_METRICS_DEVICE_HFP:
229 return "HFP";
230 case CRAS_METRICS_DEVICE_HSP:
231 return "HSP";
232 case CRAS_METRICS_DEVICE_BLUETOOTH:
233 return "Bluetooth";
234 case CRAS_METRICS_DEVICE_NO_DEVICE:
235 return "NoDevice";
236 /* Other dummy devices. */
237 case CRAS_METRICS_DEVICE_NORMAL_FALLBACK:
238 return "NormalFallback";
239 case CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK:
240 return "AbnormalFallback";
241 case CRAS_METRICS_DEVICE_SILENT_HOTWORD:
242 return "SilentHotword";
243 case CRAS_METRICS_DEVICE_UNKNOWN:
244 return "Unknown";
245 default:
246 return "InvalidType";
247 }
248 }
249
250 static enum CRAS_METRICS_DEVICE_TYPE
get_metrics_device_type(struct cras_iodev * iodev)251 get_metrics_device_type(struct cras_iodev *iodev)
252 {
253 /* Check whether it is a special device. */
254 if (iodev->info.idx < MAX_SPECIAL_DEVICE_IDX) {
255 switch (iodev->info.idx) {
256 case NO_DEVICE:
257 syslog(LOG_ERR, "The invalid device has been used.");
258 return CRAS_METRICS_DEVICE_NO_DEVICE;
259 case SILENT_RECORD_DEVICE:
260 case SILENT_PLAYBACK_DEVICE:
261 if (iodev->active_node->type ==
262 CRAS_NODE_TYPE_FALLBACK_NORMAL)
263 return CRAS_METRICS_DEVICE_NORMAL_FALLBACK;
264 else
265 return CRAS_METRICS_DEVICE_ABNORMAL_FALLBACK;
266 case SILENT_HOTWORD_DEVICE:
267 return CRAS_METRICS_DEVICE_SILENT_HOTWORD;
268 }
269 }
270
271 switch (iodev->active_node->type) {
272 case CRAS_NODE_TYPE_INTERNAL_SPEAKER:
273 return CRAS_METRICS_DEVICE_INTERNAL_SPEAKER;
274 case CRAS_NODE_TYPE_HEADPHONE:
275 return CRAS_METRICS_DEVICE_HEADPHONE;
276 case CRAS_NODE_TYPE_HDMI:
277 return CRAS_METRICS_DEVICE_HDMI;
278 case CRAS_NODE_TYPE_HAPTIC:
279 return CRAS_METRICS_DEVICE_HAPTIC;
280 case CRAS_NODE_TYPE_LINEOUT:
281 return CRAS_METRICS_DEVICE_LINEOUT;
282 case CRAS_NODE_TYPE_MIC:
283 switch (iodev->active_node->position) {
284 case NODE_POSITION_INTERNAL:
285 return CRAS_METRICS_DEVICE_INTERNAL_MIC;
286 case NODE_POSITION_FRONT:
287 return CRAS_METRICS_DEVICE_FRONT_MIC;
288 case NODE_POSITION_REAR:
289 return CRAS_METRICS_DEVICE_REAR_MIC;
290 case NODE_POSITION_KEYBOARD:
291 return CRAS_METRICS_DEVICE_KEYBOARD_MIC;
292 case NODE_POSITION_EXTERNAL:
293 default:
294 return CRAS_METRICS_DEVICE_MIC;
295 }
296 case CRAS_NODE_TYPE_HOTWORD:
297 return CRAS_METRICS_DEVICE_HOTWORD;
298 case CRAS_NODE_TYPE_POST_MIX_PRE_DSP:
299 return CRAS_METRICS_DEVICE_POST_MIX_LOOPBACK;
300 case CRAS_NODE_TYPE_POST_DSP:
301 return CRAS_METRICS_DEVICE_POST_DSP_LOOPBACK;
302 case CRAS_NODE_TYPE_USB:
303 return CRAS_METRICS_DEVICE_USB;
304 case CRAS_NODE_TYPE_BLUETOOTH:
305 #ifdef CRAS_DBUS
306 if (cras_bt_io_on_profile(iodev,
307 CRAS_BT_DEVICE_PROFILE_A2DP_SOURCE))
308 return CRAS_METRICS_DEVICE_A2DP;
309 if (cras_bt_io_on_profile(
310 iodev, CRAS_BT_DEVICE_PROFILE_HFP_AUDIOGATEWAY))
311 return CRAS_METRICS_DEVICE_HFP;
312 if (cras_bt_io_on_profile(
313 iodev, CRAS_BT_DEVICE_PROFILE_HSP_AUDIOGATEWAY))
314 return CRAS_METRICS_DEVICE_HSP;
315 #endif
316 return CRAS_METRICS_DEVICE_BLUETOOTH;
317 case CRAS_NODE_TYPE_UNKNOWN:
318 default:
319 return CRAS_METRICS_DEVICE_UNKNOWN;
320 }
321 }
322
cras_server_metrics_hfp_packet_loss(float packet_loss_ratio)323 int cras_server_metrics_hfp_packet_loss(float packet_loss_ratio)
324 {
325 struct cras_server_metrics_message msg;
326 union cras_server_metrics_data data;
327 int err;
328
329 /* Percentage is too coarse for packet loss, so we use number of bad
330 * packets per thousand packets instead. */
331 data.value = (unsigned)(round(packet_loss_ratio * 1000));
332 init_server_metrics_msg(&msg, BT_WIDEBAND_PACKET_LOSS, data);
333
334 err = cras_server_metrics_message_send(
335 (struct cras_main_message *)&msg);
336 if (err < 0) {
337 syslog(LOG_ERR,
338 "Failed to send metrics message: BT_WIDEBAND_PACKET_LOSS");
339 return err;
340 }
341 return 0;
342 }
343
cras_server_metrics_hfp_wideband_support(bool supported)344 int cras_server_metrics_hfp_wideband_support(bool supported)
345 {
346 struct cras_server_metrics_message msg;
347 union cras_server_metrics_data data;
348 int err;
349
350 data.value = supported;
351 init_server_metrics_msg(&msg, BT_WIDEBAND_SUPPORTED, data);
352
353 err = cras_server_metrics_message_send(
354 (struct cras_main_message *)&msg);
355 if (err < 0) {
356 syslog(LOG_ERR,
357 "Failed to send metrics message: BT_WIDEBAND_SUPPORTED");
358 return err;
359 }
360 return 0;
361 }
362
cras_server_metrics_device_runtime(struct cras_iodev * iodev)363 int cras_server_metrics_device_runtime(struct cras_iodev *iodev)
364 {
365 struct cras_server_metrics_message msg;
366 union cras_server_metrics_data data;
367 struct timespec now;
368 int err;
369
370 data.device_data.type = get_metrics_device_type(iodev);
371 data.device_data.direction = iodev->direction;
372 clock_gettime(CLOCK_MONOTONIC_RAW, &now);
373 subtract_timespecs(&now, &iodev->open_ts, &data.device_data.runtime);
374
375 init_server_metrics_msg(&msg, DEVICE_RUNTIME, data);
376
377 err = cras_server_metrics_message_send(
378 (struct cras_main_message *)&msg);
379 if (err < 0) {
380 syslog(LOG_ERR,
381 "Failed to send metrics message: DEVICE_RUNTIME");
382 return err;
383 }
384
385 return 0;
386 }
387
cras_server_metrics_highest_device_delay(unsigned int hw_level,unsigned int largest_cb_level,enum CRAS_STREAM_DIRECTION direction)388 int cras_server_metrics_highest_device_delay(
389 unsigned int hw_level, unsigned int largest_cb_level,
390 enum CRAS_STREAM_DIRECTION direction)
391 {
392 struct cras_server_metrics_message msg;
393 union cras_server_metrics_data data;
394 int err;
395
396 if (largest_cb_level == 0) {
397 syslog(LOG_ERR,
398 "Failed to record device delay: devided by zero");
399 return -1;
400 }
401
402 /*
403 * Because the latency depends on the callback threshold of streams, it
404 * should be calculated as dividing the highest hardware level by largest
405 * callback threshold of streams. For output device, this value should fall
406 * around 2 because CRAS 's scheduling maintain device buffer level around
407 * 1~2 minimum callback level. For input device, this value should be around
408 * 1 because the device buffer level is around 0~1 minimum callback level.
409 * Besides, UMA cannot record float so this ratio is multiplied by 1000.
410 */
411 data.value = hw_level * 1000 / largest_cb_level;
412
413 switch (direction) {
414 case CRAS_STREAM_INPUT:
415 init_server_metrics_msg(&msg, HIGHEST_DEVICE_DELAY_INPUT, data);
416 break;
417 case CRAS_STREAM_OUTPUT:
418 init_server_metrics_msg(&msg, HIGHEST_DEVICE_DELAY_OUTPUT,
419 data);
420 break;
421 default:
422 return 0;
423 }
424
425 err = cras_server_metrics_message_send(
426 (struct cras_main_message *)&msg);
427 if (err < 0) {
428 syslog(LOG_ERR,
429 "Failed to send metrics message: HIGHEST_DEVICE_DELAY");
430 return err;
431 }
432
433 return 0;
434 }
435
cras_server_metrics_highest_hw_level(unsigned hw_level,enum CRAS_STREAM_DIRECTION direction)436 int cras_server_metrics_highest_hw_level(unsigned hw_level,
437 enum CRAS_STREAM_DIRECTION direction)
438 {
439 struct cras_server_metrics_message msg;
440 union cras_server_metrics_data data;
441 int err;
442
443 data.value = hw_level;
444
445 switch (direction) {
446 case CRAS_STREAM_INPUT:
447 init_server_metrics_msg(&msg, HIGHEST_INPUT_HW_LEVEL, data);
448 break;
449 case CRAS_STREAM_OUTPUT:
450 init_server_metrics_msg(&msg, HIGHEST_OUTPUT_HW_LEVEL, data);
451 break;
452 default:
453 return 0;
454 }
455
456 err = cras_server_metrics_message_send(
457 (struct cras_main_message *)&msg);
458 if (err < 0) {
459 syslog(LOG_ERR,
460 "Failed to send metrics message: HIGHEST_HW_LEVEL");
461 return err;
462 }
463
464 return 0;
465 }
466
cras_server_metrics_longest_fetch_delay(unsigned delay_msec)467 int cras_server_metrics_longest_fetch_delay(unsigned delay_msec)
468 {
469 struct cras_server_metrics_message msg;
470 union cras_server_metrics_data data;
471 int err;
472
473 data.value = delay_msec;
474 init_server_metrics_msg(&msg, LONGEST_FETCH_DELAY, data);
475 err = cras_server_metrics_message_send(
476 (struct cras_main_message *)&msg);
477 if (err < 0) {
478 syslog(LOG_ERR,
479 "Failed to send metrics message: LONGEST_FETCH_DELAY");
480 return err;
481 }
482
483 return 0;
484 }
485
cras_server_metrics_num_underruns(unsigned num_underruns)486 int cras_server_metrics_num_underruns(unsigned num_underruns)
487 {
488 struct cras_server_metrics_message msg;
489 union cras_server_metrics_data data;
490 int err;
491
492 data.value = num_underruns;
493 init_server_metrics_msg(&msg, NUM_UNDERRUNS, data);
494 err = cras_server_metrics_message_send(
495 (struct cras_main_message *)&msg);
496 if (err < 0) {
497 syslog(LOG_ERR,
498 "Failed to send metrics message: NUM_UNDERRUNS");
499 return err;
500 }
501
502 return 0;
503 }
504
cras_server_metrics_missed_cb_frequency(const struct cras_rstream * stream)505 int cras_server_metrics_missed_cb_frequency(const struct cras_rstream *stream)
506 {
507 struct cras_server_metrics_message msg;
508 union cras_server_metrics_data data;
509 struct timespec now, time_since;
510 double seconds, frequency;
511 int err;
512
513 clock_gettime(CLOCK_MONOTONIC_RAW, &now);
514 subtract_timespecs(&now, &stream->start_ts, &time_since);
515 seconds = (double)time_since.tv_sec + time_since.tv_nsec / 1000000000.0;
516
517 /* Ignore streams which do not have enough runtime. */
518 if (seconds < MISSED_CB_FREQUENCY_SECONDS_MIN)
519 return 0;
520
521 /* Compute how many callbacks are missed in a day. */
522 frequency = (double)stream->num_missed_cb * 86400.0 / seconds;
523 data.value = (unsigned)(round(frequency) + 1e-9);
524
525 if (stream->direction == CRAS_STREAM_INPUT)
526 init_server_metrics_msg(&msg, MISSED_CB_FREQUENCY_INPUT, data);
527 else
528 init_server_metrics_msg(&msg, MISSED_CB_FREQUENCY_OUTPUT, data);
529
530 err = cras_server_metrics_message_send(
531 (struct cras_main_message *)&msg);
532 if (err < 0) {
533 syslog(LOG_ERR,
534 "Failed to send metrics message: MISSED_CB_FREQUENCY");
535 return err;
536 }
537
538 /*
539 * If missed callback happened at least once, also record frequncy after
540 * rescheduling.
541 */
542 if (!stream->num_missed_cb)
543 return 0;
544
545 subtract_timespecs(&now, &stream->first_missed_cb_ts, &time_since);
546 seconds = (double)time_since.tv_sec + time_since.tv_nsec / 1000000000.0;
547
548 /* Compute how many callbacks are missed in a day. */
549 frequency = (double)(stream->num_missed_cb - 1) * 86400.0 / seconds;
550 data.value = (unsigned)(round(frequency) + 1e-9);
551
552 if (stream->direction == CRAS_STREAM_INPUT) {
553 init_server_metrics_msg(
554 &msg, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT,
555 data);
556 } else {
557 init_server_metrics_msg(
558 &msg, MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT,
559 data);
560 }
561
562 err = cras_server_metrics_message_send(
563 (struct cras_main_message *)&msg);
564 if (err < 0) {
565 syslog(LOG_ERR,
566 "Failed to send metrics message: MISSED_CB_FREQUENCY");
567 return err;
568 }
569
570 return 0;
571 }
572
573 /*
574 * Logs the duration between stream starting time and the first missed
575 * callback.
576 */
577 static int
cras_server_metrics_missed_cb_first_time(const struct cras_rstream * stream)578 cras_server_metrics_missed_cb_first_time(const struct cras_rstream *stream)
579 {
580 struct cras_server_metrics_message msg;
581 union cras_server_metrics_data data;
582 struct timespec time_since;
583 int err;
584
585 subtract_timespecs(&stream->first_missed_cb_ts, &stream->start_ts,
586 &time_since);
587 data.value = (unsigned)time_since.tv_sec;
588
589 if (stream->direction == CRAS_STREAM_INPUT) {
590 init_server_metrics_msg(&msg, MISSED_CB_FIRST_TIME_INPUT, data);
591 } else {
592 init_server_metrics_msg(&msg, MISSED_CB_FIRST_TIME_OUTPUT,
593 data);
594 }
595 err = cras_server_metrics_message_send(
596 (struct cras_main_message *)&msg);
597 if (err < 0) {
598 syslog(LOG_ERR, "Failed to send metrics message: "
599 "MISSED_CB_FIRST_TIME");
600 return err;
601 }
602
603 return 0;
604 }
605
606 /* Logs the duration between the first and the second missed callback events. */
607 static int
cras_server_metrics_missed_cb_second_time(const struct cras_rstream * stream)608 cras_server_metrics_missed_cb_second_time(const struct cras_rstream *stream)
609 {
610 struct cras_server_metrics_message msg;
611 union cras_server_metrics_data data;
612 struct timespec now, time_since;
613 int err;
614
615 clock_gettime(CLOCK_MONOTONIC_RAW, &now);
616 subtract_timespecs(&now, &stream->first_missed_cb_ts, &time_since);
617 data.value = (unsigned)time_since.tv_sec;
618
619 if (stream->direction == CRAS_STREAM_INPUT) {
620 init_server_metrics_msg(&msg, MISSED_CB_SECOND_TIME_INPUT,
621 data);
622 } else {
623 init_server_metrics_msg(&msg, MISSED_CB_SECOND_TIME_OUTPUT,
624 data);
625 }
626 err = cras_server_metrics_message_send(
627 (struct cras_main_message *)&msg);
628 if (err < 0) {
629 syslog(LOG_ERR, "Failed to send metrics message: "
630 "MISSED_CB_SECOND_TIME");
631 return err;
632 }
633
634 return 0;
635 }
636
cras_server_metrics_missed_cb_event(struct cras_rstream * stream)637 int cras_server_metrics_missed_cb_event(struct cras_rstream *stream)
638 {
639 int rc = 0;
640
641 stream->num_missed_cb += 1;
642 if (stream->num_missed_cb == 1)
643 clock_gettime(CLOCK_MONOTONIC_RAW, &stream->first_missed_cb_ts);
644
645 /* Do not record missed cb if the stream has these flags. */
646 if (stream->flags & (BULK_AUDIO_OK | USE_DEV_TIMING | TRIGGER_ONLY))
647 return 0;
648
649 /* Only record the first and the second events. */
650 if (stream->num_missed_cb == 1)
651 rc = cras_server_metrics_missed_cb_first_time(stream);
652 else if (stream->num_missed_cb == 2)
653 rc = cras_server_metrics_missed_cb_second_time(stream);
654
655 return rc;
656 }
657
cras_server_metrics_stream_config(struct cras_rstream_config * config)658 int cras_server_metrics_stream_config(struct cras_rstream_config *config)
659 {
660 struct cras_server_metrics_message msg;
661 union cras_server_metrics_data data;
662 int err;
663
664 data.stream_config.direction = config->direction;
665 data.stream_config.cb_threshold = (unsigned)config->cb_threshold;
666 data.stream_config.flags = (unsigned)config->flags;
667 data.stream_config.format = (int)config->format->format;
668 data.stream_config.rate = (unsigned)config->format->frame_rate;
669 data.stream_config.client_type = config->client_type;
670
671 init_server_metrics_msg(&msg, STREAM_CONFIG, data);
672 err = cras_server_metrics_message_send(
673 (struct cras_main_message *)&msg);
674 if (err < 0) {
675 syslog(LOG_ERR,
676 "Failed to send metrics message: STREAM_CONFIG");
677 return err;
678 }
679
680 return 0;
681 }
682
cras_server_metrics_busyloop(struct timespec * ts,unsigned count)683 int cras_server_metrics_busyloop(struct timespec *ts, unsigned count)
684 {
685 struct cras_server_metrics_message msg;
686 union cras_server_metrics_data data;
687 int err;
688
689 data.timespec_data.runtime = *ts;
690 data.timespec_data.count = count;
691
692 init_server_metrics_msg(&msg, BUSYLOOP, data);
693
694 err = cras_server_metrics_message_send(
695 (struct cras_main_message *)&msg);
696 if (err < 0) {
697 syslog(LOG_ERR, "Failed to send metrics message: BUSYLOOP");
698 return err;
699 }
700 return 0;
701 }
702
metrics_device_runtime(struct cras_server_metrics_device_data data)703 static void metrics_device_runtime(struct cras_server_metrics_device_data data)
704 {
705 char metrics_name[METRICS_NAME_BUFFER_SIZE];
706
707 snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE,
708 "Cras.%sDevice%sRuntime",
709 data.direction == CRAS_STREAM_INPUT ? "Input" : "Output",
710 metrics_device_type_str(data.type));
711 cras_metrics_log_histogram(metrics_name, (unsigned)data.runtime.tv_sec,
712 0, 10000, 20);
713
714 /* Logs the usage of each device. */
715 if (data.direction == CRAS_STREAM_INPUT)
716 cras_metrics_log_sparse_histogram(kDeviceTypeInput, data.type);
717 else
718 cras_metrics_log_sparse_histogram(kDeviceTypeOutput, data.type);
719 }
720
metrics_busyloop(struct cras_server_metrics_timespec_data data)721 static void metrics_busyloop(struct cras_server_metrics_timespec_data data)
722 {
723 char metrics_name[METRICS_NAME_BUFFER_SIZE];
724
725 snprintf(metrics_name, METRICS_NAME_BUFFER_SIZE, "%s.%s", kBusyloop,
726 get_timespec_period_str(data.runtime));
727
728 cras_metrics_log_histogram(metrics_name, data.count, 0, 1000, 20);
729 }
730
731 static void
metrics_stream_config(struct cras_server_metrics_stream_config config)732 metrics_stream_config(struct cras_server_metrics_stream_config config)
733 {
734 /* Logs stream callback threshold. */
735 cras_metrics_log_sparse_histogram(kStreamCallbackThreshold,
736 config.cb_threshold);
737
738 /* Logs stream flags. */
739 cras_metrics_log_sparse_histogram(kStreamFlags, config.flags);
740
741 /* Logs stream sampling format. */
742 cras_metrics_log_sparse_histogram(kStreamSamplingFormat, config.format);
743
744 /* Logs stream sampling rate. */
745 cras_metrics_log_sparse_histogram(kStreamSamplingRate, config.rate);
746
747 /* Logs stream client type. */
748 if (config.direction == CRAS_STREAM_INPUT)
749 cras_metrics_log_sparse_histogram(kStreamClientTypeInput,
750 config.client_type);
751 else
752 cras_metrics_log_sparse_histogram(kStreamClientTypeOutput,
753 config.client_type);
754 }
755
handle_metrics_message(struct cras_main_message * msg,void * arg)756 static void handle_metrics_message(struct cras_main_message *msg, void *arg)
757 {
758 struct cras_server_metrics_message *metrics_msg =
759 (struct cras_server_metrics_message *)msg;
760 switch (metrics_msg->metrics_type) {
761 case BT_WIDEBAND_PACKET_LOSS:
762 cras_metrics_log_histogram(kHfpWidebandSpeechPacketLoss,
763 metrics_msg->data.value, 0, 1000,
764 20);
765 break;
766 case BT_WIDEBAND_SUPPORTED:
767 cras_metrics_log_sparse_histogram(kHfpWidebandSpeechSupported,
768 metrics_msg->data.value);
769 break;
770 case DEVICE_RUNTIME:
771 metrics_device_runtime(metrics_msg->data.device_data);
772 break;
773 case HIGHEST_DEVICE_DELAY_INPUT:
774 cras_metrics_log_histogram(kHighestDeviceDelayInput,
775 metrics_msg->data.value, 1, 10000,
776 20);
777 break;
778 case HIGHEST_DEVICE_DELAY_OUTPUT:
779 cras_metrics_log_histogram(kHighestDeviceDelayOutput,
780 metrics_msg->data.value, 1, 10000,
781 20);
782 break;
783 case HIGHEST_INPUT_HW_LEVEL:
784 cras_metrics_log_histogram(kHighestInputHardwareLevel,
785 metrics_msg->data.value, 1, 10000,
786 20);
787 break;
788 case HIGHEST_OUTPUT_HW_LEVEL:
789 cras_metrics_log_histogram(kHighestOutputHardwareLevel,
790 metrics_msg->data.value, 1, 10000,
791 20);
792 break;
793 case LONGEST_FETCH_DELAY:
794 cras_metrics_log_histogram(kStreamTimeoutMilliSeconds,
795 metrics_msg->data.value, 1, 20000,
796 10);
797 break;
798 case MISSED_CB_FIRST_TIME_INPUT:
799 cras_metrics_log_histogram(kMissedCallbackFirstTimeInput,
800 metrics_msg->data.value, 0, 90000,
801 20);
802 break;
803 case MISSED_CB_FIRST_TIME_OUTPUT:
804 cras_metrics_log_histogram(kMissedCallbackFirstTimeOutput,
805 metrics_msg->data.value, 0, 90000,
806 20);
807 break;
808 case MISSED_CB_FREQUENCY_INPUT:
809 cras_metrics_log_histogram(kMissedCallbackFrequencyInput,
810 metrics_msg->data.value, 0, 90000,
811 20);
812 break;
813 case MISSED_CB_FREQUENCY_OUTPUT:
814 cras_metrics_log_histogram(kMissedCallbackFrequencyOutput,
815 metrics_msg->data.value, 0, 90000,
816 20);
817 break;
818 case MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_INPUT:
819 cras_metrics_log_histogram(
820 kMissedCallbackFrequencyAfterReschedulingInput,
821 metrics_msg->data.value, 0, 90000, 20);
822 break;
823 case MISSED_CB_FREQUENCY_AFTER_RESCHEDULING_OUTPUT:
824 cras_metrics_log_histogram(
825 kMissedCallbackFrequencyAfterReschedulingOutput,
826 metrics_msg->data.value, 0, 90000, 20);
827 break;
828 case MISSED_CB_SECOND_TIME_INPUT:
829 cras_metrics_log_histogram(kMissedCallbackSecondTimeInput,
830 metrics_msg->data.value, 0, 90000,
831 20);
832 break;
833 case MISSED_CB_SECOND_TIME_OUTPUT:
834 cras_metrics_log_histogram(kMissedCallbackSecondTimeOutput,
835 metrics_msg->data.value, 0, 90000,
836 20);
837 break;
838 case NUM_UNDERRUNS:
839 cras_metrics_log_histogram(kUnderrunsPerDevice,
840 metrics_msg->data.value, 0, 1000,
841 10);
842 break;
843 case STREAM_CONFIG:
844 metrics_stream_config(metrics_msg->data.stream_config);
845 break;
846 case BUSYLOOP:
847 metrics_busyloop(metrics_msg->data.timespec_data);
848 break;
849 default:
850 syslog(LOG_ERR, "Unknown metrics type %u",
851 metrics_msg->metrics_type);
852 break;
853 }
854 }
855
cras_server_metrics_init()856 int cras_server_metrics_init()
857 {
858 cras_main_message_add_handler(CRAS_MAIN_METRICS, handle_metrics_message,
859 NULL);
860 return 0;
861 }
862