Bench instrumentation: one flag, console and loop timing

-DMESHTASTIC_BENCH_INSTRUMENTATION=1 (default 0) turns on the loss bench's
diagnostic logging, set up in src/BenchInstrumentation.h. It changes no
behaviour, only adds lines and their cost. This part sets:

- MESHTASTIC_LOG_RECORD_MILLIS: API log records carry "millis=<uptime> "
  (a radio task line's own logging time), and console lines print ms.
- MESHTASTIC_SLOW_THREAD_MS (10): "Thread <name> ran <n> ms".
- MESHTASTIC_LOG_USB_STATS: console bytes and log records the port takes
  and refuses, every 10 s; USB stalls of 1 s or more, with the HWCDC
  registers on ESP32-S3 and the TX latch kicks kickLatchedTx() makes;
  the loop's radio upkeep timing.

With the radio task it also logs the task's unused stack at each upkeep.

Co-Authored-By: Jonathan Bennett <jbennett@incomsystems.biz>
Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>
Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9

src/SerialConsole.cpp

@@ -53,6 +53,163 @@ SerialConsole *console;
 static bool s_serialLinkUp = false;
 #endif
 
+#ifdef MESHTASTIC_LOG_USB_STATS
+// Bench: how much console output the port refuses, and what the USB link looks like while it does
+#ifdef HWCDC_TX_KICK
+#define USB_STALL_HW
+#endif
+#include <atomic>
+namespace
+{
+struct UsbStats {
+    uint32_t frames;                      // required frames (packets) written
+    uint32_t logs;                        // best-effort log records offered to the port
+    uint32_t dropRoom, dropTail, dropBig; // log records dropped: ring short of room, a frame tail retained, too big
+    uint32_t dropRetained;                // log records not encoded: a retained frame still owns the log buffer
+    uint32_t dropBusy;                    // log records dropped rather than wait for streamLock (none: they always wait)
+};
+UsbStats usbStats; // framed output, under streamLock
+uint32_t usbStatsAt;
+// Plain-text output (no API client): bytes the port took and refused. Totals, written only under the log lock.
+volatile uint32_t textBytes, textRefused;
+uint32_t textBytesSeen, textRefusedSeen;
+// Times the TX latch held long enough to be kicked, and the kicks (see kickLatchedTx()). Under the log lock.
+volatile uint32_t latches, kicks;
+uint32_t latchesSeen, kicksSeen;
+constexpr size_t usbTxRing = 256; // HWCDC::begin()'s default
+
+// The USB serial peripheral's state, sampled during a stall
+struct UsbHw {
+    uint32_t atMs; // ms into the stall
+    uint16_t ringFree, sof;
+    uint8_t epState, epWr, epRd;
+    bool fifoFree, emptyEna, emptyRaw, plugged, taken;
+};
+
+#ifdef USB_STALL_HW
+void sampleHw(UsbHw &hw, uint32_t atMs)
+{
+    hw.atMs = atMs;
+    hw.ringFree = Port.availableForWrite();
+    hw.fifoFree = USB_SERIAL_JTAG.ep1_conf.serial_in_ep_data_free;
+    hw.emptyEna = USB_SERIAL_JTAG.int_ena.serial_in_empty_int_ena;
+    hw.emptyRaw = USB_SERIAL_JTAG.int_raw.serial_in_empty_int_raw;
+    hw.epState = USB_SERIAL_JTAG.in_ep1_st.in_ep1_state;
+    hw.epWr = USB_SERIAL_JTAG.in_ep1_st.in_ep1_wr_addr;
+    hw.epRd = USB_SERIAL_JTAG.in_ep1_st.in_ep1_rd_addr;
+    hw.sof = USB_SERIAL_JTAG.fram_num.sof_frame_index;
+    hw.plugged = HWCDC::isPlugged();
+    hw.taken = true;
+}
+#endif
+
+// A stall: the port refusing output, from the first refusal to the next write it takes. One of 1 s or more is reported
+// when it ends, since what was logged during it never reached the host.
+enum UsbHwAt { HW_ONSET, HW_100MS, HW_1S, HW_LAST, HW_END, HW_COUNT };
+struct UsbStall {
+    uint32_t fromMs, ms;
+    uint32_t bytes;     // plain-text bytes refused
+    uint32_t drops;     // framed log records refused for room
+    uint32_t unplugged; // refusals that found the USB link without SOFs
+    uint32_t frames;    // packet frames written during it
+    uint32_t latches;   // times the TX latch held long enough to be kicked during it
+    uint32_t kicks;     // times it was kicked
+    bool endedByFrame;
+    UsbHw hw[HW_COUNT];
+};
+UsbStall stallNow, stallDone;
+std::atomic<bool> stallDoneReady;
+std::atomic<uint32_t> stallsUnreported;
+
+void noteRefused(bool text)
+{
+    const uint32_t now = millis();
+    if (!stallNow.fromMs) {
+        stallNow = {};
+        stallNow.fromMs = now ? now : 1;
+#ifdef USB_STALL_HW
+        sampleHw(stallNow.hw[HW_ONSET], 0);
+#endif
+    }
+    if (text)
+        stallNow.bytes++;
+    else
+        stallNow.drops++;
+#ifdef IS_USB_HWCDC
+    if (!HWCDC::isPlugged())
+        stallNow.unplugged++;
+#endif
+#ifdef USB_STALL_HW
+    const uint32_t at = now - stallNow.fromMs;
+    if (at >= 100 && !stallNow.hw[HW_100MS].taken)
+        sampleHw(stallNow.hw[HW_100MS], at);
+    if (at >= 1000 && !stallNow.hw[HW_1S].taken)
+        sampleHw(stallNow.hw[HW_1S], at);
+    if (at >= stallNow.hw[HW_LAST].atMs + 20)
+        sampleHw(stallNow.hw[HW_LAST], at);
+#endif
+}
+
+void noteWritten(bool frame)
+{
+    if (!stallNow.fromMs)
+        return;
+    if (frame)
+        stallNow.frames++;
+    stallNow.ms = millis() - stallNow.fromMs;
+    stallNow.endedByFrame = frame;
+    if (stallNow.ms >= 1000) {
+        if (stallDoneReady.load(std::memory_order_acquire)) {
+            stallsUnreported++;
+        } else {
+#ifdef USB_STALL_HW
+            sampleHw(stallNow.hw[HW_END], stallNow.ms);
+#endif
+            stallDone = stallNow;
+            stallDoneReady.store(true, std::memory_order_release);
+        }
+    }
+    stallNow.fromMs = 0;
+}
+
+void noteText(size_t written)
+{
+    if (written) {
+        textBytes = textBytes + 1;
+        noteWritten(false);
+    } else {
+        textRefused = textRefused + 1;
+        noteRefused(true);
+    }
+}
+
+#ifdef HWCDC_TX_KICK
+/// A byte kickLatchedTx() sends through the FIFO: the ring refused it, and the latch it found has held for 20 ms
+void noteKicked()
+{
+    noteText(0);
+    stallNow.latches++;
+    stallNow.kicks++;
+    latches = latches + 1;
+    kicks = kicks + 1;
+}
+#endif
+
+// The loop's last few radio upkeeps (main.cpp), to place a stall's onset against them
+struct RadioUpkeep {
+    uint32_t fromMs, lockWaitMs, tookMs;
+};
+RadioUpkeep upkeeps[4];
+uint8_t upkeepNext;
+} // namespace
+
+void noteRadioUpkeep(uint32_t fromMs, uint32_t lockWaitMs, uint32_t tookMs)
+{
+    upkeeps[upkeepNext] = {fromMs ? fromMs : 1, lockWaitMs, tookMs};
+    upkeepNext = (upkeepNext + 1) % (sizeof(upkeeps) / sizeof(upkeeps[0]));
+}
+#endif
+
 #ifdef HWCDC_TX_KICK
 namespace
 {
@@ -87,6 +244,9 @@ bool kickLatchedTx(uint8_t c)
     txLatchedSinceMs = 0;
     USB_SERIAL_JTAG.ep1.rdwr_byte = c;
     USB_SERIAL_JTAG.ep1_conf.wr_done = 1;
+#ifdef MESHTASTIC_LOG_USB_STATS
+    noteKicked();
+#endif
     return true;
 }
 } // namespace
