From 94ab80fbc59344dfb804aefbb8148735fa3d4bbe Mon Sep 17 00:00:00 2001 From: Jonathan Bennett Date: Mon, 5 Oct 2026 03:16:55 +0000 Subject: [PATCH] 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= " (a radio task line's own logging time), and console lines print ms. - MESHTASTIC_SLOW_THREAD_MS (10): "Thread ran 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 Co-Authored-By: Claude Opus 5.5 Claude-Session: https://claude.ai/code/session_01REkPVFh6kvG4AZJ5A8AtM9 --- src/BenchInstrumentation.h | 23 ++++ src/RedirectablePrint.cpp | 23 ++++ src/RedirectablePrint.h | 6 + src/SerialConsole.cpp | 248 ++++++++++++++++++++++++++++++++++ src/SerialConsole.h | 5 + src/concurrency/OSThread.cpp | 9 ++ src/concurrency/RadioTask.cpp | 35 +++++ src/concurrency/RadioTask.h | 11 ++ src/configuration.h | 1 + src/main.cpp | 11 ++ src/mesh/StreamAPI.cpp | 25 ++++ 11 files changed, 397 insertions(+) create mode 100644 src/BenchInstrumentation.h diff --git a/src/BenchInstrumentation.h b/src/BenchInstrumentation.h new file mode 100644 index 0000000000..0ba8d0888a --- /dev/null +++ b/src/BenchInstrumentation.h @@ -0,0 +1,23 @@ +#pragma once + +// -DMESHTASTIC_BENCH_INSTRUMENTATION=1 turns on the loss bench's diagnostic logging: timing and state lines its analysis +// scripts parse, so their formats must not change. It adds the lines and their cost, and changes no behaviour. Default 0. +// It sets each switch below, which can also be set on its own. +#ifndef MESHTASTIC_BENCH_INSTRUMENTATION +#define MESHTASTIC_BENCH_INSTRUMENTATION 0 +#endif + +#if MESHTASTIC_BENCH_INSTRUMENTATION +// Stamp each API log record with the node's millis(), and print it to the ms on the console +#ifndef MESHTASTIC_LOG_RECORD_MILLIS +#define MESHTASTIC_LOG_RECORD_MILLIS +#endif +// Log each thread run that holds the main loop at least this many ms +#ifndef MESHTASTIC_SLOW_THREAD_MS +#define MESHTASTIC_SLOW_THREAD_MS 10 +#endif +// Count the console output the port refuses, and report each USB stall of 1 s or more +#ifndef MESHTASTIC_LOG_USB_STATS +#define MESHTASTIC_LOG_USB_STATS +#endif +#endif diff --git a/src/RedirectablePrint.cpp b/src/RedirectablePrint.cpp index 5023434cb1..cf346d26b9 100644 --- a/src/RedirectablePrint.cpp +++ b/src/RedirectablePrint.cpp @@ -32,6 +32,9 @@ namespace struct RadioTaskLog { const char *level; const concurrency::OSThread *thread; +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + uint32_t ms; // when it was logged, for the log record's stamp +#endif char text[240]; }; #ifndef MESHTASTIC_RADIO_TASK_LOG_LINES @@ -60,6 +63,9 @@ void RedirectablePrint::drainRadioTaskLogs() __asm__ __volatile__("" ::: "memory"); // read the entry only after seeing the head that published it const RadioTaskLog &line = radioTaskLogs[radioTaskLogTail]; concurrency::setLoggingFor(line.thread); +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + concurrency::setLoggedAtMs(line.ms); +#endif log(line.level, "%s", line.text); concurrency::clearLoggingFor(); __asm__ __volatile__("" ::: "memory"); // and free its slot only after printing it @@ -91,8 +97,12 @@ size_t RedirectablePrint::write(uint8_t c) #endif // Account for legacy config transition bool serialEnabled = config.has_security ? config.security.serial_enabled : config.device.serial_enabled; +#ifdef MESHTASTIC_LOG_USB_STATS + destWritten = !config.has_lora || serialEnabled ? dest->write(c) : 1; +#else if (!config.has_lora || serialEnabled) dest->write(c); +#endif return 1; // We always claim one was written, rather than trusting what the // serial port said (which could be zero) @@ -208,7 +218,12 @@ void RedirectablePrint::log_to_serial(const char *logLevel, const char *format, if (color) { printf("\u001b[0m"); } +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + const uint32_t nowMs = millis(); + printf("| %02d:%02d:%02d %u.%03u ", hour, min, sec, (unsigned)(nowMs / 1000), (unsigned)(nowMs % 1000)); +#else printf("| %02d:%02d:%02d %u ", hour, min, sec, millis() / 1000); +#endif #endif } else { #ifdef ARCH_PORTDUINO @@ -222,7 +237,12 @@ void RedirectablePrint::log_to_serial(const char *logLevel, const char *format, if (color) { printf("\u001b[0m"); } +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + const uint32_t nowMs = millis(); + printf("| ??:??:?? %u.%03u ", (unsigned)(nowMs / 1000), (unsigned)(nowMs % 1000)); +#else printf("| ??:??:?? %u ", millis() / 1000); +#endif #endif } auto thread = concurrency::OSThread::current(); @@ -388,6 +408,9 @@ void RedirectablePrint::log(const char *logLevel, const char *format, ...) RadioTaskLog &line = radioTaskLogs[radioTaskLogHead]; line.level = logLevel; line.thread = concurrency::OSThread::current(); +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + line.ms = millis(); +#endif va_list arg; va_start(arg, format); vsnprintf(line.text, sizeof(line.text), format, arg); diff --git a/src/RedirectablePrint.h b/src/RedirectablePrint.h index 7f18a36211..d7653562e3 100644 --- a/src/RedirectablePrint.h +++ b/src/RedirectablePrint.h @@ -1,6 +1,7 @@ #pragma once #include "../freertosinc.h" +#include "BenchInstrumentation.h" #include "Print.h" #include "mesh/generated/meshtastic/mesh.pb.h" #include @@ -55,6 +56,11 @@ class RedirectablePrint : public Print std::string mt_sprintf(const std::string fmt_str, ...); protected: +#ifdef MESHTASTIC_LOG_USB_STATS + /// Bench: what the destination took of the last byte write() passed it (write() itself always claims 1) + size_t destWritten = 1; +#endif + /// Subclasses can override if they need to change how we format over the serial port virtual void log_to_serial(const char *logLevel, const char *format, va_list arg); meshtastic_LogRecord_Level getLogLevel(const char *logLevel); diff --git a/src/SerialConsole.cpp b/src/SerialConsole.cpp index 9d3b9662e4..b2b9cd5972 100644 --- a/src/SerialConsole.cpp +++ b/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 +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 stallDoneReady; +std::atomic 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 diff --git a/src/SerialConsole.h b/src/SerialConsole.h index 1a06c1428d..2fced29fbe 100644 --- a/src/SerialConsole.h +++ b/src/SerialConsole.h @@ -74,4 +74,9 @@ class SerialConsole : public StreamAPI, public RedirectablePrint, private concur // A simple wrapper to allow non class aware code write to the console void consoleInit(); +#ifdef MESHTASTIC_LOG_USB_STATS +/// Bench: the loop's periodic radio upkeep (noise floor, AGC reset), so a console stall's onset can be placed against it +void noteRadioUpkeep(uint32_t fromMs, uint32_t lockWaitMs, uint32_t tookMs); +#endif + extern SerialConsole *console; \ No newline at end of file diff --git a/src/concurrency/OSThread.cpp b/src/concurrency/OSThread.cpp index 502098e33c..a33c048020 100644 --- a/src/concurrency/OSThread.cpp +++ b/src/concurrency/OSThread.cpp @@ -105,8 +105,17 @@ void OSThread::run() const OSThread *&running = currentThread; #endif running = this; +#ifdef MESHTASTIC_SLOW_THREAD_MS + const uint32_t startedMs = millis(); +#endif fromNowDuringRun = false; auto newDelay = runOnce(); +#ifdef MESHTASTIC_SLOW_THREAD_MS + // Bench: a thread that holds the main loop this long delays every other thread, the radio's RX handler included. + const uint32_t tookMs = millis() - startedMs; + if (tookMs >= MESHTASTIC_SLOW_THREAD_MS) + LOG_DEBUG("Thread %s ran %u ms", ThreadName.c_str(), (unsigned)tookMs); +#endif #ifdef DEBUG_HEAP auto newHeap = memGet.getFreeHeap(); if (newHeap < heap) diff --git a/src/concurrency/RadioTask.cpp b/src/concurrency/RadioTask.cpp index 8d1aa21ca1..3ebd2deecd 100644 --- a/src/concurrency/RadioTask.cpp +++ b/src/concurrency/RadioTask.cpp @@ -32,6 +32,9 @@ uint32_t radioMutexDepth; TaskHandle_t radioTask; // The line the loop is printing for the radio task (see RedirectablePrint::drainRadioTaskLogs) const OSThread *loggingForThread; +#ifdef MESHTASTIC_LOG_RECORD_MILLIS +uint32_t loggedAtMsec; +#endif TaskHandle_t volatile loggingForTask; void radioTaskMain(void *) @@ -125,6 +128,38 @@ bool loggingFor(const OSThread **thread) return true; } +#ifdef MESHTASTIC_LOG_RECORD_MILLIS +void setLoggedAtMs(uint32_t ms) +{ + loggedAtMsec = ms; +} + +bool loggedAtMs(uint32_t *ms) +{ + if (!loggingFor(nullptr)) + return false; + *ms = loggedAtMsec; + return true; +} +#endif + +#if MESHTASTIC_BENCH_INSTRUMENTATION +uint32_t radioTaskStackFree() +{ +#if INCLUDE_uxTaskGetStackHighWaterMark + if (!radioTask) + return 0; +#ifdef ARCH_ESP32 + return uxTaskGetStackHighWaterMark(radioTask); +#else + return uxTaskGetStackHighWaterMark(radioTask) * sizeof(StackType_t); +#endif +#else + return 0; +#endif +} +#endif + } // namespace concurrency #endif diff --git a/src/concurrency/RadioTask.h b/src/concurrency/RadioTask.h index 50a38743ee..1b8eb33b0b 100644 --- a/src/concurrency/RadioTask.h +++ b/src/concurrency/RadioTask.h @@ -3,6 +3,8 @@ // -DMESHTASTIC_RADIO_TASK (ESP32 and nRF52) runs the RadioLib radio thread from its own FreeRTOS task, one priority above // the main loop, so a main-loop hold can no longer delay a scan, a launch or the TX_DONE handling. The task holds the radio // lock while the radio thread runs, and the loop takes it with RADIO_TASK_LOCK() wherever it reaches into the radio. +#include "BenchInstrumentation.h" + #ifdef MESHTASTIC_RADIO_TASK #include "ThreadController.h" @@ -30,6 +32,15 @@ class OSThread; void setLoggingFor(const OSThread *thread); void clearLoggingFor(); bool loggingFor(const OSThread **thread); +#ifdef MESHTASTIC_LOG_RECORD_MILLIS +/// Bench: with setLoggingFor(), the millis() the line was logged at, for its log record's stamp; false off the printing task +void setLoggedAtMs(uint32_t ms); +bool loggedAtMs(uint32_t *ms); +#endif +#if MESHTASTIC_BENCH_INSTRUMENTATION +/// Bench: the task's stack high-water mark in bytes, 0 before it starts +uint32_t radioTaskStackFree(); +#endif class RadioTaskLockGuard { diff --git a/src/configuration.h b/src/configuration.h index 5da3c7c801..0e904ff65b 100644 --- a/src/configuration.h +++ b/src/configuration.h @@ -766,5 +766,6 @@ along with this program. If not, see . #endif // MESHTASTIC_LOCKDOWN +#include "BenchInstrumentation.h" #include "DebugConfiguration.h" #include "RF95Configuration.h" diff --git a/src/main.cpp b/src/main.cpp index 6750cc2b39..01d96f3891 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -1509,8 +1509,19 @@ void loop() lastAgcReset = millis(); // Sample before resetAGC(): recalibrating the frontend biases an RSSI read taken right after it. RADIO_TASK_LOCK(); +#ifdef MESHTASTIC_LOG_USB_STATS + const uint32_t lockedMs = millis(); +#endif RadioLibInterface::instance->updateNoiseFloor(); RadioLibInterface::instance->periodicRadioMaintenance(); +#ifdef MESHTASTIC_LOG_USB_STATS + const uint32_t doneMs = millis(); + noteRadioUpkeep(lastAgcReset, lockedMs - lastAgcReset, doneMs - lastAgcReset); + LOG_DEBUG("Radio upkeep: lock wait %u ms, took %u ms", lockedMs - lastAgcReset, doneMs - lastAgcReset); +#endif +#if MESHTASTIC_BENCH_INSTRUMENTATION && defined(MESHTASTIC_RADIO_TASK) + LOG_DEBUG("Radio task stack: %u bytes never used", (unsigned)concurrency::radioTaskStackFree()); +#endif } } diff --git a/src/mesh/StreamAPI.cpp b/src/mesh/StreamAPI.cpp index 7d3ca39532..ac2c8e444f 100644 --- a/src/mesh/StreamAPI.cpp +++ b/src/mesh/StreamAPI.cpp @@ -6,6 +6,9 @@ #include "StreamAPI.h" #include "Throttle.h" #include "concurrency/LockGuard.h" +#if defined(MESHTASTIC_LOG_RECORD_MILLIS) && defined(MESHTASTIC_RADIO_TASK) +#include "concurrency/RadioTask.h" +#endif #include "gps/RTC.h" #define START1 0x94 @@ -268,11 +271,33 @@ void StreamAPI::emitLogRecord(meshtastic_LogRecord_Level level, const char *src, fromRadioScratchLog.log_record.time = rtc_sec; strncpy(fromRadioScratchLog.log_record.source, src, sizeof(fromRadioScratchLog.log_record.source) - 1); +#ifdef MESHTASTIC_LOG_RECORD_MILLIS + char *message = fromRadioScratchLog.log_record.message; + size_t room = sizeof(fromRadioScratchLog.log_record.message) - 1; + // Bench: LogRecord.time is whole seconds, and the host's arrival stamp carries the link's queueing delay. + // Uptime taken here, as the line is logged, lets a node's events be lined up with other nodes' to the ms. + unsigned long stampMs = millis(); +#ifdef MESHTASTIC_RADIO_TASK + uint32_t loggedMs; + if (concurrency::loggedAtMs(&loggedMs)) + stampMs = loggedMs; // a radio task line the loop is printing now +#endif + const int stamped = snprintf(message, room, "millis=%lu ", stampMs); + if (stamped > 0 && (size_t)stamped < room) { + message += stamped; + room -= stamped; + } + auto num_printed = vsnprintf(message, room, format, arg); + if (num_printed > 0 && (size_t)num_printed <= room && + message[num_printed - 1] == '\n') // Strip any ending newline, because we have records for framing instead. + message[num_printed - 1] = '\0'; +#else auto num_printed = vsnprintf(fromRadioScratchLog.log_record.message, sizeof(fromRadioScratchLog.log_record.message) - 1, format, arg); if (num_printed > 0 && fromRadioScratchLog.log_record.message[num_printed - 1] == '\n') // Strip any ending newline, because we have records for framing instead. fromRadioScratchLog.log_record.message[num_printed - 1] = '\0'; +#endif size_t len = pb_encode_to_bytes(txBufLog + HEADER_LEN, meshtastic_FromRadio_size, &meshtastic_FromRadio_msg, &fromRadioScratchLog);