/* * Copyright (C) 2019 sysmocom - s.f.m.c. GmbH * All Rights Reserved * * SPDX-License-Identifier: AGPL-3.0+ * * Author: Pau Espin Pedrol * * This program is free software: you can redistribute it and/or modify * it under the terms of the GNU Affero General Public License as published by * the Free Software Foundation, either version 3 of the License, or * (at your option) any later version. * * This program is distributed in the hope that it will be useful, * but WITHOUT ANY WARRANTY; without even the implied warranty of * MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the * GNU Affero General Public License for more details. * * You should have received a copy of the GNU Affero General Public License * along with this program. If not, see . * See the COPYING file in the main directory for details. */ /* * rate_ctr API uses several osmocom select loop features, and as a result, * calls to it must be done through the main thread (the one running the osmocom * loop in osmo-trx). * Since read/write from/to SDR is done in separate threads (even read and write * each use a different thread), we must use some sort of message passing system * between main thread feeding rate_ctr structures and the Rx/Tx threads * generating the events. * The idea is that upon read/write issues, lower layers (SDR APIs) provide us with * underrun/overrun/droppedPackets information, and in that case we pass that up * the stack through signal with signal_cb * being a pointer to a "struct device_counters" structure, which contains * device (implementation agnostic) statful counters for different kind of * statistics. * That signal is processed here in device_sig_cb, where a copy of the "struct * device_counters" structure is held and the main thread is instructed through * a timerfd to update rate_ctr APIs against this copy. All this is done inside * a mutex to avoid different race conditions (between Rx andTx threads, and * between Rx/Tx and main thread). For the same reason, callers of signal * (device_sig_cb), that is Rx/Tx threads, * must do so with PTHREAD_CANCEL_DISABLE, in order to avoid possible deadlocks * in case the main thread decides to cancel other threads due to a shutdown * operation (fi SIGKILL received) */ #include #include #include #include #include extern "C" { #include #include #include #include #include #include #include "osmo_signal.h" #include "trx_vty.h" #include "trx_rate_ctr.h" } #include "Threads.h" #include "Logger.h" /* Used in dev_ctrs_pending, when set it means that channel slot contains unused (non-pending) counter data */ #define PENDING_CHAN_NONE SIZE_MAX static void *trx_rate_ctr_ctx; static struct rate_ctr_group** rate_ctrs; static struct device_counters* dev_ctrs_pending; static struct trx_counters* trx_ctrs_pending; static size_t chan_len; static struct osmo_fd dev_rate_ctr_timerfd; static struct osmo_fd trx_rate_ctr_timerfd; static Mutex dev_rate_ctr_mutex; static Mutex trx_rate_ctr_mutex; struct osmo_timer_list threshold_timer; static LLIST_HEAD(threshold_list); static unsigned int threshold_timer_sched_secs; static bool threshold_initied; const struct value_string rate_ctr_intv[] = { { RATE_CTR_INTV_SEC, "per-second" }, { RATE_CTR_INTV_MIN, "per-minute" }, { RATE_CTR_INTV_HOUR, "per-hour" }, { RATE_CTR_INTV_DAY, "per-day" }, { 0, NULL } }; const struct value_string trx_chan_ctr_names[] = { { TRX_CTR_DEV_RX_OVERRUNS, "rx_overruns" }, { TRX_CTR_DEV_TX_UNDERRUNS, "tx_underruns" }, { TRX_CTR_DEV_RX_DROP_EV, "rx_drop_events" }, { TRX_CTR_DEV_RX_DROP_SMPL, "rx_drop_samples" }, { TRX_CTR_DEV_TX_DROP_EV, "tx_drop_events" }, { TRX_CTR_DEV_TX_DROP_SMPL, "tx_drop_samples" }, { TRX_CTR_TRX_TX_STALE_BURSTS, "tx_stale_bursts" }, { TRX_CTR_TRX_TX_UNAVAILABLE_BURSTS, "tx_unavailable_bursts" }, { TRX_CTR_TRX_TRXD_FN_REPEATED, "tx_trxd_fn_repeated" }, { TRX_CTR_TRX_TRXD_FN_OUTOFORDER, "tx_trxd_fn_outoforder" }, { TRX_CTR_TRX_TRXD_FN_SKIPPED, "tx_trxd_fn_skipped" }, { TRX_CTR_TRX_RX_EMPTY_BURST, "rx_empty_burst" }, { TRX_CTR_TRX_RX_CLIPPING, "rx_clipping" }, { TRX_CTR_TRX_RX_NO_BURST_DETECTED, "rx_no_burst_detected" }, { 0, NULL } }; static const struct rate_ctr_desc trx_chan_ctr_desc[] = { [TRX_CTR_DEV_RX_OVERRUNS] = { "device:rx_overruns", "Number of Rx overruns in FIFO queue" }, [TRX_CTR_DEV_TX_UNDERRUNS] = { "device:tx_underruns", "Number of Tx underruns in FIFO queue" }, [TRX_CTR_DEV_RX_DROP_EV] = { "device:rx_drop_events", "Number of times Rx samples were dropped by HW" }, [TRX_CTR_DEV_RX_DROP_SMPL] = { "device:rx_drop_samples", "Number of Rx samples dropped by HW" }, [TRX_CTR_DEV_TX_DROP_EV] = { "device:tx_drop_events", "Number of times Tx samples were dropped by HW" }, [TRX_CTR_DEV_TX_DROP_SMPL] = { "device:tx_drop_samples", "Number of Tx samples dropped by HW" }, [TRX_CTR_TRX_TX_STALE_BURSTS] = { "trx:tx_stale_bursts", "Number of Tx burts dropped by TRX due to arriving too late" }, [TRX_CTR_TRX_TX_UNAVAILABLE_BURSTS] = { "trx:tx_unavailable_bursts","Number of Tx burts unavailable (not enqueued) at the time they should be transmitted" }, [TRX_CTR_TRX_TRXD_FN_REPEATED] = { "trx:tx_trxd_fn_repeated", "Number of Tx burts received from TRXD with repeated FN" }, [TRX_CTR_TRX_TRXD_FN_OUTOFORDER] = { "trx:tx_trxd_fn_outoforder","Number of Tx burts received from TRXD with a past FN" }, [TRX_CTR_TRX_TRXD_FN_SKIPPED] = { "trx:tx_trxd_fn_skipped", "Number of Tx burts potentially skipped due to FN jumps" }, [TRX_CTR_TRX_RX_EMPTY_BURST] = { "trx:rx_empty_burst", "Number of Rx bursts empty" }, [TRX_CTR_TRX_RX_CLIPPING] = { "trx:rx_clipping", "Number of Rx bursts discarded due to clipping" }, [TRX_CTR_TRX_RX_NO_BURST_DETECTED] = { "trx:rx_no_burst_detected", "Number of Rx burts discarded due to burst detection error" }, }; static const struct rate_ctr_group_desc trx_chan_ctr_group_desc = { .group_name_prefix = "trx:chan", .group_description = "osmo-trx statistics", .class_id = OSMO_STATS_CLASS_GLOBAL, .num_ctr = ARRAY_SIZE(trx_chan_ctr_desc), .ctr_desc = trx_chan_ctr_desc, }; static int dev_rate_ctr_timerfd_cb(struct osmo_fd *ofd, unsigned int what) { size_t chan; struct rate_ctr *ctr; LOGC(DCTR, INFO) << "Main thread is updating Device counters"; dev_rate_ctr_mutex.lock(); for (chan = 0; chan < chan_len; chan++) { if (dev_ctrs_pending[chan].chan == PENDING_CHAN_NONE) continue; LOGCHAN(chan, DCTR, DEBUG) << "rate_ctr update"; ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_RX_OVERRUNS); rate_ctr_add(ctr, dev_ctrs_pending[chan].rx_overruns - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_TX_UNDERRUNS); rate_ctr_add(ctr, dev_ctrs_pending[chan].tx_underruns - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_RX_DROP_EV); rate_ctr_add(ctr, dev_ctrs_pending[chan].rx_dropped_events - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_RX_DROP_SMPL); rate_ctr_add(ctr, dev_ctrs_pending[chan].rx_dropped_samples - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_TX_DROP_EV); rate_ctr_add(ctr, dev_ctrs_pending[chan].tx_dropped_events - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_DEV_TX_DROP_SMPL); rate_ctr_add(ctr, dev_ctrs_pending[chan].tx_dropped_samples - ctr->current); /* Mark as done */ dev_ctrs_pending[chan].chan = PENDING_CHAN_NONE; } if (osmo_timerfd_disable(&dev_rate_ctr_timerfd) < 0) LOGC(DCTR, ERROR) << "Failed to disable timerfd"; dev_rate_ctr_mutex.unlock(); return 0; } static int trx_rate_ctr_timerfd_cb(struct osmo_fd *ofd, unsigned int what) { size_t chan; struct rate_ctr *ctr; LOGC(DCTR, INFO) << "Main thread is updating Transceiver counters"; trx_rate_ctr_mutex.lock(); for (chan = 0; chan < chan_len; chan++) { if (trx_ctrs_pending[chan].chan == PENDING_CHAN_NONE) continue; LOGCHAN(chan, DCTR, DEBUG) << "rate_ctr update"; ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_TX_STALE_BURSTS); rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_stale_bursts - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_TX_UNAVAILABLE_BURSTS); rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_unavailable_bursts - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_TRXD_FN_REPEATED); rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_repeated - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_TRXD_FN_OUTOFORDER); rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_outoforder - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_TRXD_FN_SKIPPED); rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_skipped - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_RX_EMPTY_BURST); rate_ctr_add(ctr, trx_ctrs_pending[chan].rx_empty_burst - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_RX_CLIPPING); rate_ctr_add(ctr, trx_ctrs_pending[chan].rx_clipping - ctr->current); ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], TRX_CTR_TRX_RX_NO_BURST_DETECTED); rate_ctr_add(ctr, trx_ctrs_pending[chan].rx_no_burst_detected - ctr->current); /* Mark as done */ trx_ctrs_pending[chan].chan = PENDING_CHAN_NONE; } if (osmo_timerfd_disable(&trx_rate_ctr_timerfd) < 0) LOGC(DCTR, ERROR) << "Failed to disable timerfd"; trx_rate_ctr_mutex.unlock(); return 0; } /* Callback function to be called every time we receive a signal from DEVICE */ static int device_sig_cb(unsigned int subsys, unsigned int signal, void *handler_data, void *signal_data) { struct device_counters *dev_ctr; struct trx_counters *trx_ctr; /* Delay sched around 20 ms, in case we receive several calls from several * channels batched */ struct timespec next_sched = {.tv_sec = 0, .tv_nsec = 20*1000*1000}; /* no automatic re-trigger */ struct timespec intv_sched = {.tv_sec = 0, .tv_nsec = 0}; char err_buf[256]; switch (signal) { case S_DEVICE_COUNTER_CHANGE: dev_ctr = (struct device_counters *)signal_data; LOGCHAN(dev_ctr->chan, DCTR, INFO) << "Received counter change from radioDevice"; dev_rate_ctr_mutex.lock(); dev_ctrs_pending[dev_ctr->chan] = *dev_ctr; if (osmo_timerfd_schedule(&dev_rate_ctr_timerfd, &next_sched, &intv_sched) < 0) { LOGC(DCTR, ERROR) << "Failed to schedule timerfd: " << errno << " = "<< strerror_r(errno, err_buf, sizeof(err_buf)); } dev_rate_ctr_mutex.unlock(); break; case S_TRX_COUNTER_CHANGE: trx_ctr = (struct trx_counters *)signal_data; LOGCHAN(trx_ctr->chan, DCTR, INFO) << "Received counter change from Transceiver"; trx_rate_ctr_mutex.lock(); trx_ctrs_pending[trx_ctr->chan] = *trx_ctr; if (osmo_timerfd_schedule(&trx_rate_ctr_timerfd, &next_sched, &intv_sched) < 0) { LOGC(DCTR, ERROR) << "Failed to schedule timerfd: " << errno << " = "<< strerror_r(errno, err_buf, sizeof(err_buf)); } trx_rate_ctr_mutex.unlock(); break; default: break; } return 0; } /************************************ * ctr_threshold APIs ************************************/ static const char* ctr_threshold_2_vty_str(struct ctr_threshold *ctr) { static char buf[256]; int rc = 0; rc += snprintf(buf, sizeof(buf), "ctr-error-threshold %s", get_value_string(trx_chan_ctr_names, ctr->ctr_id)); rc += snprintf(buf + rc, sizeof(buf) - rc, " %d %s", ctr->val, get_value_string(rate_ctr_intv, ctr->intv)); return buf; } static void threshold_timer_cb(void *data) { struct ctr_threshold *ctr_thr; struct rate_ctr *rate_ctr; size_t chan; LOGC(DCTR, DEBUG) << "threshold_timer_cb fired!"; llist_for_each_entry(ctr_thr, &threshold_list, list) { for (chan = 0; chan < chan_len; chan++) { rate_ctr = rate_ctr_group_get_ctr(rate_ctrs[chan], ctr_thr->ctr_id); LOGCHAN(chan, DCTR, INFO) << "checking threshold: " << ctr_threshold_2_vty_str(ctr_thr) << " ("<< rate_ctr->intv[ctr_thr->intv].rate << " vs " << ctr_thr->val << ")"; if (rate_ctr->intv[ctr_thr->intv].rate >= ctr_thr->val) { LOGCHAN(chan, DCTR, FATAL) << "threshold reached, stopping! " << ctr_threshold_2_vty_str(ctr_thr) << " ("<< rate_ctr->intv[ctr_thr->intv].rate << " vs " << ctr_thr->val << ")"; osmo_signal_dispatch(SS_MAIN, S_MAIN_STOP_REQUIRED, NULL); return; } } } osmo_timer_schedule(&threshold_timer, threshold_timer_sched_secs, 0); } static size_t ctr_threshold_2_seconds(struct ctr_threshold *ctr) { size_t mult = 0; switch (ctr->intv) { case RATE_CTR_INTV_SEC: mult = 1; break; case RATE_CTR_INTV_MIN: mult = 60; break; case RATE_CTR_INTV_HOUR: mult = 60*60; break; case RATE_CTR_INTV_DAY: mult = 60*60*24; break; default: OSMO_ASSERT(false); } return mult; } static void threshold_timer_update_intv() { struct ctr_threshold *ctr, *min_ctr; size_t secs, min_secs; /* Avoid scheduling timer until itself and other structures are prepared by trx_rate_ctr_init */ if (!threshold_initied) return; if (llist_empty(&threshold_list)) { if (osmo_timer_pending(&threshold_timer)) osmo_timer_del(&threshold_timer); return; } min_ctr = llist_first_entry(&threshold_list, struct ctr_threshold, list); min_secs = ctr_threshold_2_seconds(min_ctr); llist_for_each_entry(ctr, &threshold_list, list) { secs = ctr_threshold_2_seconds(ctr); if (min_secs > secs) min_secs = secs; } threshold_timer_sched_secs = OSMO_MAX((int)(min_secs / 2 - 1), 1); LOGC(DCTR, INFO) << "New ctr-error-threshold check interval: " << threshold_timer_sched_secs << " seconds"; osmo_timer_schedule(&threshold_timer, threshold_timer_sched_secs, 0); } /* Init rate_ctr subsystem. Expected to be called during process start by main thread before VTY is ready */ void trx_rate_ctr_init(void *ctx, struct trx_ctx* trx_ctx) { size_t i; trx_rate_ctr_ctx = ctx; chan_len = trx_ctx->cfg.num_chans; dev_ctrs_pending = (struct device_counters*) talloc_zero_size(ctx, chan_len * sizeof(struct device_counters)); trx_ctrs_pending = (struct trx_counters*) talloc_zero_size(ctx, chan_len * sizeof(struct trx_counters)); rate_ctrs = (struct rate_ctr_group**) talloc_zero_size(ctx, chan_len * sizeof(struct rate_ctr_group*)); for (i = 0; i < chan_len; i++) { dev_ctrs_pending[i].chan = PENDING_CHAN_NONE; trx_ctrs_pending[i].chan = PENDING_CHAN_NONE; rate_ctrs[i] = rate_ctr_group_alloc(ctx, &trx_chan_ctr_group_desc, i); if (!rate_ctrs[i]) { LOGCHAN(i, DCTR, ERROR) << "Failed to allocate rate ctr"; exit(1); } } dev_rate_ctr_timerfd.fd = -1; if (osmo_timerfd_setup(&dev_rate_ctr_timerfd, dev_rate_ctr_timerfd_cb, NULL) < 0) { LOGC(DCTR, ERROR) << "Failed to setup timerfd"; exit(1); } trx_rate_ctr_timerfd.fd = -1; if (osmo_timerfd_setup(&trx_rate_ctr_timerfd, trx_rate_ctr_timerfd_cb, NULL) < 0) { LOGC(DCTR, ERROR) << "Failed to setup timerfd"; exit(1); } osmo_signal_register_handler(SS_DEVICE, device_sig_cb, NULL); /* Now set up threshold checks */ threshold_initied = true; osmo_timer_setup(&threshold_timer, threshold_timer_cb, NULL); threshold_timer_update_intv(); } void trx_rate_ctr_threshold_add(struct ctr_threshold *ctr) { struct ctr_threshold *new_ctr; new_ctr = talloc_zero(trx_rate_ctr_ctx, struct ctr_threshold); *new_ctr = *ctr; LOGC(DCTR, NOTICE) << "Adding new threshold check: " << ctr_threshold_2_vty_str(new_ctr); llist_add(&new_ctr->list, &threshold_list); threshold_timer_update_intv(); } int trx_rate_ctr_threshold_del(struct ctr_threshold *del_ctr) { struct ctr_threshold *ctr; llist_for_each_entry(ctr, &threshold_list, list) { if (ctr->intv != del_ctr->intv || ctr->ctr_id != del_ctr->ctr_id || ctr->val != del_ctr->val) continue; LOGC(DCTR, NOTICE) << "Deleting threshold check: " << ctr_threshold_2_vty_str(del_ctr); llist_del(&ctr->list); talloc_free(ctr); threshold_timer_update_intv(); return 0; } return -1; } void trx_rate_ctr_threshold_write_config(struct vty *vty, char *indent_prefix) { struct ctr_threshold *ctr; llist_for_each_entry(ctr, &threshold_list, list) { vty_out(vty, "%s%s%s", indent_prefix, ctr_threshold_2_vty_str(ctr), VTY_NEWLINE); } }