@@ -172,6 +332,58 @@ int32_t SerialConsole::runOnce()
     }
 #endif
 
+#ifdef MESHTASTIC_LOG_USB_STATS
+    if (stallDoneReady.load(std::memory_order_acquire)) {
+        const UsbStall stall = stallDone;
+        stallDoneReady.store(false, std::memory_order_release);
+        LOG_INFO("USB stall %u ms from uptime %u ms: refused %u B text, %u records; %u with no SOF; %u frames; ended by %s",
+                 stall.ms, stall.fromMs, stall.bytes, stall.drops, stall.unplugged, stall.frames,
+                 stall.endedByFrame ? "a packet" : "text or a log record");
+        LOG_INFO("USB stall latch: held %u times, kicked %u times", stall.latches, stall.kicks);
+        // The latest radio upkeep that started at or before the onset (upkeeps run on this thread)
+        const RadioUpkeep *before = nullptr;
+        for (const RadioUpkeep &u : upkeeps)
+            if (u.fromMs && (int32_t)(stall.fromMs - u.fromMs) >= 0 && (!before || (int32_t)(u.fromMs - before->fromMs) > 0))
+                before = &u;
+        if (before)
+            LOG_INFO("USB stall upkeep: started %u ms before onset, took %u ms (lock wait %u ms); %u more stalls unreported",
+                     stall.fromMs - before->fromMs, before->tookMs, before->lockWaitMs, stallsUnreported.exchange(0));
+        else
+            LOG_INFO("USB stall upkeep: none recorded before onset; %u more stalls unreported", stallsUnreported.exchange(0));
+#ifdef USB_STALL_HW
+        static const char *const hwAt[HW_COUNT] = {"onset", "100 ms", "1 s", "last", "end"};
+        for (int i = 0; i < HW_COUNT; i++) {
+            const UsbHw &hw = stall.hw[i];
+            if (hw.taken)
+                LOG_INFO(
+                    "USB stall hw %s +%u ms: ring free %u, FIFO free %u, IN_EMPTY ena %u raw %u, EP1 st %u wr %u rd %u, SOF %u, "
+                    "plugged %u",
+                    hwAt[i], hw.atMs, hw.ringFree, hw.fifoFree, hw.emptyEna, hw.emptyRaw, hw.epState, hw.epWr, hw.epRd, hw.sof,
+                    hw.plugged);
+        }
+#endif
+    }
+    if (Throttle::hasElapsed(usbStatsAt, 10000)) {
+        usbStatsAt = millis();
+        UsbStats seen;
+        {
+            concurrency::LockGuard guard(&streamLock);
+            seen = usbStats;
+            usbStats = {};
+        }
+        const uint32_t bytes = textBytes, refused = textRefused;
+        LOG_INFO("USB 10 s: text %u B, refused %u B; frames %u; logs %u, dropped room %u tail %u big %u retained %u busy %u",
+                 bytes - textBytesSeen, refused - textRefusedSeen, seen.frames, seen.logs, seen.dropRoom, seen.dropTail,
+                 seen.dropBig, seen.dropRetained, seen.dropBusy);
+        textBytesSeen = bytes;
+        textRefusedSeen = refused;
+        const uint32_t held = latches, kicked = kicks;
+        if (held != latchesSeen || kicked != kicksSeen)
+            LOG_INFO("USB 10 s latch: held %u times, kicked %u times", held - latchesSeen, kicked - kicksSeen);
+        latchesSeen = held;
+        kicksSeen = kicked;
+    }
+#endif
     int32_t delay = runOncePart();
 #if defined(SERIAL_HAS_ON_RECEIVE) || defined(CONFIG_IDF_TARGET_ESP32S2)
     // Nothing wakes the idle sleep for "TX space freed" or a bounded-drain remainder
