Merge pull request #352 from DrDoof/feat/health-cmd

health: a CLI dump of where the main loop's time goes

.github/workflows/build.yml

@@ -26,3 +26,5 @@ jobs:
         run: make CI=1 MACHINE="KP_9000_6XHML_X2"
       - name: Make project (8x1/RTL8373)
         run: make CI=1 MACHINE="KP_9000_9XHML_X_V3_1"
+      - name: Make project with the health instrumentation
+        run: make clean && make CI=1 MACHINE="KP_9000_6XHML_X2" HEALTH=1

Makefile

@@ -19,6 +19,10 @@ ifeq ($(MACHINE),)
 else
 	CC_FLAGS += -DMACHINE_$(MACHINE)
 endif
+# Health instrumentation and the "health" console command: HEALTH=1 gmake ...
+ifneq ($(HEALTH),)
+	CC_FLAGS += -DHEALTH
+endif
 
 ifeq ($(CI),1)
 	CC_FLAGS += --Werror

cmd_parser.c

@@ -5,6 +5,8 @@
 // #define DEBUG
 // #define REGDBG 1
 
+#include <8051.h>
+#include "cmd_parser.h"
 #include "rtl837x_common.h"
 #include "rtl837x_port.h"
 #include "rtl837x_flash.h"
@@ -1850,6 +1852,10 @@ void cmd_parser(void) __banked
 			}
 		} else if (cmd_compare(0, "stp")) {
 			stp_parse();
+#ifdef HEALTH
+		} else if (cmd_compare(0, "health")) {
+			health_show();
+#endif
 		} else if (cmd_compare(0, "pvid")) {
 			if (cmd_words_len == 3 && cmd_parse_port_separator(cmd_words_b[1]) != 0
 			    && atoi_short(cmd_words_b[2]) && atoi_results_short && atoi_results_short <= 4094)
@@ -2054,3 +2060,161 @@ void execute_commands(__xdata uint8_t *p) __banked {
 		p++;
 	};
 }
+
+#ifdef HEALTH
+/*
+ * Health instrumentation. The counters live in xdata and are fed from the
+ * main loop through the banked entry points below; the "health" command
+ * prints everything in one go. All figures are raw hex, diffing two dumps
+ * gives the rates. Phase times are in system ticks (SYS_TICK_HZ = 200,
+ * 5 ms each); a phase counts as slow when it spans 2 or more ticks.
+ */
+extern __xdata uint16_t len_left;	/* httpd: bytes still to send of the current file */
+extern __xdata uint8_t entry;		/* httpd: index of the file being sent */
+
+static __xdata uint32_t health_loops;
+__xdata uint16_t health_rx_frames;
+
+static __xdata uint16_t ph_last_t;
+static __xdata uint8_t  ph_max[HEALTH_PHASES];
+static __xdata uint16_t ph_slow[HEALTH_PHASES];
+
+/* The ISR increments ticks between the two byte reads of a 16-bit load, so
+ * read until two loads agree. */
+static uint16_t ticks_lo(void)
+{
+	uint16_t a, b;
+	a = (uint16_t)ticks;
+	do {
+		b = a;
+		a = (uint16_t)ticks;
+	} while (a != b);
+	return a;
+}
+
+
+void health_loop_start(void) __banked
+{
+	health_loops++;
+	ph_last_t = ticks_lo();
+}
+
+
+void health_phase(uint8_t id) __banked
+{
+	__xdata uint16_t now = ticks_lo();
+	__xdata uint16_t d = now - ph_last_t;
+	ph_last_t = now;
+	if (d > 0xff)
+		d = 0xff;
+	if ((uint8_t)d > ph_max[id])
+		ph_max[id] = d;
+	if (d >= 2)
+		ph_slow[id]++;
+}
+
+
+/* Fill the stack area above the current frame with a pattern; the dump scans
+ * for how much of it survived. The 8051 stack grows upward, so everything
+ * above SP is free at this point. Interrupts are held off so an ISR does not
+ * push into the area mid-paint. */
+void health_stack_paint(void) __banked
+{
+	__xdata uint8_t from = SP + 4;
+	__xdata uint8_t ea = EA;
+	EA = 0;
+	for (uint8_t i = 0xff; i >= from; i--)
+		*(__idata uint8_t *)i = 0xa5;
+	EA = ea;
+}
+
+
+static void ph_line(__code const char *name, uint8_t id)
+{
+	print_string(name);
+	print_string(" max ");
+	print_byte(ph_max[id]);
+	print_string(" slow ");
+	print_short(ph_slow[id]);
+	write_char('\n');
+}
+
+
+void health_show(void) __banked
+{
+	__xdata uint8_t i;
+
+	print_string("up ");
+	reg_read_m(RTL837X_REG_SEC_COUNTER);
+	print_byte(sfr_data[0]); print_byte(sfr_data[1]);
+	print_byte(sfr_data[2]); print_byte(sfr_data[3]);
+	print_string(" ticks ");
+	print_long(ticks);
+	print_string(" loops ");
+	print_long(health_loops);
+	print_string(" rx ");
+	print_short(health_rx_frames);
+	write_char('\n');
+
+	/* Phase timing: max duration seen (ticks of 5 ms) and slow-pass count */
+	ph_line("link", HEALTH_PH_LINK);
+	ph_line("sfp ", HEALTH_PH_SFP);
+	ph_line("rx  ", HEALTH_PH_RX);
+	ph_line("tx  ", HEALTH_PH_TX);
+	ph_line("stp ", HEALTH_PH_STP);
+	ph_line("cmd ", HEALTH_PH_CMD);
+
+	/* Stack: current depth plus how much of the painted area is untouched */
+	print_string("sp ");
+	print_byte(SP);
+	print_string(" untouched ");
+	i = 0;
+	while (*(__idata uint8_t *)(0xff - i) == 0xa5 && i < 0x86)
+		i++;
+	print_byte(i);
+	write_char('\n');
+
+	/* The TCP connection slot. One on this configuration; a build with more
+	 * has to say which slot each line is, so make that a visible decision. */
+#if UIP_CONNS != 1
+#error "health: the tcp dump prints a single slot, extend it for UIP_CONNS > 1"
+#endif
+	i = 0;
+	{
+		print_string("tcp ");
+		print_string("st ");
+		print_byte(uip_conns[i].tcpstateflags);
+		print_string(" tmr ");
+		print_byte(uip_conns[i].timer);
+		print_string(" rtx ");
+		print_byte(uip_conns[i].nrtx);
+		print_string(" rto ");
+		print_byte(uip_conns[i].rto);
+		print_string(" len ");
+		print_short(uip_conns[i].len);
+		print_string(" mss ");
+		print_short(uip_conns[i].mss);
+		write_char('\n');
+		print_string("  lport ");
+		print_short(HTONS(uip_conns[i].lport));
+		print_string(" rport ");
+		print_short(HTONS(uip_conns[i].rport));
+		print_string(" rip ");
+		print_short(HTONS(uip_conns[i].ripaddr[0]));
+		write_char(' ');
+		print_short(HTONS(uip_conns[i].ripaddr[1]));
+		write_char('\n');
+	}
+
+	/* httpd transfer state and the protocol flags */
+	print_string("httpd left ");
+	print_short(len_left);
+	print_string(" entry ");
+	print_byte(entry);
+	print_string(" stp ");
+	print_byte(stp_enabled);
+	print_string(" mvlan ");
+	print_short(management_vlan);
+	write_char('\n');
+}
+#endif

