Add counters for performance analysis and debug

Adds counters in EGPRSDL/UL TBF flow for Performance and
throughput analysis. Main counters includes NumRetx, MCS transmission
Total Acks/Nacks etc.

11 files changed, 88 insertions, 9 deletions

diff --git a/src/bts.cpp b/src/bts.cpp
index 02d1298..7595c6a 100644
--- a/src/bts.cpp
+++ b/src/bts.cpp
@@ -64,6 +64,7 @@ static const struct rate_ctr_desc bts_ctr_description[] = {
 	{ "rlc.resent",			"RLC Resent           "},
 	{ "rlc.restarted",		"RLC Restarted        "},
 	{ "rlc.stalled",		"RLC Stalled          "},
+	{ "rlc.ulstalled",		"RLC UlStalled        "},
 	{ "rlc.nacked",			"RLC Nacked           "},
 	{ "rlc.ass.timedout",		"RLC Assign Timeout   "},
 	{ "rlc.ass.failed",		"RLC Assign Failed    "},
@@ -73,13 +74,20 @@ static const struct rate_ctr_desc bts_ctr_description[] = {
 	{ "rlc.late-block",		"RLC Late Block       "},
 	{ "rlc.sent-dummy",		"RLC Sent Dummy       "},
 	{ "rlc.sent-control",		"RLC Sent Control     "},
+	{ "rlc.dl_bytes",		"RLC DL Bytes         "},
+	{ "rlc.dl_payload_bytes",	"RLC DL Payload Bytes "},
+	{ "rlc.ul_bytes",		"RLC UL Bytes         "},
+	{ "rlc.ul_payload_bytes",	"RLC UL Payload Bytes "},
 	{ "decode.errors",		"Decode Errors        "},
+	{ "llc_decode.err",		"llc Decode Errors    "},
 	{ "sba.allocated",		"SBA Allocated        "},
 	{ "sba.freed",			"SBA Freed            "},
 	{ "sba.timedout",		"SBA Timeout          "},
 	{ "llc.timeout",		"Timedout Frames      "},
 	{ "llc.dropped",		"Dropped Frames       "},
 	{ "llc.scheduled",		"Scheduled Frames     "},
+	{ "llc.dl_bytes",               "RLC encapsulated PDUs"},
+	{ "llc.ul_bytes",               "full PDUs received   "},
 	{ "rach.requests",		"RACH requests        "},
 };
 
@@ -1302,6 +1310,8 @@ int gprs_rlcmac_pdch::rcv_block(uint8_t *data, uint8_t len, uint32_t fn,
 		return -EINVAL;
 	}
 
+	bts()->rlc_ul_bytes(len);
+
 	LOGP(DRLCMACUL, LOGL_DEBUG, "Got RLC block, coding scheme: %s, "
 		"length: %d (%d))\n", cs.name(), len, cs.usedSizeUL());
 
diff --git a/src/bts.h b/src/bts.h
index bfbe014..2f63961 100644
--- a/src/bts.h
+++ b/src/bts.h
@@ -229,6 +229,7 @@ public:
 		CTR_RLC_RESENT,
 		CTR_RLC_RESTARTED,
 		CTR_RLC_STALLED,
+		CTR_RLC_UL_STALLED,
 		CTR_RLC_NACKED,
 		CTR_RLC_ASS_TIMEDOUT,
 		CTR_RLC_ASS_FAILED,
@@ -238,13 +239,20 @@ public:
 		CTR_RLC_LATE_BLOCK,
 		CTR_RLC_SENT_DUMMY,
 		CTR_RLC_SENT_CONTROL,
+		CTR_RLC_DL_BYTES,
+		CTR_RLC_DL_PAYLOAD_BYTES,
+		CTR_RLC_UL_BYTES,
+		CTR_RLC_UL_PAYLOAD_BYTES,
 		CTR_DECODE_ERRORS,
+		CTR_LLC_DECODE_ERRORS,
 		CTR_SBA_ALLOCATED,
 		CTR_SBA_FREED,
 		CTR_SBA_TIMEDOUT,
 		CTR_LLC_FRAME_TIMEDOUT,
 		CTR_LLC_FRAME_DROPPED,
 		CTR_LLC_FRAME_SCHED,
+		CTR_LLC_DL_BYTES,
+		CTR_LLC_UL_BYTES,
 		CTR_RACH_REQUESTS,
 	};
 