@@ -221,7 +433,13 @@ size_t SerialConsole::writeText(uint8_t c)
     if ((!config.has_lora || serialEnabled) && kickLatchedTx(c))
         return 1;
 #endif
+#ifdef MESHTASTIC_LOG_USB_STATS
+    RedirectablePrint::write(c);
+    noteText(destWritten);
+    return 1;
+#else
     return RedirectablePrint::write(c);
+#endif
 }
 
 /// Wake the serial worker when PhoneAPI queues output.
@@ -296,7 +514,15 @@ bool SerialConsole::canEncodeLogRecord()
 {
 #ifdef IS_USB_SERIAL
     concurrency::LockGuard guard(&streamLock);
+#ifdef MESHTASTIC_LOG_USB_STATS
+    if (!frameWriter.isIdle()) {
+        usbStats.dropRetained++;
+        return false;
+    }
+    return true;
+#else
     return frameWriter.isIdle();
+#endif
 #else
     return true;
 #endif
@@ -312,7 +538,29 @@ bool SerialConsole::writeFrame(uint8_t *buf, size_t len, bool bestEffort)
     const size_t totalLen = buildFrameHeader(buf, len);
 
     concurrency::LockGuard guard(&streamLock);
+#ifdef MESHTASTIC_LOG_USB_STATS
+    const bool written = frameWriter.writeFrame(Port, buf, totalLen, bestEffort);
+    if (bestEffort) {
+        usbStats.logs++;
+        if (written) {
+            noteWritten(false);
+        } else if (!frameWriter.isIdle()) {
+            usbStats.dropTail++;
+        } else if (totalLen > usbTxRing) {
+            usbStats.dropBig++;
+        } else {
+            usbStats.dropRoom++;
+            noteRefused(false);
+        }
+    } else {
+        usbStats.frames++;
+        if (written)
+            noteWritten(true);
+    }
+    return written;
+#else
     return frameWriter.writeFrame(Port, buf, totalLen, bestEffort);
+#endif
 #else
     return StreamAPI::writeFrame(buf, len, bestEffort);
 #endif