cmd_parser.h

@@ -9,6 +9,32 @@ extern __xdata uint8_t cmd_buffer[CMD_BUF_SIZE];
 extern __xdata uint8_t cmd_available;
 extern __xdata uint8_t err_status;
 
+/* Health instrumentation, built with HEALTH=1. Without it the hooks below
+ * compile to nothing and the "health" command does not exist. */
+#ifdef HEALTH
+/* Phase ids, in main-loop order */
+#define HEALTH_PH_LINK	0
+#define HEALTH_PH_SFP	1
+#define HEALTH_PH_RX	2
+#define HEALTH_PH_TX	3
+#define HEALTH_PH_STP	4
+#define HEALTH_PH_CMD	5
+#define HEALTH_PHASES	6
+
+extern __xdata uint16_t health_rx_frames;
+#define health_rx_frame()	health_rx_frames++
+
+void health_loop_start(void) __banked;	/* once per idle() pass, resets the phase baseline */
+void health_phase(uint8_t id) __banked;	/* after each phase; accounts ticks since last checkpoint */
+void health_stack_paint(void) __banked;	/* paint the unused stack area once at boot */
+void health_show(void) __banked;	/* "health" CLI dump */
+#else
+#define health_rx_frame()
+#define health_loop_start()
+#define health_phase(id)
+#define health_stack_paint()
+#endif
+
 void cmd_tokenize(void) __banked;
 void cmd_parser(void) __banked;
 void execute_config(void) __banked;

doc/health.md

