From c0d6fd27ff4c6cfa57303a37bc452f87c56e0b6c Mon Sep 17 00:00:00 2001 From: Pau Espin Pedrol Date: Thu, 9 Jul 2020 16:51:47 +0200 Subject: [PATCH] Introduce rate counters to detect issues in received Dl bursts from TRXD This ones together with rate counters already available in lower layers allows to understand better the source of the problem with stalled tx bursts. Change-Id: Ia34f7e7d780ad1e12f24638a07f05fe91f2afea5 --- CommonLibs/osmo_signal.h | 3 ++ CommonLibs/trx_rate_ctr.cpp | 12 +++++++ CommonLibs/trx_rate_ctr.h | 3 ++ CommonLibs/trx_vty.c | 8 +++-- Transceiver52M/Transceiver.cpp | 59 +++++++++++++++++++++++++++++----- Transceiver52M/Transceiver.h | 5 +++ 6 files changed, 80 insertions(+), 10 deletions(-) diff --git a/CommonLibs/osmo_signal.h b/CommonLibs/osmo_signal.h index de17b1d7..5cd90c6a 100644 --- a/CommonLibs/osmo_signal.h +++ b/CommonLibs/osmo_signal.h @@ -61,4 +61,7 @@ struct device_counters { struct trx_counters { size_t chan; unsigned int tx_stale_bursts; /* Amount of Tx bursts dropped to to arriving too late from TRXD */ + unsigned int tx_trxd_fn_repeated; + unsigned int tx_trxd_fn_outoforder; + unsigned int tx_trxd_fn_skipped; }; diff --git a/CommonLibs/trx_rate_ctr.cpp b/CommonLibs/trx_rate_ctr.cpp index 6391a382..8b2597d6 100644 --- a/CommonLibs/trx_rate_ctr.cpp +++ b/CommonLibs/trx_rate_ctr.cpp @@ -103,6 +103,9 @@ const struct value_string trx_chan_ctr_names[] = { { 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_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" }, { 0, NULL } }; @@ -114,6 +117,9 @@ static const struct rate_ctr_desc trx_chan_ctr_desc[] = { [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_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" }, }; static const struct rate_ctr_group_desc trx_chan_ctr_group_desc = { @@ -166,6 +172,12 @@ static int trx_rate_ctr_timerfd_cb(struct osmo_fd *ofd, unsigned int what) { LOGCHAN(chan, DMAIN, INFO) << "rate_ctr update"; ctr = &rate_ctrs[chan]->ctr[TRX_CTR_TRX_TX_STALE_BURSTS]; rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_stale_bursts - ctr->current); + ctr = &rate_ctrs[chan]->ctr[TRX_CTR_TRX_TRXD_FN_REPEATED]; + rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_repeated - ctr->current); + ctr = &rate_ctrs[chan]->ctr[TRX_CTR_TRX_TRXD_FN_OUTOFORDER]; + rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_outoforder - ctr->current); + ctr = &rate_ctrs[chan]->ctr[TRX_CTR_TRX_TRXD_FN_SKIPPED]; + rate_ctr_add(ctr, trx_ctrs_pending[chan].tx_trxd_fn_skipped - ctr->current); /* Mark as done */ trx_ctrs_pending[chan].chan = PENDING_CHAN_NONE; } diff --git a/CommonLibs/trx_rate_ctr.h b/CommonLibs/trx_rate_ctr.h index 588ac2f0..cef3c21f 100644 --- a/CommonLibs/trx_rate_ctr.h +++ b/CommonLibs/trx_rate_ctr.h @@ -11,6 +11,9 @@ enum TrxCtr { TRX_CTR_DEV_TX_DROP_EV, TRX_CTR_DEV_TX_DROP_SMPL, TRX_CTR_TRX_TX_STALE_BURSTS, + TRX_CTR_TRX_TRXD_FN_REPEATED, + TRX_CTR_TRX_TRXD_FN_OUTOFORDER, + TRX_CTR_TRX_TRXD_FN_SKIPPED, }; struct ctr_threshold { diff --git a/CommonLibs/trx_vty.c b/CommonLibs/trx_vty.c index f085d098..941a4354 100644 --- a/CommonLibs/trx_vty.c +++ b/CommonLibs/trx_vty.c @@ -390,7 +390,7 @@ static int vty_intv_name_2_id(const char* str) { return -1; } -#define THRESHOLD_ARGS "(rx_overruns|tx_underruns|rx_drop_events|rx_drop_samples|tx_drop_events|tx_drop_samples|tx_stale_bursts)" +#define THRESHOLD_ARGS "(rx_overruns|tx_underruns|rx_drop_events|rx_drop_samples|tx_drop_events|tx_drop_samples|tx_stale_bursts|tx_trxd_fn_repeated|tx_trxd_fn_outoforder|tx_trxd_fn_skipped)" #define THRESHOLD_STR_VAL(s) "Set threshold value for rate_ctr device:" OSMO_STRINGIFY_VAL(s) "\n" #define THRESHOLD_STRS \ THRESHOLD_STR_VAL(rx_overruns) \ @@ -399,7 +399,11 @@ static int vty_intv_name_2_id(const char* str) { THRESHOLD_STR_VAL(rx_drop_samples) \ THRESHOLD_STR_VAL(tx_drop_events) \ THRESHOLD_STR_VAL(tx_drop_samples) \ - THRESHOLD_STR_VAL(tx_stale_bursts) + THRESHOLD_STR_VAL(tx_stale_bursts) \ + THRESHOLD_STR_VAL(tx_trxd_fn_repeated) \ + THRESHOLD_STR_VAL(tx_trxd_fn_outoforder) \ + THRESHOLD_STR_VAL(tx_trxd_fn_skipped) \ + "" #define INTV_ARGS "(per-second|per-minute|per-hour|per-day)" #define INTV_STR_VAL(s) "Threshold value sampled " OSMO_STRINGIFY_VAL(s) "\n" #define INTV_STRS \ diff --git a/Transceiver52M/Transceiver.cpp b/Transceiver52M/Transceiver.cpp index 2ae5eda7..d45a28bc 100644 --- a/Transceiver52M/Transceiver.cpp +++ b/Transceiver52M/Transceiver.cpp @@ -52,6 +52,14 @@ Transceiver *transceiver; /* Number of running values use in noise average */ #define NOISE_CNT 20 + +static void dispatch_trx_rate_ctr_change(TransceiverState *state, unsigned int chan) { + thread_enable_cancel(false); + state->ctrs.chan = chan; + osmo_signal_dispatch(SS_DEVICE, S_TRX_COUNTER_CHANGE, &state->ctrs); + thread_enable_cancel(true); +} + TransceiverState::TransceiverState() : mRetrans(false), mNoiseLev(0.0), mNoises(NOISE_CNT), mPower(0.0) { @@ -87,6 +95,8 @@ bool TransceiverState::init(FillerType filler, size_t sps, float scale, size_t r if ((sps != 1) && (sps != 4)) return false; + mFiller = filler; + for (size_t n = 0; n < 8; n++) { for (size_t i = 0; i < 102; i++) { switch (filler) { @@ -437,12 +447,8 @@ void Transceiver::pushRadioVector(GSM::Time &nowTime) delete burst; } - if (stale_bursts_changed) { - thread_enable_cancel(false); - state->ctrs.chan = i; - osmo_signal_dispatch(SS_DEVICE, S_TRX_COUNTER_CHANGE, &state->ctrs); - thread_enable_cancel(true); - } + if (stale_bursts_changed) + dispatch_trx_rate_ctr_change(state, i); TN = nowTime.TN(); modFN = nowTime.FN() % state->fillerModulus[TN]; @@ -1001,6 +1007,7 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) struct trxd_hdr_v01_dl *dl; char buffer[sizeof(*dl) + EDGE_BURST_NBITS]; uint32_t fn; + uint8_t tn; // check data socket msgLen = read(mDataSockets[chan], buffer, sizeof(buffer)); @@ -1029,6 +1036,7 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) /* Convert TDMA FN to the host endianness */ fn = osmo_load32be(&dl->common.fn); + tn = dl->common.tn; /* Make sure we support the received header format */ switch (dl->common.version) { @@ -1044,14 +1052,49 @@ bool Transceiver::driveTxPriorityQueue(size_t chan) LOGCHAN(chan, DTRXDDL, DEBUG) << "Rx TRXD message (hdr_ver=" << unsigned(dl->common.version) << "): fn=" << fn << ", tn=" << unsigned(dl->common.tn) << ", burst_len=" << burstLen; + TransceiverState *state = &mStates[chan]; + GSM::Time currTime = GSM::Time(fn, tn); + + /* Verify proper FN order in DL stream */ + if (state->first_dl_fn_rcv[tn]) { + int32_t delta = GSM::FNDelta(currTime.FN(), state->last_dl_time_rcv[tn].FN()); + if (delta == 1) { + /* usual expected scenario, continue code flow */ + } else if (delta == 0) { + LOGCHAN(chan, DTRXDDL, NOTICE) << "Rx TRXD msg with repeated FN " << currTime; + state->ctrs.tx_trxd_fn_repeated++; + dispatch_trx_rate_ctr_change(state, chan); + return true; + } else if (delta < 0) { + LOGCHAN(chan, DTRXDDL, NOTICE) << "Rx TRXD msg with previous FN " << currTime + << " vs last " << state->last_dl_time_rcv[tn]; + state->ctrs.tx_trxd_fn_outoforder++; + dispatch_trx_rate_ctr_change(state, chan); + /* Allow adding radio vector below, since it gets sorted in the queue */ + } else if (chan == 0 && state->mFiller == FILLER_ZERO) { + /* delta > 1. Some FN was lost in the middle. We can only easily rely + * on consecutive FNs in TRX0 since it must transmit continuously in all + * setups. Also, osmo-trx supports optionally filling empty bursts on + * its own. In that case bts-trx is not obliged to submit all bursts. */ + LOGCHAN(chan, DTRXDDL, NOTICE) << "Rx TRXD msg with future FN " << currTime + << " vs last " << state->last_dl_time_rcv[tn] + << ", " << delta - 1 << " FN lost"; + state->ctrs.tx_trxd_fn_skipped += delta - 1; + dispatch_trx_rate_ctr_change(state, chan); + } + if (delta > 0) + state->last_dl_time_rcv[tn] = currTime; + } else { /* Initial check, simply store state */ + state->first_dl_fn_rcv[tn] = true; + state->last_dl_time_rcv[tn] = currTime; + } + BitVector newBurst(burstLen); BitVector::iterator itr = newBurst.begin(); uint8_t *bufferItr = dl->soft_bits; while (itr < newBurst.end()) *itr++ = *bufferItr++; - GSM::Time currTime = GSM::Time(fn, dl->common.tn); - addRadioVector(chan, newBurst, dl->tx_att, currTime); return true; diff --git a/Transceiver52M/Transceiver.h b/Transceiver52M/Transceiver.h index 7ce5fa20..39298aae 100644 --- a/Transceiver52M/Transceiver.h +++ b/Transceiver52M/Transceiver.h @@ -63,6 +63,7 @@ struct TransceiverState { /* The filler table */ signalVector *fillerTable[102][8]; int fillerModulus[8]; + FillerType mFiller; bool mRetrans; /* Most recent channel estimate of all timeslots */ @@ -86,6 +87,10 @@ struct TransceiverState { /* counters */ struct trx_counters ctrs; + + /* Used to keep track of lost and out of order frames */ + bool first_dl_fn_rcv[8]; + GSM::Time last_dl_time_rcv[8]; }; /** The Transceiver class, responsible for physical layer of basestation */