diff --git a/device/src/connections.c b/device/src/connections.c index 36a2544dd..83061acaf 100644 --- a/device/src/connections.c +++ b/device/src/connections.c @@ -143,6 +143,7 @@ void Connections_ResetWatermarks(connection_id_t connectionId) { Connections[connectionId].watermarks.txIdx = 0; Connections[connectionId].watermarks.rxIdx = 255; + Connections[connectionId].watermarks.rxIdxValid = false; } void Connections_ReportState(connection_id_t connectionId) { diff --git a/device/src/connections.h b/device/src/connections.h index 12f83ef70..b015ae099 100644 --- a/device/src/connections.h +++ b/device/src/connections.h @@ -69,6 +69,7 @@ typedef struct { uint8_t rxIdx; uint8_t txIdx; + bool rxIdxValid; // rxIdx holds the watermark of a frame accepted since the last reset } ATTR_PACKED connection_watermarks_t; typedef struct { diff --git a/device/src/keyboard/key_scanner.c b/device/src/keyboard/key_scanner.c index c213071c6..3f36caf61 100644 --- a/device/src/keyboard/key_scanner.c +++ b/device/src/keyboard/key_scanner.c @@ -301,6 +301,8 @@ static void scanAllKeys() { } if (DEVICE_IS_UHK80_LEFT) { + // If ack gets lost, second key state change will block (because uart is busy with control of the first one). That blocks us. Third keystate change may be lost. + // TODO: consider passing this via postponer queue. Messenger_Send2(DeviceId_Uhk80_Right, MessageId_SyncableProperty, SyncablePropertyId_LeftHalfKeyStates, compressedBuffer, compressedLength); } } diff --git a/device/src/keyboard/uart_bridge.c b/device/src/keyboard/uart_bridge.c index 8fd9f44cd..db70343ea 100644 --- a/device/src/keyboard/uart_bridge.c +++ b/device/src/keyboard/uart_bridge.c @@ -1,3 +1,4 @@ +#include #include #include #include @@ -20,8 +21,18 @@ #define THREAD_PRIORITY -5 #define UART_FOREVER_TIMEOUT 10000 -#define UART_RESEND_DELAY 64 -#define UART_RESEND_COUNT 5 +// Resend an unacked frame every UART_RESEND_DELAY ms, up to UART_RESEND_COUNT times, then +// give up. The ack loop takes ~3ms for a key-state frame and ~13ms for a maximum-length one +// (115200 baud), so 15ms is late enough not to duplicate a frame that's merely in flight. +// +// The delay is constant, not exponential, on purpose. Senders block on txBufferBusy (one +// slot) until the outstanding frame is acked; on the left half that sender is the key +// scanner thread, which then stops scanning - key changes made during the stall are +// coalesced into the next snapshot or, if pressed and released inside it, never seen. The +// worst-case stall is therefore UART_RESEND_COUNT * UART_RESEND_DELAY (was ~8s with the old +// 64ms<=64ms +} latency_stats_t; + +typedef struct { + uint32_t framesSent; + uint32_t framesReceived; + uint16_t ackWhileIdle; // ack arrived while we weren't waiting for one + uint16_t nackWhileIdle; + uint16_t nackReceived; + uint16_t resendTimeout; + uint16_t resendNack; + uint16_t giveUps; + uint16_t txSendFail; // uart_tx returned an error + uint16_t unexpectedBytes; + latency_stats_t ackLoop; // sender: uart_tx of a frame -> its ack parsed + latency_stats_t ackTurn; // receiver: frame parsed -> ack handed to uart_tx +} uart_bridge_stats_t; + +static uart_bridge_stats_t stats = {0}; + +static void recordLatency(latency_stats_t* s, uint32_t startCyc) { + uint32_t us = k_cyc_to_us_floor32(k_cycle_get_32() - startCyc); + uint8_t bucket; + if (us < 1000) { + bucket = 0; + } else if (us < 4000) { + bucket = 1; + } else if (us < 16000) { + bucket = 2; + } else if (us < 64000) { + bucket = 3; + } else { + bucket = 4; + } + s->hist[bucket]++; + s->count++; + s->sumUs += us; + s->maxUs = MAX(s->maxUs, us); +} + /* UART message format: * [START_BYTE,crc16,escaped(messengerPacket), ENDBYTE] * crcMessage = 4 bytes = CRC16 in format [ESCAPE_BYTE,byte1,ESCAPE_BYTE,byte2] @@ -129,6 +194,37 @@ static void setRxState(uart_state_t *uartState, uart_rx_state_t state) { wakeControlThread(uartState); } +// Dumps a frame as a few log lines rather than one log message per byte: this runs in the +// UART ISR, and a per-byte dump floods the deferred log buffer faster than any log thread +// priority can drain it. Only the head of the frame is shown. +#define FRAME_DUMP_LINE_LEN 80 +#define FRAME_DUMP_MAX_LINES 2 + +static void logFrameBytes(const uint8_t* data, uint16_t len) { + char line[FRAME_DUMP_LINE_LEN]; + uint16_t pos = 0; + uint16_t shown = len; + uint16_t lines = 0; + + for (uint16_t i = 0; i < shown; i++) { + int n = snprintf(line + pos, FRAME_DUMP_LINE_LEN - pos, "%02x ", data[i]); + bool lineFull = n < 0 || pos + n >= sizeof(line) - 1; + if (lineFull) { + line[pos] = '\0'; + LogU(" %s\n", line); + pos = 0; + if (++lines >= FRAME_DUMP_MAX_LINES) { + break; + } + n = snprintf(line, sizeof(line), "%02x ", data[i]); + } + pos += n; + } + if (pos > 0) { + LogU(" %s%s\n", line, shown < len ? "..." : ""); + } +} + static void receiveMessage(void *state, uart_control_t messageKind, const uint8_t* data, uint16_t len) { uart_state_t *uartState = (uart_state_t *)state; @@ -136,15 +232,21 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ switch (messageKind) { case UartControl_Ack: if (uartState->txState == UartTxState_WaitingForAck) { + recordLatency(&stats.ackLoop, uartState->sentCyc); uartState->resendTries = 0; uartState->txState = UartTxState_Idle; k_sem_give(&uartState->txBufferBusy); + } else { + stats.ackWhileIdle++; } break; case UartControl_Nack: if (uartState->txState == UartTxState_WaitingForAck) { + stats.nackReceived++; uartState->txState = UartTxState_Resend; wakeControlThread(uartState); + } else { + stats.nackWhileIdle++; } break; case UartControl_Ping: @@ -153,6 +255,8 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ case UartControl_ValidMessage: { uartState->lastPingTime = k_uptime_get(); + stats.framesReceived++; + uartState->ackReqCyc = k_cycle_get_32(); setRxState(uartState, UartRxState_Ack); // message @@ -171,12 +275,8 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ uartState->invalidMessagesCounter++; const char *out1, *out2; Messenger_GetMessageDescription(uartState->rxBuffer, 0, &out1, &out2); - LogUO("Crc-invalid UART message received! %s %s ", out1, out2 == NULL ? "" : out2); - - for (uint16_t i = 0; i < uartState->parser.rxPosition; i++) { - LogU("%i ", uartState->rxBuffer[i]); - } - LogU("\n"); + LogUO("Crc-invalid UART message received! %s %s\n", out1, out2 == NULL ? "" : out2); + logFrameBytes(uartState->rxBuffer, uartState->parser.rxPosition); setRxState(uartState, UartRxState_Nack); @@ -184,15 +284,14 @@ static void receiveMessage(void *state, uart_control_t messageKind, const uint8_ } break; case UartControl_Unexpected: -#if UART_LOWPOWER - // Out-of-frame garbage is expected here: enabling RX mid-byte after a GPIO wake - // yields a partial byte or the tail of the wake byte. The parser resyncs on the - // next Start byte, whereas resetting RX (10ms of deafness, wake sense unarmed) - // exactly when the real frame is inbound turns one garbled byte into a resend storm. + // Out-of-frame garbage: a byte received while the parser is between frames. It is + // routine after any RX teardown - bridgeOnRxDisabled resyncs the parser while the + // peer's frame may still be streaming in, so its remaining bytes land here. The + // parser resyncs itself on the next Start byte. Tearing RX down here instead + // (the old UartLink_Reset) made every such byte another teardown, another mid-frame + // re-enable, and so on until the frame ended - one lost frame per hiccup. + stats.unexpectedBytes++; BridgeDbg("BRIDGE RX unexpected byte\n"); -#else - UartLink_Reset(&uartState->core); -#endif break; } } @@ -229,8 +328,11 @@ int UartBridge_SendMessage(message_t* msg) { UartParser_AppendEscapedTxBytes(&uartState->parser, msg->data, msg->len); UartParser_FinalizeMessage(&uartState->parser); + stats.framesSent++; + uartState->sentCyc = k_cycle_get_32(); err = UartLink_Send(&uartState->core, uartState->parser.txBuffer, uartState->parser.txPosition); if (err != 0) { + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } @@ -241,22 +343,34 @@ int UartBridge_SendMessage(message_t* msg) { return err; } -static void sendControl(uart_state_t *uartState, uint8_t byte) { +static void sendControl(uart_state_t *uartState, uint8_t byte, bool isAck) { UartLink_LockBusy(&uartState->core); - int err = UartLink_Send(&uartState->core, &byte, 1); + if (isAck) { + // Measured once we hold the TX slot: includes waiting out our own in-flight frame. + recordLatency(&stats.ackTurn, uartState->ackReqCyc); + } + uartState->controlByte = byte; + int err = UartLink_Send(&uartState->core, &uartState->controlByte, 1); if (err != 0) { // No transfer started -> no TX_DONE -> return the slot ourselves. + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } } // wakePeer: a nack-triggered resend skips the wake handshake, since the peer just parsed // our garbled frame and is provably awake; a timeout-triggered one redoes it, because -// after 64ms+ of silence the peer has almost certainly slept again. This must not +// after the resend delay of silence the peer may have slept again. This must not // k_sleep - it runs on the control thread, where blocking makes us blind to wake edges, // acks and pings, which used to cascade into a disconnect + BLE-fallback feedback loop. static void resend(uart_state_t *uartState, bool wakePeer) { + if (wakePeer) { + stats.resendTimeout++; + } else { + stats.resendNack++; + } if (uartState->resendTries++ > UART_RESEND_COUNT) { + stats.giveUps++; LogU("Repeatedly failed to send a message! "); for (uint16_t i = 0; i < uartState->parser.txPosition; i++) { LogU("%i ", uartState->parser.txBuffer[i]); @@ -273,9 +387,11 @@ static void resend(uart_state_t *uartState, bool wakePeer) { UartLink_SendWakeByte(&uartState->core); } UartLink_LockBusy(&uartState->core); + uartState->sentCyc = k_cycle_get_32(); int err = UartLink_Send(&uartState->core, uartState->parser.txBuffer, uartState->parser.txPosition); if (err != 0) { // No transfer started -> no TX_DONE -> return the slot ourselves. + stats.txSendFail++; k_sem_give(&uartState->core.txControlBusy); } uartState->lastMessageSentTime = k_uptime_get(); @@ -333,7 +449,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (currentTime >= lastPingSentTime + UART_BRIDGE_PING_INTERVAL) { UartLink_WakeRx(&uartState->core); UartLink_SendWakeByte(&uartState->core); - sendControl(uartState, UartControlByte_Ping); + sendControl(uartState, UartControlByte_Ping, false); lastPingSentTime = currentTime; } @@ -342,11 +458,11 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { if (Connections_IsReady(uartState->connectionId)) { switch (uartState->rxState) { case UartRxState_Ack: - sendControl(uartState, UartControlByte_Ack); + sendControl(uartState, UartControlByte_Ack, true); uartState->rxState = UartRxState_Idle; break; case UartRxState_Nack: - sendControl(uartState, UartControlByte_Nack); + sendControl(uartState, UartControlByte_Nack, false); uartState->rxState = UartRxState_Idle; break; case UartRxState_Idle: @@ -360,7 +476,7 @@ static void uartLoop(void *arg1, void *arg2, void *arg3) { currentTime = k_uptime_get(); if (uartState->txState == UartTxState_WaitingForAck) { - uint32_t resendDelay = (UART_RESEND_DELAY << uartState->resendTries); + uint32_t resendDelay = UART_RESEND_DELAY; uint32_t resendTime = uartState->lastMessageSentTime + resendDelay; if (currentTime >= resendTime) { LogU("Uart: didn't receive ack %d, resending (delay %d)\n", currentTime, resendDelay); @@ -515,3 +631,35 @@ void UartBridge_Resume(void) { wakeControlThread(uartState); } + +static void dumpLatency(const char* label, const latency_stats_t* s) { + uint32_t meanUs = s->count == 0 ? 0 : s->sumUs / s->count; + LogU(" %s: n=%u mean=%uus max=%uus\n", label, (unsigned)s->count, (unsigned)meanUs, (unsigned)s->maxUs); + LogU(" hist <1/<4/<16/<64/>=64ms: %u/%u/%u/%u/%u\n", + (unsigned)s->hist[0], (unsigned)s->hist[1], (unsigned)s->hist[2], (unsigned)s->hist[3], (unsigned)s->hist[4]); +} + +void UartBridge_DumpStats(void) { + uart_state_t *uartState = &bridgeState; + uart_link_t *core = &uartState->core; + if (core->device == NULL) { + LogU("Uart bridge: no bridge uart on this routing\n"); + return; + } + LogU("Uart bridge stats (t=%u ms): enabled=%d txState=%d rxState=%d resendTries=%u\n", + (unsigned)Timer_GetCurrentTime(), (int)core->enabled, (int)uartState->txState, (int)uartState->rxState, + (unsigned)uartState->resendTries); + LogU(" frames: sent=%u received=%u crcInvalid=%u unexpectedBytes=%u\n", + (unsigned)stats.framesSent, (unsigned)stats.framesReceived, (unsigned)uartState->invalidMessagesCounter, + (unsigned)stats.unexpectedBytes); + LogU(" acks: whileIdle=%u nack=%u nackWhileIdle=%u\n", + (unsigned)stats.ackWhileIdle, (unsigned)stats.nackReceived, (unsigned)stats.nackWhileIdle); + LogU(" resends: timeout=%u nack=%u giveUps=%u txSendFail=%u txAborted=%u\n", + (unsigned)stats.resendTimeout, (unsigned)stats.resendNack, (unsigned)stats.giveUps, + (unsigned)stats.txSendFail, (unsigned)core->txAbortedCount); + LogU(" rx stopped: overrun=%u framing=%u break=%u other=%u disabled=%u\n", + (unsigned)core->rxStoppedOverrun, (unsigned)core->rxStoppedFraming, (unsigned)core->rxStoppedBreak, + (unsigned)core->rxStoppedOther, (unsigned)core->rxDisabledCount); + dumpLatency("ackLoop (send->ack)", &stats.ackLoop); + dumpLatency("ackTurn (rx->ack tx)", &stats.ackTurn); +} diff --git a/device/src/keyboard/uart_bridge.h b/device/src/keyboard/uart_bridge.h index 55aa6037a..a88eea70a 100644 --- a/device/src/keyboard/uart_bridge.h +++ b/device/src/keyboard/uart_bridge.h @@ -28,4 +28,7 @@ void UartBridge_Suspend(void); void UartBridge_Resume(void); + // Print bridge link diagnostics (frame/ack/resend counters, ack latencies) to the uart log. + void UartBridge_DumpStats(void); + #endif // __UART_H__ diff --git a/device/src/keyboard/uart_link.c b/device/src/keyboard/uart_link.c index fa0e0d29e..47f8fe372 100644 --- a/device/src/keyboard/uart_link.c +++ b/device/src/keyboard/uart_link.c @@ -26,6 +26,7 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void case UART_TX_ABORTED: // TODO: is this needed? // uart_tx(uartState->device, uartState->txBuffer, uartState->txPosition, UART_TIMEOUT); + uartState->txAbortedCount++; LogU("Tx aborted. Please report this!\n"); break; @@ -57,6 +58,7 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void case UART_RX_DISABLED: uartState->enabled = false; + uartState->rxDisabledCount++; // Every RX teardown lands here, including driver-initiated ones (framing/break // errors are routine when RX is enabled mid-byte after a GPIO wake). Let the owner // re-arm RX if it wants it up - otherwise the link stays deaf. @@ -69,6 +71,18 @@ static void uart_callback(const struct device *dev, struct uart_event *evt, void // reason: 1=overrun 2=parity 4=framing 8=break (uart.h uart_rx_stop_reason) BridgeDbg("BRIDGE RX_STOPPED reason %d\n", evt->data.rx_stop.reason); uartState->enabled = false; + { + uint8_t reason = evt->data.rx_stop.reason; + if (reason & UART_ERROR_OVERRUN) { + uartState->rxStoppedOverrun++; + } else if (reason & UART_ERROR_FRAMING) { + uartState->rxStoppedFraming++; + } else if (reason & UART_BREAK) { + uartState->rxStoppedBreak++; + } else { + uartState->rxStoppedOther++; + } + } break; } } @@ -252,7 +266,8 @@ void UartLink_SendWakeByte(uart_link_t *uartState) { return; } - uint8_t wake = UartControlByte_Wake; + // uart_tx reads its buffer by DMA after returning; a stack byte doesn't outlive the call. + static uint8_t wake = UartControlByte_Wake; UartLink_LockBusy(uartState); int err = uart_tx(uartState->device, &wake, 1, UART_TRANSPORT_TIMEOUT_US); if (err != 0) { diff --git a/device/src/keyboard/uart_link.h b/device/src/keyboard/uart_link.h index 7abff8b51..63e6cda7d 100644 --- a/device/src/keyboard/uart_link.h +++ b/device/src/keyboard/uart_link.h @@ -60,6 +60,14 @@ struct k_sem txControlBusy; bool enabled; + // Diagnostics, printed by UartBridge_DumpStats. + uint16_t rxStoppedOverrun; + uint16_t rxStoppedFraming; + uint16_t rxStoppedBreak; + uint16_t rxStoppedOther; + uint16_t rxDisabledCount; + uint16_t txAbortedCount; + // Low-power (UART_LOWPOWER) state struct gpio_dt_spec rxWakePin; // RXD as a GPIO; .port == NULL disables LP struct gpio_callback rxWakeCb; diff --git a/device/src/messenger.c b/device/src/messenger.c index 8bad0d283..e68d27890 100644 --- a/device/src/messenger.c +++ b/device/src/messenger.c @@ -377,7 +377,18 @@ bool processWatermarks(uint8_t srcConnectionId, uint8_t src, const uint8_t* data return false; } - Connections[srcConnectionId].watermarks.rxIdx = data[offset+MessageOffset_Wm]; + connection_watermarks_t* wm = &Connections[srcConnectionId].watermarks; + uint8_t rxIdx = data[offset+MessageOffset_Wm]; + + // A frame whose ack got lost is resent with the same watermark; don't apply it twice + // (key states carry cursor deltas). rxIdxValid guards the first frame after a local + // watermark reset, whose rxIdx is unrelated to what the peer is sending. + if (wm->rxIdxValid && rxIdx == wm->rxIdx) { + return false; + } + + wm->rxIdx = rxIdx; + wm->rxIdxValid = true; return true; } diff --git a/device/src/shell/shell_commands.c b/device/src/shell/shell_commands.c index abde6803f..e371d7dc2 100644 --- a/device/src/shell/shell_commands.c +++ b/device/src/shell/shell_commands.c @@ -24,6 +24,9 @@ #include "stubs.h" #include "slave_drivers/kboot_driver.h" #include "pin_wiring.h" +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT +#include "keyboard/uart_bridge.h" +#endif #include "slot.h" #include "i2c_addresses.h" #include "test_suite/test_suite.h" @@ -523,6 +526,14 @@ static int cmd_uhk_recover(const struct shell *shell, size_t argc, char *argv[]) return 0; } +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT +static int cmd_uhk_uartStats(const struct shell *shell, size_t argc, char *argv[]) +{ + UartBridge_DumpStats(); + return 0; +} +#endif + static int cmd_uhk_jitterTest(const struct shell *shell, size_t argc, char *argv[]) { if (argc == 1) { @@ -597,6 +608,9 @@ void InitShellCommands(void) SHELL_CMD_ARG(testSuite, NULL, "run test suite [module] [test]", cmd_uhk_testSuite, 1, 2), SHELL_CMD_ARG(jitterTest, NULL, "get/set mouse jitter test mode", cmd_uhk_jitterTest, 1, 1), SHELL_CMD_ARG(listActiveKeys, NULL, "list currently pressed keys", cmd_uhk_listActiveKeys, 1, 0), +#if DEVICE_IS_UHK80_LEFT || DEVICE_IS_UHK80_RIGHT + SHELL_CMD_ARG(uartStats, NULL, "print bridge uart link statistics", cmd_uhk_uartStats, 1, 0), +#endif SHELL_CMD_ARG(printStatus, NULL, "print the macro status buffer", cmd_uhk_printStatus, 1, 0), SHELL_CMD_ARG(recover, NULL, "dump diagnostics into the status buffer and reboot", cmd_uhk_recover, 1, 0), SHELL_CMD_ARG(reportEventVector, NULL, "decode an EventVector mask value", cmd_uhk_reportEventVector, 2, 0), diff --git a/right/src/macros/debug_commands.c b/right/src/macros/debug_commands.c index 9646c28c9..43cb9b4f2 100644 --- a/right/src/macros/debug_commands.c +++ b/right/src/macros/debug_commands.c @@ -23,6 +23,7 @@ #include "keyboard/battery_manager.h" #include "keyboard/battery_percent_calculator.h" #include "state_sync.h" +#include "keyboard/uart_bridge.h" #endif macro_result_t Macros_ProcessStatsLayerStackCommand() @@ -153,6 +154,9 @@ void Macros_RecoverDiagnostics(void) Macros_ProcessClearStatusCommand(true); c2usb_diag_dump(); Hid_DumpTransportState(); +#if DEVICE_IS_KEYBOARD && defined(__ZEPHYR__) + UartBridge_DumpStats(); +#endif Trace_Print(LogTarget_Uart | LogTarget_ErrorBuffer, "Diagnostics reboot."); StateWormhole.persistStatusBuffer = true; Reboot(false); diff --git a/shared/uart_parser.c b/shared/uart_parser.c index c6c789fd5..f655970fa 100644 --- a/shared/uart_parser.c +++ b/shared/uart_parser.c @@ -11,8 +11,10 @@ #ifdef DEVICE_ID #include "logger.h" +#include "debug.h" // DEBUG_STRESS_UART #else #define LogU(...) +#define DEBUG_STRESS_UART false #endif #define CRC_SALT 0x1234 @@ -54,11 +56,24 @@ static void processIncomingByte(uart_parser_t *uartState, uint8_t byte) { #if DEBUG_STRESS_UART uint16_t r1 = get_random(); uint8_t r2 = get_random(); + uint16_t r3 = get_random(); + // Mutate byte if (r1 < 128) { - LogU("Oops!\n"); + LogU("UartStress: Oops!\n"); byte = byte ^ r2; } + + // Or drop the byte + if (r3 < 128) { + return; + } + + // More dropped acks, more fun + bool isAckLike = byte == UartControlByte_Ack || byte == UartControlByte_Nack; + if (r3 < 2048 && isAckLike && !uartState->receivingMessage) { + + } #endif