@@ -307,6 +315,7 @@ public:
 	void rlc_resent();
 	void rlc_restarted();
 	void rlc_stalled();
+	void rlc_ul_stalled();
 	void rlc_nacked();
 	void rlc_ass_timedout();
 	void rlc_ass_failed();
@@ -316,13 +325,20 @@ public:
 	void rlc_late_block();
 	void rlc_sent_dummy();
 	void rlc_sent_control();
+	void rlc_dl_bytes(int bytes);
+	void rlc_dl_payload_bytes(int bytes);
+	void rlc_ul_bytes(int bytes);
+	void rlc_ul_payload_bytes(int bytes);
 	void decode_error();
+	void llc_decode_err();
 	void sba_allocated();
 	void sba_freed();
 	void sba_timedout();
 	void llc_timedout_frame();
 	void llc_dropped_frame();
 	void llc_frame_sched();
+	void llc_dl_bytes(int bytes);
+	void llc_ul_bytes(int bytes);
 	void rach_frame();
 
 	void ms_present(int32_t n);
@@ -430,6 +446,11 @@ inline struct osmo_stat_item_group *BTS::stat_items() const
 	return m_statg;
 }
 
+#define CREATE_COUNT_ADD_INLINE(func_name, ctr_name) \
+	inline void BTS::func_name(int inc) {\
+		rate_ctr_add(&m_ratectrs->ctr[ctr_name], inc); \
+	}
+
 #define CREATE_COUNT_INLINE(func_name, ctr_name) \
 	inline void BTS::func_name() {\
 		rate_ctr_inc(&m_ratectrs->ctr[ctr_name]); \
@@ -449,6 +470,7 @@ CREATE_COUNT_INLINE(rlc_sent, CTR_RLC_SENT)
 CREATE_COUNT_INLINE(rlc_resent, CTR_RLC_RESENT)
 CREATE_COUNT_INLINE(rlc_restarted, CTR_RLC_RESTARTED)
 CREATE_COUNT_INLINE(rlc_stalled, CTR_RLC_STALLED)
+CREATE_COUNT_INLINE(rlc_ul_stalled, CTR_RLC_UL_STALLED)
 CREATE_COUNT_INLINE(rlc_nacked, CTR_RLC_NACKED)
 CREATE_COUNT_INLINE(rlc_ass_timedout, CTR_RLC_ASS_TIMEDOUT);
 CREATE_COUNT_INLINE(rlc_ass_failed, CTR_RLC_ASS_FAILED);
@@ -458,13 +480,20 @@ CREATE_COUNT_INLINE(rlc_rel_timedout, CTR_RLC_REL_TIMEDOUT);
 CREATE_COUNT_INLINE(rlc_late_block, CTR_RLC_LATE_BLOCK);
 CREATE_COUNT_INLINE(rlc_sent_dummy, CTR_RLC_SENT_DUMMY);
 CREATE_COUNT_INLINE(rlc_sent_control, CTR_RLC_SENT_CONTROL);
+CREATE_COUNT_ADD_INLINE(rlc_dl_bytes, CTR_RLC_DL_BYTES);
+CREATE_COUNT_ADD_INLINE(rlc_dl_payload_bytes, CTR_RLC_DL_PAYLOAD_BYTES);
+CREATE_COUNT_ADD_INLINE(rlc_ul_bytes, CTR_RLC_UL_BYTES);
+CREATE_COUNT_ADD_INLINE(rlc_ul_payload_bytes, CTR_RLC_UL_PAYLOAD_BYTES);
 CREATE_COUNT_INLINE(decode_error, CTR_DECODE_ERRORS)
+CREATE_COUNT_INLINE(llc_decode_err, CTR_DECODE_ERRORS)
 CREATE_COUNT_INLINE(sba_allocated, CTR_SBA_ALLOCATED)
 CREATE_COUNT_INLINE(sba_freed, CTR_SBA_FREED)
 CREATE_COUNT_INLINE(sba_timedout, CTR_SBA_TIMEDOUT)
 CREATE_COUNT_INLINE(llc_timedout_frame, CTR_LLC_FRAME_TIMEDOUT);
 CREATE_COUNT_INLINE(llc_dropped_frame, CTR_LLC_FRAME_DROPPED);
 CREATE_COUNT_INLINE(llc_frame_sched, CTR_LLC_FRAME_SCHED);
+CREATE_COUNT_ADD_INLINE(llc_dl_bytes, CTR_LLC_DL_BYTES);
+CREATE_COUNT_ADD_INLINE(llc_ul_bytes, CTR_LLC_UL_BYTES);
 CREATE_COUNT_INLINE(rach_frame, CTR_RACH_REQUESTS);
 
 #undef CREATE_COUNT_INLINE
diff --git a/src/gprs_rlcmac_meas.cpp b/src/gprs_rlcmac_meas.cpp
index 5a2e38e..50641c3 100644
--- a/src/gprs_rlcmac_meas.cpp
+++ b/src/gprs_rlcmac_meas.cpp
@@ -129,6 +129,9 @@ int gprs_rlcmac_received_lost(struct gprs_rlcmac_dl_tbf *tbf, uint16_t received,
 	tbf->m_bw.dl_loss_received += received;
 	tbf->m_bw.dl_loss_lost += lost;
 
+	tbf->m_bw.total_dl_loss_received += received;
+	tbf->m_bw.total_dl_loss_lost += lost;
+
 	gettimeofday(&now_tv, NULL);
 	elapsed = ((now_tv.tv_sec - loss_tv->tv_sec) << 7)
 		+ ((now_tv.tv_usec - loss_tv->tv_usec) << 7) / 1000000;
diff --git a/src/gprs_rlcmac_sched.cpp b/src/gprs_rlcmac_sched.cpp
index fce3aaf..0367ad0 100644
--- a/src/gprs_rlcmac_sched.cpp
+++ b/src/gprs_rlcmac_sched.cpp
@@ -360,6 +360,7 @@ int gprs_rlcmac_rcv_rts_block(struct gprs_rlcmac_bts *bts,
 	if (!msg)
 		return -ENOMEM;
 	/* msg is now available */
+	bts->bts->rlc_dl_bytes(msg->data_len);
 
 	/* set USF */
 	OSMO_ASSERT(msgb_length(msg) > 0);
diff --git a/src/pcu_vty_functions.cpp b/src/pcu_vty_functions.cpp
index 8009535..b4986a8 100644
--- a/src/pcu_vty_functions.cpp
+++ b/src/pcu_vty_functions.cpp
@@ -66,14 +66,32 @@ static void tbf_print_vty_info(struct vty *vty, gprs_rlcmac_tbf *tbf)
 
 	if (ul_tbf) {
 		gprs_rlc_ul_window *win = &ul_tbf->m_window;
-		vty_out(vty, " V(Q)=%d V(R)=%d",
-			win->v_q(), win->v_r());
+		vty_out(vty, " V(Q)=%d V(R)=%d RX_CNTR=%d",
+			win->v_q(), win->v_r(), ul_tbf->m_rx_counter);
+			vty_out(vty, "%s%s", VTY_NEWLINE, VTY_NEWLINE);
+		for (int i = 0; i < 9; i++) {
+			vty_out(vty, " MCS%d=%d ", i+1, tbf->m_ctr_num_blocks[i]);
+		}
 	}
 	if (dl_tbf) {
 		gprs_rlc_dl_window *win = &dl_tbf->m_window;
-		vty_out(vty, " V(A)=%d V(S)=%d nBSN=%d%s",
-			win->v_a(), win->v_s(), win->resend_needed(),
-			win->window_stalled() ? " STALLED" : "");
+		vty_out(vty,
+			" V(A)=%d V(S)=%d LLC_QUEUE_SIZE=%d LLC_OCTETS=%d "
+			"nBSN=%d%s NA=%u A=%u",
+			win->v_a(), win->v_s(), dl_tbf->llc_queue()->size(),
+			dl_tbf->llc_queue()->octets(),
+			win->resend_needed(),
+			win->window_stalled() ? " STALLED" : "",
+			dl_tbf->m_bw.total_dl_loss_lost,
+			dl_tbf->m_bw.total_dl_loss_received);
+			vty_out(vty, "%s%s", VTY_NEWLINE, VTY_NEWLINE);
+		for (int i = 0; i < 9; i++) {
+			vty_out(vty, " MCS%d=%d ", i+1, tbf->m_ctr_num_blocks[i]);
+		}
+		vty_out(vty, "%s%s", VTY_NEWLINE, VTY_NEWLINE);
+		for (int i = 0; i < 3; i++) {
+			vty_out(vty, " retx%d=%d ", i+1, tbf->m_ctr_retx[i]);
+		}
 	}
 	vty_out(vty, "%s%s", VTY_NEWLINE, VTY_NEWLINE);
 }
diff --git a/src/rlc.cpp b/src/rlc.cpp
index dc1db3e..c84fed0 100644
--- a/src/rlc.cpp
+++ b/src/rlc.cpp
@@ -32,6 +32,7 @@ uint8_t *gprs_rlc_data::prepare(size_t block_data_len)
 	/* todo.. only set it once if it turns out to be a bottleneck */
 	memset(block, 0x0, sizeof(block));
 	memset(block, 0x2b, block_data_len);
+	m_ctr_num_retx = 0;
 
 	/* Initial value of puncturing scheme */
 	next_ps = EGPRS_PS_1;
diff --git a/src/rlc.h b/src/rlc.h
index b731859..11edde2 100644
--- a/src/rlc.h
+++ b/src/rlc.h
@@ -161,6 +161,7 @@ struct gprs_rlc_data {
 
 	/* Holds the current status of the block w.r.t DL split blocks*/
 	egprs_rlc_dl_reseg_bsn_state block_status_dl;
+	uint32_t m_ctr_num_retx;
 };
 
 void gprs_rlc_data_info_init_dl(struct gprs_rlc_data_info *rlc,
diff --git a/src/tbf.cpp b/src/tbf.cpp
index 8493505..c77c5ee 100644
--- a/src/tbf.cpp
+++ b/src/tbf.cpp
@@ -86,7 +86,7 @@ gprs_rlcmac_tbf::gprs_rlcmac_tbf(BTS *bts_, gprs_rlcmac_tbf_direction dir) :
 	memset(&timer, 0, sizeof(timer));
 	memset(&m_rlc, 0, sizeof(m_rlc));
 	memset(&gsm_timer, 0, sizeof(gsm_timer));
-
+	memset(&m_ctr_num_blocks, 0, 9 * sizeof(uint32_t));
 	m_llc.init();
 
 	m_name_buf[0] = '\0';
@@ -728,7 +728,9 @@ struct gprs_rlcmac_ul_tbf *tbf_alloc_ul_tbf(struct gprs_rlcmac_bts *bts,
 gprs_rlcmac_dl_tbf::BandWidth::BandWidth() :
 	dl_bw_octets(0),
 	dl_loss_lost(0),
-	dl_loss_received(0)
+	dl_loss_received(0),
+	total_dl_loss_lost(0),
+	total_dl_loss_received(0)
 {
 	timerclear(&dl_bw_tv);
 	timerclear(&dl_loss_tv);
diff --git a/src/tbf.h b/src/tbf.h
index a825b4f..698f0db 100644
--- a/src/tbf.h
+++ b/src/tbf.h
@@ -224,6 +224,8 @@ struct gprs_rlcmac_tbf {
 	 */
 	uint8_t m_tfi;
 	time_t m_created_ts;
+	uint32_t m_ctr_num_blocks[9];
+	uint32_t m_ctr_retx[3];
 
 protected:
 	gprs_rlcmac_bts *bts_data() const;
@@ -395,6 +397,9 @@ struct gprs_rlcmac_dl_tbf : public gprs_rlcmac_tbf {
 		uint16_t dl_loss_lost; /* sum of lost packets */
 		uint16_t dl_loss_received; /* sum of received packets */
 
+		uint32_t total_dl_loss_lost; /* total of lost packets */
+		uint32_t total_dl_loss_received; /* total of received packets */
+
 		BandWidth();
 	} m_bw;
 
diff --git a/src/tbf_dl.cpp b/src/tbf_dl.cpp
index 80ab000..74e3df9 100644
--- a/src/tbf_dl.cpp
+++ b/src/tbf_dl.cpp
@@ -572,6 +572,7 @@ int gprs_rlcmac_dl_tbf::create_new_bsn(const uint32_t fn, GprsCodingScheme cs)
 		LOGP(DRLCMACDL, LOGL_INFO, "Complete DL frame for %s"
 			"len=%d\n", tbf_name(this), m_llc.frame_length());
 		gprs_rlcmac_dl_bw(this, m_llc.frame_length());
+		bts->llc_dl_bytes(m_llc.frame_length());
 		m_llc.reset();
 
 		if (is_final) {
@@ -728,6 +729,10 @@ struct msgb *gprs_rlcmac_dl_tbf::create_dl_acked_block(
 
 		Encoding::rlc_copy_from_aligned_buffer(&rlc, data_block_idx,
 			msg_data, block_data);
+		m_ctr_num_blocks[cs.to_num() - 1]++;
+		m_rlc.block(bsn)->m_ctr_num_retx++;
+		if(m_rlc.block(bsn)->m_ctr_num_retx > 1)
+			m_ctr_retx[m_rlc.block(bsn)->m_ctr_num_retx > 3 ? 2:m_rlc.block(bsn)->m_ctr_num_retx - 2]++;
 	}
 
 	OSMO_ASSERT(ARRAY_SIZE(punct) >= 2);
diff --git a/src/tbf_ul.cpp b/src/tbf_ul.cpp
index 1342ef2..dc3f628 100644
--- a/src/tbf_ul.cpp
+++ b/src/tbf_ul.cpp
@@ -67,6 +67,8 @@ int gprs_rlcmac_ul_tbf::assemble_forward_llc(const gprs_rlc_data *_data)
 	for (i = 0; i < num_frames; i++) {
 		frame = frames + i;
 
+		bts->rlc_ul_payload_bytes(frame->length);
+
 		LOGP(DRLCMACUL, LOGL_DEBUG, "-- Frame %d starts at offset %d, "
 			"length=%d, is_complete=%d\n",
 			i + 1, frame->offset, frame->length, frame->is_complete);
@@ -79,6 +81,7 @@ int gprs_rlcmac_ul_tbf::assemble_forward_llc(const gprs_rlc_data *_data)
 			LOGP(DRLCMACUL, LOGL_INFO, "%s complete UL frame len=%d\n",
 				tbf_name(this) , m_llc.frame_length());
 			snd_ul_ud();
+			bts->llc_ul_bytes(m_llc.frame_length());
 			m_llc.reset();
 		}
 	}
@@ -364,7 +367,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
 				Decoding::rlc_copy_to_aligned_buffer(rlc,
 				block_idx, data, rlc_data);
 		}
-
+		m_ctr_num_blocks[rlc->cs.to_num() - 1]++;
 		LOGP(DRLCMACUL, LOGL_DEBUG,
 			"%s: data_length=%d, data=%s\n",
 			name(), block->len, osmo_hexdump(rlc_data, block->len));
@@ -374,7 +377,7 @@ int gprs_rlcmac_ul_tbf::rcv_data_block_acknowledged(
 				rdbi, rlc->cs, rlc_data, NULL, 0, &new_tlli);
 
 			if (num_chunks < 0) {
-				bts->decode_error();
+				bts->llc_decode_err();
 				LOGP(DRLCMACUL, LOGL_NOTICE,
 					"Failed to decode TLLI of %s UL DATA "
 					"TFI=%d.\n", rlc->cs.name(), rlc->tfi);
@@ -456,6 +459,7 @@ void gprs_rlcmac_ul_tbf::maybe_schedule_uplink_acknack(
 		if (rlc->si) {
 			LOGP(DRLCMACUL, LOGL_NOTICE, "- Scheduling Ack/Nack, "
 				"because MS is stalled.\n");
+			bts->rlc_ul_stalled();
 		}
 		if (have_ti) {
 			LOGP(DRLCMACUL, LOGL_DEBUG, "- Scheduling Ack/Nack, "