@@ -0,0 +1,79 @@
+# The health command
+
+`health` prints a one-page snapshot of the firmware's vital signs on the
+serial console. It exists for the situations where the switch misbehaves and
+every probe from the network measures the network instead of the device: the
+dump is taken from inside, costs one command, and works while HTTP does not.
+
+```
+> health
+up 0000001f ticks 0x00001f4c loops 0x000016da rx 0x024e
+link max 01 slow 0x0000
+sfp  max 74 slow 0x0001
+rx   max 00 slow 0x0000
+tx   max 00 slow 0x0000
+stp  max 04 slow 0x0001
+cmd  max 02 slow 0x0001
+sp 80 untouched 62
+tcp st 00 tmr 00 rtx 00 rto 00 len 0x0000 mss 0x05b4
+  lport 0x0000 rport 0x0000 rip 0x0000 0x0000
+httpd left 0x0000 entry 00 stp 01 mvlan 0x0002
+```
+
+The instrumentation is not part of a default build. It costs about 1.1 kB
+of bank 2, a few bytes of xdata and seven banked calls per main-loop pass,
+which is nothing a user needs unless they are chasing a problem, so it is
+switched on at build time:
+
+```
+make MACHINE=SWTGW218AS HEALTH=1
+```
+
+Without it the hooks compile to nothing and `health` is not a command.
+
+All figures are raw hex. The counters are cumulative: take two dumps a known
+time apart and the differences give the rates.
+
+## The first line
+
+`up` is the seconds counter, `ticks` the system tick (200 per second),
+`loops` the number of main-loop passes and `rx` the frames handle_rx has
+taken off the NIC. A healthy loop completes one pass per tick, so the
+difference in `loops` tracks the difference in `ticks`; a loop that falls
+behind is being held up by one of the phases below. The `rx` rate separates
+a flooded CPU port from a stalled loop, which look identical from outside.
+
+## Phases
+
+Each line is one section of the main loop: the link poll, SFP handling,
+frame reception, TCP transmission, the STP timers and the command dispatch.
+`max` is the worst time that section has taken, in ticks of 5 ms; `slow`
+counts the passes that took two ticks or more. A misbehaving subsystem
+names itself here, which is the difference between knowing that the loop is
+slow and knowing why.
+
+A dump of its own output takes the console some milliseconds, so running
+`health` repeatedly increments the `cmd` counters by itself. That is the
+instrument observing itself, not a fault.
+
+## Stack
+
+At boot the free stack area is painted with a pattern. `sp` is the live
+stack pointer; `untouched` counts the painted bytes still intact at the top,
+which is the closest thing to a high-water mark this hardware offers. A
+shrinking `untouched` across dumps means something is reaching deeper than
+anything before it.
+
+## The TCP slot
+
+The connection table is printed whole, one slot per pair of lines: TCP
+state (3 is ESTABLISHED, 0 closed), retransmission timer and counter, bytes
+in flight, negotiated MSS, then the ports and the peer address. With a
+single slot serving the entire web interface, one glance answers the
+question every management outage starts with: who is holding it. A slot
+showing state 3 with nothing in flight and a peer that no longer answers is
+a connection whose owner went away.
+
+`httpd left` and `entry` describe the file transfer the web server believes
+it is in the middle of, and the trailing flags show whether STP is running
+and which VLAN carries management.

rtlplayground.c

@@ -1015,6 +1015,7 @@ void handle_rx(void)
 			REG_SET(RTL837X_REG_NIC_RXCMD, 1);
 			return;
 		}
+		health_rx_frame();
 
 #ifdef RXTXDBG
 		print_string("\n<< ");
@@ -1176,6 +1177,7 @@ void idle(void)
 	reg_read(RTL837X_REG_NIC_RX_BUFF_DATA);
 	if (!SFR_DATA_U16)
 		PCON |= 1;
+	health_loop_start();
 	if (sec_counter >= SYS_TICK_HZ) {
 		sec_counter -= SYS_TICK_HZ;
 		reg_read_m(RTL837X_REG_SEC_COUNTER);
@@ -1251,13 +1253,18 @@ void idle(void)
 		}
 	}
 
+	health_phase(HEALTH_PH_LINK);
+
 	// Check for changes with SFP modules
 	handle_sfp();
+	health_phase(HEALTH_PH_SFP);
 
 	// Check new Packets RX
 	handle_rx();
+	health_phase(HEALTH_PH_RX);
 	// Check UIP for packets to transmit
 	handle_tx();
+	health_phase(HEALTH_PH_TX);
 	// If STP protocol enabled, decrease STP timers to trigger actions
 	if (stp_enabled) {
 		if (!stp_clock) {
@@ -1267,6 +1274,7 @@ void idle(void)
 			stp_clock--;
 		}
 	}
+	health_phase(HEALTH_PH_STP);
 	// Check whether a command is waiting in the cmd_buffer and execute
 	if (cmd_available) {
 		cmd_available = 0;
@@ -1275,6 +1283,7 @@ void idle(void)
 			cmd_parser();
 		print_cmd_prompt();
 	}
+	health_phase(HEALTH_PH_CMD);
 }
 
 
@@ -1769,6 +1778,7 @@ void main(void)
 
 	cmd_editor_init();
 
+	health_stack_paint();
 	while (1) {
 		cmd_edit();
 		idle(); // Enter Idle mode until interrupt occurs