diff --git a/lib/Epub/Epub/Section.cpp b/lib/Epub/Epub/Section.cpp index 24385c4b6e4..be0240de452 100644 --- a/lib/Epub/Epub/Section.cpp +++ b/lib/Epub/Epub/Section.cpp @@ -7,6 +7,7 @@ #include #include +#include "../../../src/util/InputDiag.h" #include "Epub/css/CssParser.h" #include "Page.h" #include "hyphenation/Hyphenator.h" @@ -98,12 +99,17 @@ uint32_t Section::onPageComplete(std::unique_ptr page) { return 0; } + // Timed apart from the rest of the build: writing a laid-out page to the card is the one + // phase that is storage-bound rather than parse- or measure-bound, so it has to be separable + // before anything is attributed to "the build being slow". + const unsigned long writeStartMs = millis(); const uint32_t position = file.position(); if (!page->serialize(file)) { LOG_ERR("SCT", "Failed to serialize page %d", builtPageCount_); return 0; } LOG_DBG("SCT", "Page %d processed", builtPageCount_); + InputDiag::noteBuildPageWrite(millis() - writeStartMs); builtPageCount_++; // pageCount is the pages available to read: a rebuild over a partial only raises it diff --git a/lib/hal/HalGPIO.cpp b/lib/hal/HalGPIO.cpp index 90d180dcdad..0fa88acd901 100644 --- a/lib/hal/HalGPIO.cpp +++ b/lib/hal/HalGPIO.cpp @@ -156,6 +156,8 @@ bool HalGPIO::wasAnyPressed() const { return inputMgr.wasAnyPressed(); } bool HalGPIO::wasReleased(uint8_t buttonIndex) const { return inputMgr.wasReleased(buttonIndex); } +bool HalGPIO::isDebouncePending() const { return inputMgr.isDebouncePending(); } + bool HalGPIO::wasAnyReleased() const { return inputMgr.wasAnyReleased(); } bool HalGPIO::rawInputActive() { diff --git a/lib/hal/HalGPIO.h b/lib/hal/HalGPIO.h index f35740e2947..1325f2cc1c4 100644 --- a/lib/hal/HalGPIO.h +++ b/lib/hal/HalGPIO.h @@ -75,6 +75,9 @@ class HalGPIO { bool wasPressed(uint8_t buttonIndex) const; bool wasAnyPressed() const; bool wasReleased(uint8_t buttonIndex) const; + // A button sample changed but has not been committed yet (InputManager's two-sample debounce). + // Consumed by the INPUT_DIAG timing diagnostics. + bool isDebouncePending() const; bool wasAnyReleased() const; unsigned long getHeldTime() const; unsigned long getPowerButtonHeldTime() const; diff --git a/lib/hal/HalSystem.cpp b/lib/hal/HalSystem.cpp index e02ddd18f06..a40b6a8bab9 100644 --- a/lib/hal/HalSystem.cpp +++ b/lib/hal/HalSystem.cpp @@ -10,6 +10,10 @@ #include "esp_private/esp_cpu_internal.h" #include "esp_private/esp_system_attr.h" #include "esp_private/panic_internal.h" +// Generated per build by scripts/ost_version.py. The version macro names the commit, which +// cannot tell two builds apart while the tree carries uncommitted changes -- and a crash +// report read against the wrong firmware is worse than no report. +#include "ostBuildId.generated.h" #if !__riscv #include // XtExcFrame for the stack capture below #endif @@ -165,7 +169,8 @@ std::string getPanicInfo(bool full) { } else { std::string info; - info += "CrossPoint version: " CROSSPOINT_VERSION; + info += "OST build: " OST_BUILD_ID; + info += "\nCrossPoint version: " CROSSPOINT_VERSION; // A lockup or hardware watchdog resets without running any panic hook, so // the reason and stack come back empty; the reset cause is then the only // way to tell those apart from a true panic. diff --git a/platformio.ini b/platformio.ini index e6b5d0f7d00..9cf06aa5290 100644 --- a/platformio.ini +++ b/platformio.ini @@ -117,6 +117,7 @@ extra_scripts = pre:scripts/build_html.py pre:scripts/gen_i18n.py pre:scripts/git_branch.py + pre:scripts/ost_version.py pre:scripts/patch_jpegdec.py post:scripts/register_unit_tests_target.py post:scripts/patch_arduino_rom_libc.py diff --git a/scripts/ost_version.py b/scripts/ost_version.py new file mode 100644 index 00000000000..ca631f04340 --- /dev/null +++ b/scripts/ost_version.py @@ -0,0 +1,170 @@ +""" +PlatformIO pre-build script: stamp this fork's build marker. + +Upstream numbers its releases, but a fork rebuilt several times a day has no way +to tell one binary from the next -- neither the .bin files waiting on the desk +nor the firmware already on the device. This stamps both. + +Version format: YYYYMMDDNN -- the build date plus a counter starting at 01 each +day, so 2026080901 is the first build of 9 August 2026. + +The counter lives in .ost-build (gitignored) and is deliberately local to this +machine. It answers "which build is on the device", not "which release is this", +so there is nothing for anyone else to reproduce. A fresh clone restarts at 01; +the date in front keeps the ordering right regardless. + +Copies the built image to dist/ under a name carrying the number. Diagnostic +builds (INPUT_DIAG) get a -diag suffix so the two cannot be confused on the card. + +The number stays out of the compile: defining it (a past OST_VERSION macro) put +a value that changes every build into every translation unit's command line, +which invalidated all objects -- libraries included -- and made each no-change +rebuild a 3-minute full recompile. Nothing ever read the macro; the filename is +the only consumer. If the firmware is ever to display it, generate a header and +include it from the one file that shows it. +""" + +import datetime +import os +import shlex +import shutil +import sys + +COUNTER_FILE = '.ost-build' +DIST_DIR = 'dist' + + +def warn(msg): + print(f'WARNING [ost_version.py]: {msg}', file=sys.stderr) + + +def next_version(project_dir): + """Return YYYYMMDDNN, advancing the per-day counter.""" + today = datetime.date.today().strftime('%Y%m%d') + path = os.path.join(project_dir, COUNTER_FILE) + + stored_date, stored_seq = '', 0 + try: + with open(path, 'r', encoding='utf-8') as f: + stored_date, _, seq_text = f.read().strip().partition(' ') + stored_seq = int(seq_text) + except FileNotFoundError: + pass + except (ValueError, OSError) as e: + warn(f'could not read {COUNTER_FILE} ({e}); restarting the counter') + + seq = stored_seq + 1 if stored_date == today else 1 + if seq > 99: + # Two digits is the format. Past 99 builds in a day, keep counting rather + # than silently reusing a number -- the string just gets one wider. + warn(f'{seq} builds today; the number is now wider than 10 digits') + + try: + with open(path, 'w', encoding='utf-8') as f: + f.write(f'{today} {seq}\n') + except OSError as e: + warn(f'could not write {COUNTER_FILE} ({e}); the number may repeat') + + return f'{today}{seq:02d}' + + +def _flag_sets_input_diag(text): + return text == '-DINPUT_DIAG' or text.startswith('-DINPUT_DIAG=') + + +def has_input_diag(env): + """True when this build carries INPUT_DIAG. + + Every route the flag can arrive by is checked, because a diagnostic image + named as a plain one is the mix-up this suffix exists to prevent, and the + cost of it lands on the device: an SD write and a repro cycle against + firmware that is not what it says it is. + + The routes differ in when they become visible. A pre: script runs before + PlatformIO has folded build_flags into CPPDEFINES, so a -D from + platformio.ini or platformio.local.ini is still only in the raw flag list; + PLATFORMIO_BUILD_FLAGS reaches the compiler without passing through either + at that point, and is only readable from the environment. Called again from + the post action, CPPDEFINES has everything -- main() ORs the two, so a route + that misses one is still caught by the other. + """ + for define in env.get('CPPDEFINES', []): + name = define[0] if isinstance(define, (list, tuple)) else define + if str(name) == 'INPUT_DIAG': + return True + + for flag in env.get('BUILD_FLAGS', []) or []: + if _flag_sets_input_diag(str(flag)): + return True + + for var in ('PLATFORMIO_BUILD_FLAGS', 'PLATFORMIO_BUILD_SRC_FLAGS'): + raw = os.environ.get(var) + if not raw: + continue + try: + flags = shlex.split(raw) + except ValueError: + # Unbalanced quotes: fall back to whitespace splitting rather than + # reporting a diagnostic build as plain. + flags = raw.split() + if any(_flag_sets_input_diag(f) for f in flags): + return True + + return False + + +def write_build_id_header(project_dir, build_id): + """Publish the build number to the firmware through a generated header. + + A define would reach every translation unit and make each build a full + rebuild; only the two files that write diagnostics need the string, so it + goes in a header that only they include. It lives under lib/hal because + that path is reachable from both lib and src, which src/util is not. + """ + path = os.path.join(project_dir, 'lib', 'hal', 'ostBuildId.generated.h') + body = f'#pragma once\n#define OST_BUILD_ID "{build_id}"\n' + try: + with open(path, 'r', encoding='utf-8') as f: + if f.read() == body: + return + except OSError: + pass + try: + with open(path, 'w', encoding='utf-8') as f: + f.write(body) + except OSError as e: + warn(f'could not write {path} ({e}); the build id will be stale') + + +def copy_to_dist(project_dir, version, suffix, source): + dist = os.path.join(project_dir, DIST_DIR) + target = os.path.join(dist, f'crosspoint-OST-{version}{suffix}.bin') + try: + os.makedirs(dist, exist_ok=True) + shutil.copyfile(source, target) + print(f'OST build {version}{suffix} -> {os.path.relpath(target, project_dir)}') + except OSError as e: + warn(f'could not copy the image to {DIST_DIR} ({e})') + + +def main(env): + project_dir = env.subst('$PROJECT_DIR') + version = next_version(project_dir) + diag_at_pre = has_input_diag(env) + write_build_id_header(project_dir, f'{version}{"-diag" if diag_at_pre else ""}') + + def post_action(target, source, env): + # Re-check against the fully folded environment and keep whichever pass + # saw the flag: the name has to be wrong in the safe direction. + suffix = '-diag' if (diag_at_pre or has_input_diag(env)) else '' + copy_to_dist(project_dir, version, suffix, str(target[0])) + + env.AddPostAction('$BUILD_DIR/${PROGNAME}.bin', post_action) + + +# PlatformIO/SCons entry point — Import and env are SCons builtins injected at runtime. +try: + Import('env') # noqa: F821 # type: ignore[name-defined] + main(env) # noqa: F821 # type: ignore[name-defined] +except NameError: + pass diff --git a/src/activities/ActivityManager.cpp b/src/activities/ActivityManager.cpp index bef68c5e738..a777b2faba3 100644 --- a/src/activities/ActivityManager.cpp +++ b/src/activities/ActivityManager.cpp @@ -28,6 +28,7 @@ #include "util/BmpViewerActivity.h" #include "util/FrontlightPanelActivity.h" #include "util/FullScreenMessageActivity.h" +#include "util/InputDiag.h" static portMUX_TYPE activityManagerSpinlock = portMUX_INITIALIZER_UNLOCKED; @@ -70,10 +71,36 @@ void ActivityManager::renderTaskLoop() { RenderLock lock; if (currentActivity) { HalPowerManager::Lock powerLock; // Ensure we don't go into low-power mode while rendering +#ifdef INPUT_DIAG + // Snapshot the name onto the stack before rendering. render() receives the lock by value and + // may release it partway, after which the main task can pop and destroy this activity -- so + // reading the name after render() returns is not safe. Guarded rather than routed through the + // no-op InputDiag stub because the snapshot itself would otherwise cost every build a copy. + char renderedName[16]; + snprintf(renderedName, sizeof(renderedName), "%s", currentActivity->name.c_str()); + const unsigned long renderStart = millis(); + InputDiag::noteRenderStart(); +#endif // Night mode is a global output polarity applied to every activity. // The sleep screen forces normal polarity itself (SleepActivity). display.setInverted(SETTINGS.screenInverted != 0); currentActivity->render(std::move(lock)); +#ifdef INPUT_DIAG + const unsigned long renderDurationMs = millis() - renderStart; + // The glyph counters (on-demand loads, arena rebuilds) come with the font stage; 0 until then. + InputDiag::noteRender(renderedName, renderDurationMs, 0, 0, 0); + // A render this slow isn't drawing -- it's stuck somewhere upstream (SD I/O, glyph + // cache, allocation). The 16-line log ring is system-wide and short, so whatever ran + // during the stall is likely still in it right now; a routine render would evict it + // within a few more renders. captureLogs() keeps only the first capture, so repeat + // stalls this session don't overwrite the one that still has the culprit. + constexpr unsigned long SLOW_RENDER_CAPTURE_MS = 5000; + if (renderDurationMs >= SLOW_RENDER_CAPTURE_MS) { + char reason[48]; + snprintf(reason, sizeof(reason), "slow-render %s %lums", renderedName, renderDurationMs); + InputDiag::captureLogs(reason); + } +#endif } // Notify any task blocked in requestUpdateAndWait() that the render is done. TaskHandle_t waiter = nullptr; diff --git a/src/activities/home/HomeActivity.cpp b/src/activities/home/HomeActivity.cpp index 83df634d099..63adbe3923a 100644 --- a/src/activities/home/HomeActivity.cpp +++ b/src/activities/home/HomeActivity.cpp @@ -24,6 +24,7 @@ #include "RecentBooksStore.h" #include "components/UITheme.h" #include "fontIds.h" +#include "util/InputDiag.h" int HomeActivity::getMenuItemCount() const { int count = 4; // File Browser, Library, File transfer, Settings @@ -227,6 +228,8 @@ void HomeActivity::loadRecentCovers(int coverHeight) { void HomeActivity::onEnter() { Activity::onEnter(); + // What is still allocated once the previous screen is gone (diag builds only). + InputDiag::dumpHeapMap("home-enter"); hasOpdsServers = OPDS_STORE.hasServers(); diff --git a/src/activities/reader/EpubReaderActivity.cpp b/src/activities/reader/EpubReaderActivity.cpp index 2bde8919bec..6c7113b6cb5 100644 --- a/src/activities/reader/EpubReaderActivity.cpp +++ b/src/activities/reader/EpubReaderActivity.cpp @@ -45,6 +45,7 @@ #include "fontIds.h" #include "util/BookmarkUtil.h" #include "util/ButtonNavigator.h" +#include "util/InputDiag.h" #include "util/ScreenshotUtil.h" namespace { @@ -162,6 +163,7 @@ EpubReaderActivity::~EpubReaderActivity() { saveProgress(origin.spineIndex, origin.pageNumber, 0); } + const uint32_t freeBefore = ESP.getFreeHeap(); section.reset(); if (pendingReadFolderMove && epub) { const std::string srcPath = epub->getPath(); @@ -172,9 +174,13 @@ EpubReaderActivity::~EpubReaderActivity() { } else { epub.reset(); } + + InputDiag::noteCloseHeap(freeBefore / 1024, ESP.getFreeHeap() / 1024, ESP.getMaxAllocHeap() / 1024); } bool EpubReaderActivity::loadBook() { + InputDiag::noteOpenBegin(); + InputDiag::noteOpenStage(0, "enter"); auto loadedEpub = makeUniqueNoThrow(bookPath, "/.crosspoint"); if (!loadedEpub) { LOG_ERR("ERS", "Failed to allocate EPUB object"); @@ -198,6 +204,7 @@ bool EpubReaderActivity::loadBook() { return false; } epub = std::move(loadedEpub); + InputDiag::noteOpenStage(1, "epub"); ImageBlock::clearRenderFailures(); ImageBlock::setExtractor(epub.get(), [](void* ctx, const char* src, const char* dest) { @@ -429,8 +436,9 @@ void EpubReaderActivity::loop() { { RenderLock lock(RenderLock::Mode::Try); if (lock.ownsLock() && backgroundBuildWanted() && buildTickHeapGate()) { - if (!section->buildSomeMore(BACKGROUND_BUILD_PAGES_PER_TICK)) { + if (!buildChunkTimed(BACKGROUND_BUILD_PAGES_PER_TICK)) { LOG_ERR("ERS", "Background section build failed"); + InputDiag::captureLogs("section-build-failed"); section.reset(); requestUpdate(); } else if (section->isBuildComplete() && applyDeferredReposition()) { @@ -1143,9 +1151,22 @@ bool EpubReaderActivity::skipLoopDelay() { return !buildHeapPaused && backgroundBuildWanted(); } +bool EpubReaderActivity::buildChunkTimed(const uint16_t pages) { + const uint16_t pageCountBefore = section->pageCount; + const unsigned long startMs = millis(); + const bool ok = section->buildSomeMore(pages); + const unsigned long chunkMs = millis() - startMs; + InputDiag::noteBuildChunk(currentSpineIndex, pageCountBefore, section->pageCount, chunkMs); + buildAccumMsThisRender += chunkMs; + buildChunkCountThisRender++; + return ok; +} + void EpubReaderActivity::renderBook() { currentPageLinks.clear(); if (!epub) return; + buildAccumMsThisRender = 0; + buildChunkCountThisRender = 0; // Runs under the render task's RenderLock; catches every requestUpdate() // exit from the overlay while its deferred chrome refresh is still pending. settleOverlayRefresh(); @@ -1157,6 +1178,9 @@ void EpubReaderActivity::renderBook() { }; const auto showBuildError = [this]() { + // Snapshot the log ring before anything else: on a device with no serial console this is the + // only record of which check inside the section build actually failed. No-op without INPUT_DIAG. + InputDiag::captureLogs("section-build-failed", /*failure=*/true); renderer.clearScreen(); const auto labels = mappedInput.mapLabels(tr(STR_BACK), "", "", ""); GUI.drawButtonHints(renderer, labels.btn1, labels.btn2, labels.btn3, labels.btn4); @@ -1195,6 +1219,8 @@ void EpubReaderActivity::renderBook() { buildViewportHeight = viewportHeight; const ReaderRenderSpec renderSpec = SETTINGS.readerRenderSpec(viewportWidth, viewportHeight); + // getReaderFontId() inside readerRenderSpec resolves (and lazily loads) the SD reader font. + InputDiag::noteOpenStage(2, "font"); if (!section) { const auto filepath = epub->getSpineItem(currentSpineIndex).href; @@ -1296,7 +1322,7 @@ void EpubReaderActivity::renderBook() { if (buildPopupPending && millis() - buildStartMs >= BUILD_POPUP_DEADLINE_MS) { showBuildPopup(renderer, pagesUntilFullRefresh); } - if (!section->buildSomeMore(BUILD_PAGES_PER_CHUNK)) { + if (!buildChunkTimed(BUILD_PAGES_PER_CHUNK)) { LOG_ERR("ERS", "Failed during incremental section build"); section.reset(); buildPopupPending = false; @@ -1359,7 +1385,7 @@ void EpubReaderActivity::renderBook() { return; } while (!section->isBuildComplete() && section->currentPage >= static_cast(section->pageCount)) { - if (!section->buildSomeMore(BUILD_PAGES_PER_CHUNK)) { + if (!buildChunkTimed(BUILD_PAGES_PER_CHUNK)) { LOG_ERR("ERS", "Failed during incremental section build"); section.reset(); showBuildError(); @@ -1369,7 +1395,7 @@ void EpubReaderActivity::renderBook() { } if (section->isBuilding()) { while (!section->isBuildComplete() && section->currentPage >= static_cast(section->pageCount)) { - if (!section->buildSomeMore(BUILD_PAGES_PER_CHUNK)) { + if (!buildChunkTimed(BUILD_PAGES_PER_CHUNK)) { LOG_ERR("ERS", "Failed during incremental section build"); section.reset(); showBuildError(); @@ -1378,6 +1404,12 @@ void EpubReaderActivity::renderBook() { } } + if (buildChunkCountThisRender > 0) { + InputDiag::noteBuildTotal(currentSpineIndex, buildAccumMsThisRender, buildChunkCountThisRender); + } + // Section loaded (or built far enough for the requested page). + InputDiag::noteOpenStage(3, "sect"); + if (!section->isBuilding() && section->pageCount > 0 && section->currentPage >= static_cast(section->pageCount)) { section->currentPage = section->pageCount - 1; @@ -1432,6 +1464,7 @@ void EpubReaderActivity::renderBook() { return; } pageLoadRetryCount = 0; + InputDiag::notePoint("pg:load"); currentPageVisibleOffset = p->visibleTextOffset; currentPageFootnotes = std::move(p->footnotes); @@ -1444,10 +1477,12 @@ void EpubReaderActivity::renderBook() { // needs that slot, then snapshot the newly rendered page below. discardOverlayPage(); + InputDiag::noteOpenStage(4, "built"); const auto start = millis(); renderContents(std::move(p), orientedMarginTop, orientedMarginRight, orientedMarginBottom, orientedMarginLeft); LOG_DBG("ERS", "Rendered page in %dms", millis() - start); lastRenderCompleteMs = millis(); + InputDiag::noteOpenStage(5, "page1"); markPageRendered(); } @@ -1573,6 +1608,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or renderStatusBar(); scope.endScanAndPrewarm(); const auto tPrewarm = millis(); + InputDiag::notePoint("pg:prewarm"); const bool pageHasImages = page->hasImages(); const bool pageHasImagesNeedingDecode = pageHasImages && page->hasImagesNeedingDecode(); @@ -1613,6 +1649,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or page->render(renderer, fontId, orientedMarginLeft, orientedMarginTop); renderStatusBar(); const auto tBwRender = millis(); + InputDiag::notePoint("pg:bw"); if (absoluteImageGrayscale) { const auto baseMode = cleanImageBasePending ? HalDisplay::HALF_REFRESH : HalDisplay::FAST_REFRESH; @@ -1650,6 +1687,8 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or ReaderUtils::displayWithRefreshCycle(renderer, pagesUntilFullRefresh); } const auto tDisplay = millis(); + InputDiag::notePageRender(tPrewarm - t0, tBwRender - tPrewarm, tDisplay - tBwRender); + InputDiag::notePoint("pg:disp"); if (tiledGrayscale) { constexpr int STRIP_ROWS = 80; @@ -1680,6 +1719,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or if (lsbPlaneBuf) { renderPlaneToBuffer(true, lsbPlaneBuf.get()); if (msbPlaneBuf) renderPlaneToBuffer(false, msbPlaneBuf.get()); + InputDiag::notePoint("pg:planes"); const auto tGrayRender = millis(); renderer.waitRefreshComplete(); @@ -1708,6 +1748,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or tGrayWrite - tWait, tGrayDisplay - tGrayWrite, tEnd - tGrayDisplay, tEnd - t0, msbPlaneBuf ? 2 : 1); } else { auto scratch = makeUniqueNoThrow(static_cast(gwBytes) * STRIP_ROWS); + InputDiag::notePoint("pg:scratch"); renderer.waitRefreshComplete(); if (!scratch) { LOG_ERR("ERS", "OOM: grayscale strip scratch (%d bytes); skipping AA this page", gwBytes * STRIP_ROWS); @@ -1731,6 +1772,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or renderer.writeGrayscalePlaneStrip(true, scratch.get(), y, rows); } const auto tGrayLsb = millis(); + InputDiag::notePoint("pg:lsb"); renderer.setRenderMode(GfxRenderer::GRAYSCALE_MSB); for (int y = 0; y < gh; y += STRIP_ROWS) { @@ -1742,6 +1784,7 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or renderer.writeGrayscalePlaneStrip(false, scratch.get(), y, rows); } const auto tGrayMsb = millis(); + InputDiag::notePoint("pg:msb"); renderer.setRenderMode(GfxRenderer::BW); renderer.displayGrayBuffer(); @@ -1772,12 +1815,14 @@ void EpubReaderActivity::renderContents(std::unique_ptr page, const int or renderGrayscalePass(); renderer.copyGrayscaleLsbBuffers(); const auto tGrayLsb = millis(); + InputDiag::notePoint("pg:lsb"); renderer.clearScreen(absoluteImageGrayscale ? 0xFF : 0x00); renderer.setRenderMode(GfxRenderer::GRAYSCALE_MSB); renderGrayscalePass(); renderer.copyGrayscaleMsbBuffers(); const auto tGrayMsb = millis(); + InputDiag::notePoint("pg:msb"); renderer.displayGrayBuffer(); const auto tGrayDisplay = millis(); diff --git a/src/activities/reader/EpubReaderActivity.h b/src/activities/reader/EpubReaderActivity.h index a728476577c..aa8cad8f4ac 100644 --- a/src/activities/reader/EpubReaderActivity.h +++ b/src/activities/reader/EpubReaderActivity.h @@ -47,6 +47,12 @@ class EpubReaderActivity final : public ReaderActivity { bool currentPageBookmarked = false; int idlePrewarmSpine = -1; int idlePrewarmPage = -1; + // Per-render section-build accounting for INPUT_DIAG. A single chunk can look cheap + // (BUILD_PAGES_PER_CHUNK pages, sub-second) while the loop around it still iterates dozens + // of times to reach a distant target -- noteBuildChunk's per-chunk max misses that; this + // catches the render-level total instead. Reset at the top of renderBook(). + unsigned long buildAccumMsThisRender = 0; + int buildChunkCountThisRender = 0; unsigned long lastRenderCompleteMs = 0; bool bookmarkRemoved = false; std::vector cachedBookmarks; @@ -119,6 +125,8 @@ class EpubReaderActivity final : public ReaderActivity { // Requires the render lock; heap admission is checked separately by the build tick. bool backgroundBuildWanted() const; bool buildTickHeapGate(); + // section->buildSomeMore() plus the INPUT_DIAG chunk timing and the per-render totals above. + bool buildChunkTimed(uint16_t pages); bool buildHeapPaused = false; static constexpr size_t RENDER_MIN_FREE_HEAP = 24 * 1024; static constexpr int BUILD_WINDOW_AHEAD = 5; diff --git a/src/main.cpp b/src/main.cpp index c9094d4bb6c..31086ceac58 100644 --- a/src/main.cpp +++ b/src/main.cpp @@ -37,6 +37,7 @@ #include "fontIds.h" #include "platform/UsbSerialJtagHandoff.h" #include "util/ButtonNavigator.h" +#include "util/InputDiag.h" #include "util/ScreenshotUtil.h" #include "util/Timezones.h" @@ -402,6 +403,13 @@ void setup() { LOG_INF("MAIN", "Device: %s", BoardConfig::ACTIVE.name); #endif + // The SDK's 40 MHz default stays. The X3 routes its card through the GPIO matrix (GPIO 8/10/7 + // are not the C3's SPI2 IOMUX pins), which ESP-IDF rates at 26.6 MHz for reads, so asking for + // 20 MHz looked like it might remove retries. Measured 2026-09-11 on the same 634 KB cover: + // 40 MHz 3,886 ms, 20 MHz 4,342 ms. Halving the clock cost only 10%, so the transfer is about + // a tenth of the time and the rest is per-operation overhead -- the clock is not the lever. + InputDiag::noteSdClock(BoardConfig::ACTIVE.sd.spiHz != 0 ? BoardConfig::ACTIVE.sd.spiHz : 40000000); + // SD Card Initialization // We need 6 open files concurrently when parsing a new chapter if (!Storage.begin()) { @@ -588,6 +596,11 @@ void loop() { gpio.setSharedConfirmPowerShortPressEmitsPower(SETTINGS.shortPwrBtn == CrossPointSettings::SHORT_PWRBTN::SLEEP); mappedInputManager.update(); + // Immediately after the input poll: the gap between consecutive samples is what decides whether a + // press can be seen at all. No-op unless built with INPUT_DIAG. + const bool diagInputEdge = gpio.wasAnyPressed() || gpio.wasAnyReleased(); + const bool diagInputPending = gpio.isDebouncePending(); + InputDiag::sample(loopStartTime, diagInputEdge, diagInputPending); if (activityManager.requiresExclusiveStorageLoop()) { // USB Drive handed the raw SD card to the host. Do not run screenshots, @@ -799,6 +812,11 @@ void loop() { } } + // After the loop duration above, so the SD write it may perform is not counted in it; before the + // render-lock check below, which returns early while a render is running (#3652). No-op unless + // built with INPUT_DIAG. + InputDiag::flush(diagInputEdge || diagInputPending); + bool skipLoopDelay = false; { RenderLock lock(RenderLock::Mode::Try); diff --git a/src/util/InputDiag.cpp b/src/util/InputDiag.cpp new file mode 100644 index 00000000000..f48ba58da84 --- /dev/null +++ b/src/util/InputDiag.cpp @@ -0,0 +1,1463 @@ +#include "InputDiag.h" + +#ifdef INPUT_DIAG + +#include +#include +#include +#include +#include +#include +#include +#include +#include + +#include +#include +#include +#include +#include +#include + +#include "activities/RenderLock.h" +// Generated per build by scripts/ost_version.py. Included only here and in HalSystem, so a new +// build number recompiles those two files rather than the whole tree. +#include + +namespace { +constexpr char DIAG_PATH[] = "/input-diag.txt"; +constexpr unsigned long FLUSH_INTERVAL_MS = 5000; +// Split the poll intervals by CPU tier. LOW_POWER_FREQ is 10 MHz on X3 and 80 MHz on PSRAM boards, +// against a normal 160 MHz, so any threshold between the two tiers works. +constexpr uint32_t FULL_SPEED_MIN_MHZ = 120; + +// Plain statics, not atomics: written only from the main loop, and read back by flush() on the same +// task. Nothing here is load-bearing, so a torn value would only misreport a diagnostic. +unsigned long lastSampleAt = 0; +unsigned long lastFlushAt = 0; +uint32_t pollGapMaxFullMs = 0; +uint32_t pollGapMaxLowMs = 0; +uint32_t samplesLowPower = 0; +uint32_t debounceEpisodes = 0; +uint32_t committedEdges = 0; +uint32_t cpuMhzMin = 0; +bool wasPending = false; +// Written from the render task, read by flush() on the main task. Aligned 32-bit scalars on a +// single core, and nothing downstream acts on them, so a stale read only misreports a diagnostic. +// Glyphs a render read one at a time, because the prewarm did not cover them. A prewarm that names +// the wrong font reports success and drops no data, so this is the only number that shows it: it +// climbs by a screenful on every repaint while ui_prewarm_fail stays at zero. +uint32_t onDemandGlyphsLast = 0; +uint32_t onDemandGlyphsMax = 0; +char onDemandGlyphsMaxName[16] = "-"; + +// UI glyph prewarms that reported failure: the text stayed on the on-demand path, so the screen +// draws through SdCardFont's 8-entry overflow ring. Counted because the failure is silent from the +// outside -- the screen just gets slow -- and the usual cause is that the mini bitmap arena no +// longer fits in one contiguous block, which heap_max_alloc alone cannot confirm. +uint32_t uiPrewarmFailCount = 0; +uint32_t uiPrewarmFailMinAlloc = 0; + +// Heap the frame's glyph prewarm consumed, worst case, and the samples the two brackets take. +int32_t uiPrewarmHeapMax = 0; +uint32_t uiPrewarmHeapAtBegin = 0; +uint32_t renderHeapAtStart = 0; + +// Geometry of the last list screen built (see noteListBand). +int16_t listBandY = 0; +int16_t listBandHeight = 0; +int16_t listRowHeightPx = 0; +int16_t listVisibleRowCount = 0; +int16_t listScreenHeight = 0; + +uint32_t renderMaxMs = 0; +uint32_t renderMaxAtMs = 0; // uptime when render_max was set, to line it up with the other logs +uint32_t renderLastMs = 0; +uint32_t renderCount = 0; +// Which activity produced renderMaxMs. render_log's 12-entry ring rolls the culprit +// out of view long before a slow session ends; this pins it for the whole session. +constexpr uint8_t RENDER_MAX_NAME_LEN = 16; +char renderMaxName[RENDER_MAX_NAME_LEN] = {}; + +// Mini-arena rebuilds, last render and worst render. The on-demand counter stays at zero when a +// caller warms one string at a time, because a rebuild reads into the arena rather than the +// overflow ring; these are what show it. +uint32_t miniRebuildsLast = 0; +uint32_t miniRebuildsMax = 0; +uint32_t miniRebuildMsTotal = 0; +char miniRebuildsMaxName[RENDER_MAX_NAME_LEN] = {}; + +// Ring of the most recent renders, so the report shows the shape over time rather than one maximum +// with no context. Names are truncated rather than pointed at: the activity that produced a render +// is deleted on navigation, so keeping the pointer would dangle by the time flush() reads it. +constexpr uint8_t RENDER_LOG_SIZE = 12; +constexpr uint8_t RENDER_NAME_LEN = 12; +struct RenderEntry { + char name[RENDER_NAME_LEN]; + uint32_t ms; + // Mini-arena rebuilds during this render. Sits beside the duration because that is the only + // pairing that separates a render that is slow from a render that rebuilt the glyph arena once + // per string it drew -- the two look identical in every other figure here. + uint16_t miniRebuilds; + // Free heap and the largest run available at the end of this render, in KB. Two numbers because + // they answer different questions: free falling and never recovering is something not being given + // back, while free holding steady as the largest run shrinks is fragmentation. The prewarm + // failures that made a file browser page take six seconds happened with 2 KB as the largest run, + // which neither a snapshot at flush time nor a session minimum could have shown. + uint16_t heapFreeKb; + uint16_t heapMaxAllocKb; + // Heap this render consumed, in KB: positive means it took memory and had not given it back by + // the time it finished. A page turn in a file list read -46 here while its cost went from 473 ms + // to 19 s, which is the difference between a render that is slow and a render that is expensive. + int16_t heapDeltaKb; +}; +RenderEntry renderLog[RENDER_LOG_SIZE] = {}; +uint8_t renderLogNext = 0; + +// File-scope so flush() stays inside the 256-byte stack budget for locals. Only the main loop task +// calls flush(), so there is no second writer. +// Sized with headroom: the report already filled 1279 of a 1280-byte buffer, which truncated the +// trailing legend and would have silently dropped whatever line was added next. +char reportBuf[2304]; + +// The report is written in parts that reuse reportBuf, so its size bounds one +// part, not the whole file (the whole file outgrew it once font_copy= arrived, +// and a full buffer used to skip the write entirely). +void writeReportPart(HalFile& file, int len) { + if (len <= 0) return; + if (static_cast(len) >= sizeof(reportBuf)) len = static_cast(sizeof(reportBuf) - 1); + file.write(reinterpret_cast(reportBuf), static_cast(len)); +} + +constexpr char kReportNotes[] = + "\n" + "# render_log entries are name:ms@freeKB/maxAllocKB+consumedKB rRebuilds, oldest first.\n" + "# poll_gap_* is the interval between button samples. A press shorter than\n" + "# the gap in force at the time cannot be committed at all.\n" + "# One clean press = 2 episodes (down, up) and 2 edges. episodes well above\n" + "# edges means presses reached the pin and were dropped by the debounce.\n" + "# render_* covers drawing plus the panel refresh. The refresh alone is a\n" + "# few hundred ms, so a much larger figure is drawing time, not the panel.\n" + "# render_log is name:ms per render, oldest first.\n" + "# vert_* splits the vertical draw of the last page. cells and groups are counts,\n" + "# so ms/cell and ms/group say whether the cost is per call or in one place.\n" + "# page_* splits one page render: glyph prewarm from the card, drawing, then the\n" + "# panel refresh. Whichever dominates is where a page turn's cost actually is.\n" + "# heap_max_alloc is the largest single block still obtainable. A ZIP inflate\n" + "# buffer needs one contiguous block, so that number matters more than the total.\n" + "# build_chunk_max_ms is the single slowest Section::buildSomeMore() call this\n" + "# session -- it has no internal time budget, so one pathological page freezes\n" + "# input for its whole duration. pages=X..Y is the watermark before/after the\n" + "# call; the slow content is in that page range of the given spine index.\n" + "# build_total_max_ms is the worst render's summed buildSomeMore() time across\n" + "# all its chunks. A high total with a low build_chunk_max_ms means many small\n" + "# chunks, not one slow page -- chunks=N says how many it took to catch up.\n" + "# heap_min_log lists each fall of the heap low-water mark (512 B or more), newest\n" + "# first. The fall happened after the `after` point and before the `in` hook saw it.\n" + "# A page render passes, in order: open:built (start) pg:load pg:prewarm pg:bw pg:disp,\n" + "# then pg:planes, or pg:scratch pg:lsb pg:msb, and ends at open:page1.\n"; + +// Last and worst page-render phase split. +// What the last page scope's scan handed to the prewarm, and how often prewarm() +// bailed at its entry (scratch alloc / zero budget). Together with the rebuild +// counters these pin WHERE the per-page warm dies: zero scan bytes = the hook +// never fired; bytes>0 with entry-fails climbing = prewarm can't even start; +// bytes>0, no fails, no rebuilds = subset-hit against data the draw can't see. +uint32_t scanLastBytes = 0; +uint8_t scanLastFonts = 0; +uint32_t scanZeroCount = 0; +uint32_t prewarmEntryFailsTotal = 0; +// Draws whose font found no free scan slot: their glyphs were never prewarmed. +uint32_t scanFontOverflowTotal = 0; + +// Book-open heap checkpoints (see noteOpenStage in the header). KB resolution is +// enough to attribute an ~85KB footprint; labels are truncated to keep the line short. +constexpr uint8_t OPEN_STAGE_COUNT = 6; +struct OpenStage { + char label[8] = ""; + uint16_t freeKb = 0; + uint16_t maxAllocKb = 0; +}; +OpenStage openStages[OPEN_STAGE_COUNT]; + +// Reader-teardown heap figures (see noteCloseHeap in the header). 0 = no close yet. +uint16_t closeBeforeFreeKb = 0; +uint16_t closeAfterFreeKb = 0; +uint16_t closeAfterMaxKb = 0; + +uint32_t pageRenderPrewarmMs = 0; +uint32_t pageRenderDrawMs = 0; +uint32_t pageRenderDisplayMs = 0; +uint32_t pageRenderPrewarmMaxMs = 0; +uint32_t pageRenderDrawMaxMs = 0; +uint32_t pageRenderDisplayMaxMs = 0; + +uint32_t pageBlocksMs = 0; +uint32_t pageStatusBarMs = 0; + +// renderVertical's split for the last page drawn. +uint32_t vertBodyMs = 0; +uint32_t vertBodyCells = 0; +uint32_t vertRubyMeasureMs = 0; +uint32_t vertRubyDrawMs = 0; +uint32_t vertRubyGroups = 0; + +// The worst grayscale pair seen, kept by LSB duration. Both planes run the same +// loops, so a lopsided pair means the first pass warmed something -- these say +// what: glyphs fetched one at a time, or .pxc draws that went back to the card. +uint32_t aaWorstLsbMs = 0; +uint32_t aaWorstAtMs = 0; +uint32_t aaWorstLsbGlyphs = 0; +uint32_t aaWorstLsbSdMs = 0; +uint32_t aaWorstLsbSdDraws = 0; +uint32_t aaWorstMsbMs = 0; +uint32_t aaWorstMsbGlyphs = 0; +uint32_t aaWorstMsbSdMs = 0; +uint32_t aaWorstMsbSdDraws = 0; + +// Snapshot of the RTC log ring taken at a failure, waiting to be written out. +constexpr char LOG_PATH[] = "/input-diag-log.txt"; +char capturedLogs[2048]; +bool capturedLogsPending = false; +bool capturedLogsIsFailure = false; + +// Worst single buildSomeMore() call this session, by duration. +uint32_t buildChunkMaxMs = 0; +int buildChunkMaxSpineIndex = -1; +uint16_t buildChunkMaxPageBefore = 0; +uint16_t buildChunkMaxPageAfter = 0; + +// Worst render-level total across all buildSomeMore() calls made to catch one page up, +// by summed duration -- distinct from buildChunkMaxMs, which only sees the single worst +// chunk and misses a render slowed by many small ones. +uint32_t buildTotalMaxMs = 0; +int buildTotalMaxSpineIndex = -1; +int buildTotalMaxChunkCount = 0; + +// Smallest headroom any layout pass started with this session, and the token count that +// needed it. UINT32_MAX until the first pass so an untouched session prints nothing useful +// rather than a misleading zero. +uint32_t buildHeadroomMinFree = UINT32_MAX; +uint32_t buildHeadroomMinMaxAlloc = 0; +uint32_t buildHeadroomMinWords = 0; +uint32_t buildHeadroomMaxWords = 0; + +// Ring of the last per-glyph fetches, newest last. +constexpr uint8_t GLYPH_MISS_EVENTS = 24; +struct GlyphMissEvent { + uint32_t codepoint; + uint8_t style; +}; +GlyphMissEvent glyphMissEvents[GLYPH_MISS_EVENTS] = {}; +uint32_t glyphMissTotal = 0; + +// The .cpfont in use and what it costs before any page: see noteFontChoice. +char fontName[32] = ""; +uint8_t fontStyles = 0; +uint8_t fontAdvanceY = 0; +uint32_t fontGlyphs = 0; +uint32_t fontResidentBytes = 0; +bool fontFromFlash = false; +uint32_t fontFlashBytes = 0; +uint8_t fontScaleNum = 1; +uint8_t fontScaleDen = 1; + +// Grayscale plane loops split into compose-in-RAM and push-to-panel. +bool aaWorstArmed = false; +uint32_t sdClockHz = 0; + +constexpr uint8_t FONT_COPY_EVENTS = 3; +char fontCopyEvents[FONT_COPY_EVENTS][160] = {}; + +// When the heap watermark (ESP.getMinFreeHeap) falls, and what had just run. +// The watermark is global and says nothing about when; checking it at every +// hook below brackets the drop between two named points: `in` is the hook that +// saw it (the work that just finished), `after` the named point before that. +// A drop seen from the idle loop keeps the last named point as its bracket. +constexpr uint8_t HEAP_MIN_EVENTS = 6; +constexpr uint32_t HEAP_MIN_STEP = 512; // smaller moves are noise, not an event +struct HeapMinEvent { + uint32_t ms; + uint32_t minFree; + uint32_t freeNow; + uint32_t maxNow; + char in[20]; + char after[20]; +}; +HeapMinEvent heapMinEvents[HEAP_MIN_EVENTS] = {}; +uint32_t heapMinEventTotal = 0; +uint32_t heapMinRecorded = UINT32_MAX; +char heapLastPoint[20] = "boot"; +// heap-low.txt is rewritten each time a new low is recorded with this little left. +constexpr uint32_t HEAP_LOW_SNAPSHOT_BELOW = 16 * 1024; + +void formatPoint(char* out, size_t outLen, const char* tag, const char* detail) { + if (detail == nullptr || detail[0] == '\0') { + snprintf(out, outLen, "%s", tag); + return; + } + // First word of the detail only: image lines carry sizes after it. + size_t n = 0; + while (detail[n] != '\0' && detail[n] != ' ' && n < 12) n++; + snprintf(out, outLen, "%s:%.*s", tag, static_cast(n), detail); +} + +void snapshotHeapLow(const char* in, const char* after, uint32_t minFree, uint32_t freeNow); +void snapshotBuildLowIfLower(const char* point); +void writeHeapLowIfPending(); + +void checkHeapMin(const char* tag, const char* detail = nullptr) { + const uint32_t minFree = ESP.getMinFreeHeap(); + const bool named = strcmp(tag, "loop") != 0; + if (heapMinRecorded == UINT32_MAX || minFree + HEAP_MIN_STEP <= heapMinRecorded) { + HeapMinEvent& e = heapMinEvents[heapMinEventTotal % HEAP_MIN_EVENTS]; + e.ms = millis(); + e.minFree = minFree; + e.freeNow = ESP.getFreeHeap(); + e.maxNow = ESP.getMaxAllocHeap(); + formatPoint(e.in, sizeof(e.in), tag, detail); + snprintf(e.after, sizeof(e.after), "%s", heapLastPoint); + heapMinEventTotal++; + heapMinRecorded = minFree; + // Low enough to matter: record who holds the heap at this moment. Any task may take the + // snapshot (the heap walk touches no storage); flush() writes it once storage is free. + if (e.freeNow < HEAP_LOW_SNAPSHOT_BELOW) snapshotHeapLow(e.in, e.after, minFree, e.freeNow); + } + if (named) formatPoint(heapLastPoint, sizeof(heapLastPoint), tag, detail); +} +uint32_t fontCopyTotal = 0; +// Vertical page geometry, sampled once per chapter build (see noteVerticalLayout). +uint16_t vertCell = 0, vertPitch = 0, vertRubyReserve = 0, vertViewportW = 0, vertViewportH = 0; +// Layout give-ups: the count, and which check refused last (see noteLayoutGiveUp). +uint32_t layoutGiveUps = 0; +uint8_t layoutGiveUpKind = 0; +uint32_t layoutGiveUpTokens = 0; +uint32_t layoutGiveUpFree = 0; +uint32_t layoutGiveUpMaxAlloc = 0; + +uint32_t aaRefreshWaitMs = 0; +uint32_t aaRefreshWaitMaxMs = 0; +uint32_t aaLsbDrawMs = 0; +uint32_t aaLsbPushMs = 0; +uint32_t aaMsbDrawMs = 0; +uint32_t aaMsbPushMs = 0; + +// Section-build phases: pages written to the card, and the advance-table work the measuring did. +uint32_t buildPageWrites = 0; +uint32_t buildPageWriteMs = 0; +uint32_t buildFontCalls = 0; +uint32_t buildFontMs = 0; +uint32_t buildFontTableMax = 0; +uint32_t buildFontTableLimit = 0; +uint32_t buildFontFullSkips = 0; + +// Page-glyph prewarm budgets. The minimum is what the tightest page got; clips count the pages +// that wanted more glyphs than the heap would pay for. +uint32_t prewarmBudgetMin = UINT32_MAX; +uint32_t prewarmBudgetMinWanted = 0; +uint32_t prewarmBudgetMinFree = 0; +uint32_t prewarmBudgetClips = 0; + +// Next-chapter lookahead build (EpubReaderActivity::tickLookaheadBuild): kept apart from the +// foreground build counters so a slow idle tick and a slow chapter crossing stay tellable. +uint32_t lookaheadStarts = 0; +uint32_t lookaheadCompletions = 0; +uint32_t lookaheadTicks = 0; +uint32_t lookaheadReleases = 0; +uint32_t aaAborts = 0; +uint32_t lookaheadPages = 0; +uint32_t lookaheadTotalMs = 0; +uint32_t lookaheadChunkMaxMs = 0; +int lookaheadChunkMaxSpineIndex = -1; +uint32_t lookaheadChunkMaxMhz = 0; +} // namespace + +void InputDiag::sample(const unsigned long nowMs, const bool committedEdge, const bool debouncePending) { + checkHeapMin("loop"); + const uint32_t mhz = getCpuFrequencyMhz(); + if (cpuMhzMin == 0 || mhz < cpuMhzMin) { + cpuMhzMin = mhz; + } + + if (lastSampleAt != 0) { + const uint32_t gap = static_cast(nowMs - lastSampleAt); + if (mhz < FULL_SPEED_MIN_MHZ) { + samplesLowPower++; + if (gap > pollGapMaxLowMs) pollGapMaxLowMs = gap; + } else if (gap > pollGapMaxFullMs) { + pollGapMaxFullMs = gap; + } + } + lastSampleAt = nowMs; + + // Count episodes rather than samples: one raw change stays pending across several fast re-polls + // while it waits out the debounce window, and that is one press, not several. + if (debouncePending && !wasPending) { + debounceEpisodes++; + } + wasPending = debouncePending; + + if (committedEdge) { + committedEdges++; + } +} + +void InputDiag::noteListBand(const int bandY, const int bandHeight, const int rowHeight, const int visibleRows, + const int screenHeight) { + listBandY = static_cast(bandY); + listBandHeight = static_cast(bandHeight); + listRowHeightPx = static_cast(rowHeight); + listVisibleRowCount = static_cast(visibleRows); + listScreenHeight = static_cast(screenHeight); +} + +void InputDiag::noteRenderStart() { renderHeapAtStart = ESP.getFreeHeap(); } + +void InputDiag::noteUiPrewarmBegin() { uiPrewarmHeapAtBegin = ESP.getFreeHeap(); } + +void InputDiag::noteUiPrewarmEnd() { + if (uiPrewarmHeapAtBegin == 0) return; + const int32_t consumed = static_cast(uiPrewarmHeapAtBegin) - static_cast(ESP.getFreeHeap()); + if (consumed > uiPrewarmHeapMax) uiPrewarmHeapMax = consumed; + uiPrewarmHeapAtBegin = 0; +} + +void InputDiag::noteRender(const char* activityName, const unsigned long durationMs, const uint32_t onDemandGlyphs, + const uint32_t miniRebuilds, const uint32_t miniRebuildMs) { + checkHeapMin("render", activityName); + renderLastMs = static_cast(durationMs); + if (renderLastMs > renderMaxMs) { + renderMaxMs = renderLastMs; + renderMaxAtMs = static_cast(millis()); + snprintf(renderMaxName, sizeof(renderMaxName), "%s", activityName ? activityName : "?"); + } + renderCount++; + + onDemandGlyphsLast = onDemandGlyphs; + if (onDemandGlyphs > onDemandGlyphsMax) { + onDemandGlyphsMax = onDemandGlyphs; + snprintf(onDemandGlyphsMaxName, sizeof(onDemandGlyphsMaxName), "%s", activityName ? activityName : "?"); + } + + miniRebuildsLast = miniRebuilds; + miniRebuildMsTotal += miniRebuildMs; + if (miniRebuilds > miniRebuildsMax) { + miniRebuildsMax = miniRebuilds; + snprintf(miniRebuildsMaxName, sizeof(miniRebuildsMaxName), "%s", activityName ? activityName : "?"); + } + + RenderEntry& entry = renderLog[renderLogNext]; + snprintf(entry.name, sizeof(entry.name), "%s", activityName ? activityName : "?"); + entry.ms = renderLastMs; + entry.miniRebuilds = static_cast(miniRebuilds > 0xFFFF ? 0xFFFF : miniRebuilds); + const uint32_t heapNow = ESP.getFreeHeap(); + entry.heapFreeKb = static_cast(heapNow / 1024); + entry.heapMaxAllocKb = static_cast(ESP.getMaxAllocHeap() / 1024); + const int32_t consumed = static_cast(renderHeapAtStart) - static_cast(heapNow); + entry.heapDeltaKb = renderHeapAtStart == 0 ? 0 : static_cast(consumed / 1024); + renderHeapAtStart = 0; + renderLogNext = static_cast((renderLogNext + 1) % RENDER_LOG_SIZE); +} + +void InputDiag::noteOpenBegin() { + for (auto& s : openStages) { + s.label[0] = '\0'; + s.freeKb = 0; + s.maxAllocKb = 0; + } + Storage.remove("/open-heap.txt"); +} + +void InputDiag::noteCloseHeap(const uint32_t beforeFreeKb, const uint32_t afterFreeKb, const uint32_t afterMaxKb) { + checkHeapMin("close"); + closeBeforeFreeKb = static_cast(beforeFreeKb); + closeAfterFreeKb = static_cast(afterFreeKb); + closeAfterMaxKb = static_cast(afterMaxKb); +} + +void InputDiag::noteOpenStage(const uint8_t slot, const char* label) { + checkHeapMin("open", label); + if (slot >= OPEN_STAGE_COUNT) return; + auto& s = openStages[slot]; + if (s.label[0] != '\0') return; // write-once until the next noteOpenBegin() + snprintf(s.label, sizeof(s.label), "%s", label ? label : "?"); + s.freeKb = static_cast(ESP.getFreeHeap() / 1024); + s.maxAllocKb = static_cast(ESP.getMaxAllocHeap() / 1024); + + // Also rewrite a dedicated file immediately: the periodic flush() skips while a RenderLock is + // held, which is the whole of a blocking section build -- exactly where the open sequence dies. + // A crash then loses every stage. Rewriting all recorded stages per checkpoint survives it + // (HalStorage has no append mode; the file is a few lines, so the rewrite is negligible). + HalFile f; + if (Storage.openFileForWrite("DIAG", "/open-heap.txt", f)) { + char line[48]; + for (const auto& stage : openStages) { + if (stage.label[0] == '\0') continue; + const int n = + snprintf(line, sizeof(line), "%s: free=%uKB maxAlloc=%uKB\n", stage.label, stage.freeKb, stage.maxAllocKb); + if (n > 0) f.write(reinterpret_cast(line), static_cast(n)); + } + } +} + +namespace { +// 48 rather than 24: one image writes up to five lines (img, probe, extract, +// decode, placed, plus the fit bounds), so a ten-picture chapter overran the +// ring and dropped exactly the entries an investigation wanted -- the first +// images of the chapter. 48 x 96B is 4.6KB of static DRAM, and only in a +// diagnostic build. +constexpr uint8_t IMG_EVENT_COUNT = 48; +char imgEvents[IMG_EVENT_COUNT][96]; +uint8_t imgEventCount = 0; // total recorded; ring position = count % IMG_EVENT_COUNT +} // namespace + +// Allocation tags (diag env links with -Wl,--wrap=malloc/calloc/realloc). Each block is 12 bytes +// longer than asked and ends with: the malloc caller, then the first two further code addresses +// found on the caller's stack. operator new and std::string go through malloc, so the first tag +// names libstdc++ and the stack ones name the code that wanted the memory. dumpHeapMap reads them +// back from the end of every used block (the poisoning header holds the requested size). Nothing +// changes for free(): the tag rides inside the block. +namespace { +constexpr size_t ALLOC_TAG_BYTES = 12; +inline bool looksLikeCode(const uint32_t v) { + return (v >= 0x42000000u && v < 0x42800000u) || (v >= 0x40380000u && v < 0x403E0000u); +} +// Addresses that name no owner: the malloc wrappers themselves and libstdc++'s operator new +// family (new, new[], and their nothrow forms sit next to each other). Tags made only of these +// said "operator new[] (nothrow)" for 65 KB of the heap and nothing more (heap-low, 2026-09-26). +bool isAllocPlumbing(uint32_t v); + +inline void writeAllocTag(void* p, const size_t n, void* ra) { + if (p == nullptr) return; + uint32_t tag[3] = {0, 0, 0}; + uint8_t found = 0; + const uint32_t first = reinterpret_cast(ra); + if (!isAllocPlumbing(first)) tag[found++] = first; + // Walk the stack above this frame for the next return addresses (no frame pointers on this + // build, so this is a heuristic: code addresses spilled by the callers). + volatile uint32_t probe = 0; + const uint32_t* sp = reinterpret_cast(const_cast(&probe)); + for (uint32_t i = 0; i < 96 && found < 3; i++) { + const uint32_t v = sp[i]; + if (!looksLikeCode(v) || isAllocPlumbing(v)) continue; + if (v == tag[0] || v == tag[1]) continue; + tag[found++] = v; + } + memcpy(static_cast(p) + n, tag, sizeof(tag)); +} +} // namespace + +extern "C" { +void* __wrap_malloc(size_t n); +void* __wrap_calloc(size_t count, size_t n); +void* __wrap_realloc(void* p, size_t n); +} + +namespace { +bool isAllocPlumbing(const uint32_t v) { + static uint32_t newLo = 0, newHi = 0; + if (newLo == 0) { + const uint32_t a[] = { + reinterpret_cast(static_cast(&::operator new)), + reinterpret_cast(static_cast(&::operator new[])), + reinterpret_cast(static_cast(&::operator new)), + reinterpret_cast(static_cast(&::operator new[])), + }; + newLo = *std::min_element(a, a + 4); + newHi = *std::max_element(a, a + 4); + } + if (v >= newLo && v < newHi + 0x80) return true; + const uint32_t w[] = {reinterpret_cast(&__wrap_malloc), reinterpret_cast(&__wrap_calloc), + reinterpret_cast(&__wrap_realloc)}; + for (const uint32_t f : w) { + if (v >= f && v < f + 0x80) return true; + } + return false; +} +} // namespace + +extern "C" { +void* __real_malloc(size_t n); +void* __real_calloc(size_t count, size_t n); +void* __real_realloc(void* p, size_t n); +void* __wrap_malloc(size_t n) { + void* p = __real_malloc(n + ALLOC_TAG_BYTES); + writeAllocTag(p, n, __builtin_return_address(0)); + return p; +} +void* __wrap_calloc(size_t count, size_t n) { + const size_t total = count * n; + if (n != 0 && total / n != count) return nullptr; + void* p = __real_calloc(1, total + ALLOC_TAG_BYTES); + writeAllocTag(p, total, __builtin_return_address(0)); + return p; +} +void* __wrap_realloc(void* old, size_t n) { + if (n == 0) return __real_realloc(old, 0); + void* p = __real_realloc(old, n + ALLOC_TAG_BYTES); + writeAllocTag(p, n, __builtin_return_address(0)); + return p; +} +} + +namespace { +struct HeapBlockRec { + uint32_t addr; + uint32_t size; + uint8_t used; + uint8_t head[16]; + uint32_t tag[3]; +}; +struct HeapWalkCtx { + HeapBlockRec* recs; + uint16_t count; + uint16_t capacity; + uint32_t smallUsedCount; + uint32_t smallUsedBytes; + uint32_t smallFreeCount; + uint32_t smallFreeBytes; + uint32_t usedBytes; + uint32_t freeBytes; + uint32_t dropped; +}; +// Every used block: the fragmentation seen after reading came from ~15 blocks under 256 B left +// inside the one large free region (2026-09-25), so the small ones are the ones to name. +constexpr uint32_t HEAP_MAP_MIN_USED = 0; +constexpr uint32_t HEAP_MAP_MIN_FREE = 256; + +// Runs with the heap locked: no allocation, no I/O, only copying into the prepared array. +bool heapWalkRecord(walker_heap_into_t, walker_block_info_t block, void* user) { + auto* ctx = static_cast(user); + if (block.used) { + ctx->usedBytes += block.size; + } else { + ctx->freeBytes += block.size; + } + const bool keep = block.used ? block.size >= HEAP_MAP_MIN_USED : block.size >= HEAP_MAP_MIN_FREE; + if (!keep) { + if (block.used) { + ctx->smallUsedCount++; + ctx->smallUsedBytes += block.size; + } else { + ctx->smallFreeCount++; + ctx->smallFreeBytes += block.size; + } + return true; + } + if (ctx->count >= ctx->capacity) { + ctx->dropped++; + return true; + } + HeapBlockRec& r = ctx->recs[ctx->count++]; + r.addr = reinterpret_cast(block.ptr); + r.size = block.size; + r.used = block.used ? 1 : 0; + memset(r.head, 0, sizeof(r.head)); + memset(r.tag, 0, sizeof(r.tag)); + if (block.used) { + memcpy(r.head, block.ptr, block.size < sizeof(r.head) ? block.size : sizeof(r.head)); + // Poisoning header: 4-byte magic, then the requested size; the tag is its last 12 bytes. + uint32_t requested = 0; + if (block.size >= 8) memcpy(&requested, static_cast(block.ptr) + 4, sizeof(requested)); + if (requested >= ALLOC_TAG_BYTES && requested + 8 <= block.size) { + memcpy(r.tag, static_cast(block.ptr) + 8 + requested - ALLOC_TAG_BYTES, sizeof(r.tag)); + } + } + return true; +} +} // namespace + +namespace { +// heap-low.txt: who holds the heap when the low-water mark falls below HEAP_LOW_SNAPSHOT_BELOW. +// dumpHeapMap needs a 14 KB array and cannot run there, so this aggregates used blocks by their +// allocation tag into a fixed static table during the walk (no allocation, heap locked) and +// writes the largest owners. The chapter build's heap fell page by page to 6.2 KB free +// (2026092609, in=pagewrite after=pagewrite): something accumulates across pages. +constexpr uint8_t HEAP_LOW_OWNERS = 40; +struct HeapOwner { + uint32_t tag[3]; + uint32_t bytes; + uint16_t blocks; + uint32_t largest; +}; +struct HeapLowCtx { + HeapOwner owners[HEAP_LOW_OWNERS]; + uint8_t used; + uint32_t overflowBytes; + uint16_t overflowBlocks; + uint32_t usedBytes; + uint32_t freeBytes; + uint32_t largestFree; +}; +HeapLowCtx heapLow; + +bool heapLowRecord(walker_heap_into_t, walker_block_info_t block, void* user) { + auto* ctx = static_cast(user); + if (!block.used) { + ctx->freeBytes += block.size; + if (block.size > ctx->largestFree) ctx->largestFree = block.size; + return true; + } + ctx->usedBytes += block.size; + uint32_t tag[3] = {0, 0, 0}; + uint32_t requested = 0; + if (block.size >= 8) memcpy(&requested, static_cast(block.ptr) + 4, sizeof(requested)); + if (requested >= ALLOC_TAG_BYTES && requested + 8 <= block.size) { + memcpy(tag, static_cast(block.ptr) + 8 + requested - ALLOC_TAG_BYTES, sizeof(tag)); + if (!looksLikeCode(tag[0])) tag[0] = tag[1] = tag[2] = 0; + } + for (uint8_t i = 0; i < ctx->used; i++) { + HeapOwner& o = ctx->owners[i]; + if (o.tag[0] == tag[0] && o.tag[1] == tag[1] && o.tag[2] == tag[2]) { + o.bytes += block.size; + o.blocks++; + if (block.size > o.largest) o.largest = block.size; + return true; + } + } + if (ctx->used < HEAP_LOW_OWNERS) { + HeapOwner& o = ctx->owners[ctx->used++]; + memcpy(o.tag, tag, sizeof(tag)); + o.bytes = block.size; + o.blocks = 1; + o.largest = block.size; + return true; + } + // Full: the table filled in address order with small owners and 130 KB went to "other" + // (2026092611). Evict the smallest owner when this block alone is bigger than it. + uint8_t smallest = 0; + for (uint8_t i = 1; i < ctx->used; i++) { + if (ctx->owners[i].bytes < ctx->owners[smallest].bytes) smallest = i; + } + HeapOwner& victim = ctx->owners[smallest]; + if (block.size > victim.bytes) { + ctx->overflowBytes += victim.bytes; + ctx->overflowBlocks += victim.blocks; + memcpy(victim.tag, tag, sizeof(tag)); + victim.bytes = block.size; + victim.blocks = 1; + victim.largest = block.size; + } else { + ctx->overflowBytes += block.size; + ctx->overflowBlocks++; + } + return true; +} + +constexpr uint8_t HEAP_LOW_TOP = 20; +struct HeapLowSlot { + const char* path; + uint32_t ms; + uint32_t minFree; + uint32_t freeNow; + uint32_t maxNow; + char in[20]; + char after[20]; + uint32_t usedBytes; + uint32_t freeBytes; + uint32_t largestFree; + uint32_t otherBytes; + uint16_t otherBlocks; + uint8_t count; + HeapOwner top[HEAP_LOW_TOP]; + uint32_t lowestFreeNow; // this slot re-snapshots only when the heap is 512 B lower still + bool pending; +}; +// [0] the global low-water mark (any phase: in practice the anti-aliasing page render); +// [1] the chapter build's page boundaries, which never set the global low once a render has. +HeapLowSlot heapLowSlots[2] = {{"/heap-low.txt"}, {"/heap-low-build.txt"}}; +std::atomic heapLowBusy{false}; + +void snapshotHeapLowInto(HeapLowSlot& slot, const char* in, const char* after, const uint32_t minFree, + const uint32_t freeNow) { + bool expected = false; + if (!heapLowBusy.compare_exchange_strong(expected, true)) return; + memset(&heapLow, 0, sizeof(heapLow)); + heap_caps_walk(MALLOC_CAP_8BIT, heapLowRecord, &heapLow); + std::sort(heapLow.owners, heapLow.owners + heapLow.used, + [](const HeapOwner& a, const HeapOwner& b) { return a.bytes > b.bytes; }); + slot.ms = millis(); + slot.minFree = minFree; + slot.freeNow = freeNow; + slot.maxNow = ESP.getMaxAllocHeap(); + snprintf(slot.in, sizeof(slot.in), "%s", in ? in : "?"); + snprintf(slot.after, sizeof(slot.after), "%s", after ? after : "?"); + slot.usedBytes = heapLow.usedBytes; + slot.freeBytes = heapLow.freeBytes; + slot.largestFree = heapLow.largestFree; + slot.count = heapLow.used < HEAP_LOW_TOP ? heapLow.used : HEAP_LOW_TOP; + memcpy(slot.top, heapLow.owners, sizeof(HeapOwner) * slot.count); + slot.otherBytes = heapLow.overflowBytes; + slot.otherBlocks = heapLow.overflowBlocks; + for (uint8_t i = slot.count; i < heapLow.used; i++) { + slot.otherBytes += heapLow.owners[i].bytes; + slot.otherBlocks += heapLow.owners[i].blocks; + } + slot.lowestFreeNow = freeNow; + slot.pending = true; + heapLowBusy.store(false); +} + +void snapshotHeapLow(const char* in, const char* after, const uint32_t minFree, const uint32_t freeNow) { + snapshotHeapLowInto(heapLowSlots[0], in, after, minFree, freeNow); +} + +void writeHeapLowIfPending() { + for (HeapLowSlot& slot : heapLowSlots) { + if (!slot.pending) continue; + bool expected = false; + if (!heapLowBusy.compare_exchange_strong(expected, true)) return; + slot.pending = false; + HalFile file; + if (Storage.openFileForWrite("DIAG", slot.path, file)) { + char line[256]; + int n = snprintf(line, sizeof(line), + "# build=" OST_BUILD_ID + " at_ms=%lu in=%s after=%s min=%lu now=%lu max=%lu\n" + "# used=%lu free=%lu largest_free=%lu other=%u/%luB\n", + static_cast(slot.ms), slot.in, slot.after, + static_cast(slot.minFree), static_cast(slot.freeNow), + static_cast(slot.maxNow), static_cast(slot.usedBytes), + static_cast(slot.freeBytes), static_cast(slot.largestFree), + static_cast(slot.otherBlocks), static_cast(slot.otherBytes)); + if (n > 0) + file.write(reinterpret_cast(line), static_cast(std::min(n, sizeof(line) - 1))); + for (uint8_t i = 0; i < slot.count; i++) { + const HeapOwner& o = slot.top[i]; + n = snprintf(line, sizeof(line), "%6lu B %4u blk max %5lu by=0x%08lx<0x%08lx<0x%08lx\n", + static_cast(o.bytes), static_cast(o.blocks), + static_cast(o.largest), static_cast(o.tag[0]), + static_cast(o.tag[1]), static_cast(o.tag[2])); + if (n > 0) + file.write(reinterpret_cast(line), static_cast(std::min(n, sizeof(line) - 1))); + } + } + heapLowBusy.store(false); + } +} + +// Chapter-build page boundary: snapshot into the build slot whenever the heap is lower than at +// any earlier boundary (by 512 B), independent of the global low-water mark. +void snapshotBuildLowIfLower(const char* point) { + const uint32_t freeNow = ESP.getFreeHeap(); + HeapLowSlot& slot = heapLowSlots[1]; + if (freeNow >= HEAP_LOW_SNAPSHOT_BELOW) return; + if (slot.lowestFreeNow != 0 && freeNow + HEAP_MIN_STEP > slot.lowestFreeNow) return; + snapshotHeapLowInto(slot, point, heapLastPoint, ESP.getMinFreeHeap(), freeNow); +} +} // namespace + +void InputDiag::dumpHeapMap(const char* label) { + static bool bootWritten = false; + constexpr uint16_t CAPACITY = 360; // 400 x 36 B = 14.4 KB, freed before the file is closed + const uint32_t freeBefore = ESP.getFreeHeap(); + const uint32_t maxBefore = ESP.getMaxAllocHeap(); + auto* recs = static_cast(malloc(sizeof(HeapBlockRec) * CAPACITY)); + if (recs == nullptr) return; + HeapWalkCtx ctx{}; + ctx.recs = recs; + ctx.capacity = CAPACITY; + heap_caps_walk(MALLOC_CAP_8BIT, heapWalkRecord, &ctx); + + const char* path = bootWritten ? "/heap-map.txt" : "/heap-map-boot.txt"; + bootWritten = true; + HalFile file; + if (Storage.openFileForWrite("DIAG", path, file)) { + char line[256]; + int n = snprintf(line, sizeof(line), + "# %s build=" OST_BUILD_ID + " uptime_ms=%lu free=%lu max=%lu (before this dump's own %u B array" + " at 0x%08lx)\n# used=%lu free=%lu small_used=%lu/%luB small_free=%lu/%luB dropped=%lu\n", + label ? label : "?", millis(), static_cast(freeBefore), + static_cast(maxBefore), static_cast(sizeof(HeapBlockRec) * CAPACITY), + static_cast(reinterpret_cast(recs)), + static_cast(ctx.usedBytes), static_cast(ctx.freeBytes), + static_cast(ctx.smallUsedCount), static_cast(ctx.smallUsedBytes), + static_cast(ctx.smallFreeCount), static_cast(ctx.smallFreeBytes), + static_cast(ctx.dropped)); + if (n > 0) + file.write(reinterpret_cast(line), static_cast(std::min(n, sizeof(line) - 1))); + // Tasks: the TCB is a heap block of its own and the stack another, so name both here. + { + constexpr UBaseType_t MAX_TASKS = 16; + TaskStatus_t tasks[MAX_TASKS]; + const UBaseType_t taskCount = uxTaskGetSystemState(tasks, MAX_TASKS, nullptr); + for (UBaseType_t t = 0; t < taskCount; t++) { + n = snprintf(line, sizeof(line), "T %-16s tcb=0x%08lx stack_base=0x%08lx free_min=%u prio=%u\n", + tasks[t].pcTaskName, static_cast(reinterpret_cast(tasks[t].xHandle)), + static_cast(reinterpret_cast(tasks[t].pxStackBase)), + static_cast(tasks[t].usStackHighWaterMark), + static_cast(tasks[t].uxCurrentPriority)); + if (n > 0) + file.write(reinterpret_cast(line), static_cast(std::min(n, sizeof(line) - 1))); + } + } + for (uint16_t i = 0; i < ctx.count; i++) { + const HeapBlockRec& r = recs[i]; + n = snprintf(line, sizeof(line), "%c 0x%08lx %6lu", r.used ? 'U' : 'F', static_cast(r.addr), + static_cast(r.size)); + if (r.used) { + n += snprintf(line + n, sizeof(line) - n, " "); + for (size_t k = 0; k < sizeof(r.head); k++) n += snprintf(line + n, sizeof(line) - n, "%02x", r.head[k]); + n += snprintf(line + n, sizeof(line) - n, " |"); + for (size_t k = 0; k < sizeof(r.head); k++) { + const char c = static_cast(r.head[k]); + line[n++] = (c >= 0x20 && c < 0x7f) ? c : '.'; + } + line[n++] = '|'; + if (looksLikeCode(r.tag[0])) { + n += snprintf(line + n, sizeof(line) - n, " by=0x%08lx<0x%08lx<0x%08lx", static_cast(r.tag[0]), + static_cast(r.tag[1]), static_cast(r.tag[2])); + } + } + line[n++] = '\n'; + file.write(reinterpret_cast(line), static_cast(n)); + } + } + free(recs); +} + +namespace { +// Who creates FreeRTOS mutexes, and when. The Home heap after reading holds 104-byte queue +// blocks (a mutex's control block) created mid-book and left inside the large free region; the +// linker routes every xQueueCreateMutex through the wrapper below (-Wl,--wrap in the diag env), +// and the caller's address names the owner via addr2line on the ELF. +constexpr uint8_t MUTEX_EVENTS = 12; +struct MutexEvent { + uint32_t ms; + uint32_t caller; + uint32_t handle; + uint8_t type; +}; +MutexEvent mutexEvents[MUTEX_EVENTS] = {}; +uint32_t mutexEventTotal = 0; +} // namespace + +extern "C" { +// newlib's static locks are created on first acquire (lock_init_generic), so a lock first taken +// mid-book puts its mutex in the middle of the heap. The caller of the acquire that finds the +// lock still zero names the newlib function (localtime, stdio, ...). type 0xF0 / 0xF1. +void __real__lock_acquire(_lock_t* lock); +void __real__lock_acquire_recursive(_lock_t* lock); +static void noteLockInit(_lock_t* lock, const uint8_t type, void* ra) { + if (lock == nullptr || *lock != 0) return; + MutexEvent& e = mutexEvents[mutexEventTotal % MUTEX_EVENTS]; + // Tick count, not millis(): newlib takes its locks before the timer service is up. + e.ms = static_cast(xTaskGetTickCount()) * portTICK_PERIOD_MS; + e.caller = reinterpret_cast(ra); + e.handle = reinterpret_cast(lock); + e.type = type; + mutexEventTotal++; +} +void __wrap__lock_acquire(_lock_t* lock) { + noteLockInit(lock, 0xF0, __builtin_return_address(0)); + __real__lock_acquire(lock); +} +void __wrap__lock_acquire_recursive(_lock_t* lock) { + noteLockInit(lock, 0xF1, __builtin_return_address(0)); + __real__lock_acquire_recursive(lock); +} +QueueHandle_t __real_xQueueGenericCreate(UBaseType_t len, UBaseType_t itemSize, uint8_t ucQueueType); +// Binary/counting semaphores and plain queues come through here (mutexes do not: xQueueCreateMutex +// calls it inside queue.c, past the linker's reach). Logged in the same ring, type | 0x80. +QueueHandle_t __wrap_xQueueGenericCreate(const UBaseType_t len, const UBaseType_t itemSize, const uint8_t ucQueueType) { + QueueHandle_t handle = __real_xQueueGenericCreate(len, itemSize, ucQueueType); + MutexEvent& e = mutexEvents[mutexEventTotal % MUTEX_EVENTS]; + e.ms = millis(); + e.caller = reinterpret_cast(__builtin_return_address(0)); + e.handle = reinterpret_cast(handle); + e.type = static_cast(ucQueueType | 0x80); + mutexEventTotal++; + return handle; +} +QueueHandle_t __real_xQueueCreateMutex(uint8_t ucQueueType); +QueueHandle_t __wrap_xQueueCreateMutex(const uint8_t ucQueueType) { + QueueHandle_t handle = __real_xQueueCreateMutex(ucQueueType); + // std::mutex creates and destroys thousands of these while reading (pthread_mutex_init); + // they drowned the ring, so only the other creators are kept. + const uint32_t caller = reinterpret_cast(__builtin_return_address(0)); + const uint32_t pthreadInit = reinterpret_cast(&pthread_mutex_init); + if (caller >= pthreadInit && caller < pthreadInit + 0x100) return handle; + MutexEvent& e = mutexEvents[mutexEventTotal % MUTEX_EVENTS]; + e.ms = millis(); + e.caller = reinterpret_cast(__builtin_return_address(0)); + e.handle = reinterpret_cast(handle); + e.type = ucQueueType; + mutexEventTotal++; + return handle; +} +} + +void InputDiag::notePoint(const char* tag) { checkHeapMin(tag ? tag : "?"); } + +void InputDiag::noteImageEvent(const char* line) { + checkHeapMin("img", line); + if (!line) return; + snprintf(imgEvents[imgEventCount % IMG_EVENT_COUNT], sizeof(imgEvents[0]), "%s free=%u max=%u", line, + static_cast(ESP.getFreeHeap()), static_cast(ESP.getMaxAllocHeap())); + imgEventCount++; + + // Same rewrite-per-event scheme as noteOpenStage: build holds RenderLock, the periodic + // flush never runs there, and a crash must not lose the trail. + HalFile f; + if (Storage.openFileForWrite("DIAG", "/image-diag.txt", f)) { + const uint8_t n = imgEventCount < IMG_EVENT_COUNT ? imgEventCount : IMG_EVENT_COUNT; + const uint8_t start = imgEventCount < IMG_EVENT_COUNT ? 0 : imgEventCount % IMG_EVENT_COUNT; + for (uint8_t i = 0; i < n; i++) { + const char* e = imgEvents[(start + i) % IMG_EVENT_COUNT]; + f.write(reinterpret_cast(e), strlen(e)); + f.write(reinterpret_cast("\n"), 1); + } + } +} + +void InputDiag::noteScanOutcome(const uint32_t scanBytes, const uint8_t scanFonts, const uint32_t prewarmEntryFails, + const uint32_t scanFontOverflows) { + scanFontOverflowTotal = scanFontOverflows; + scanLastBytes = scanBytes; + scanLastFonts = scanFonts; + if (scanBytes == 0) scanZeroCount++; + prewarmEntryFailsTotal = prewarmEntryFails; +} + +void InputDiag::notePageRender(const unsigned long prewarmMs, const unsigned long drawMs, + const unsigned long displayMs) { + pageRenderPrewarmMs = static_cast(prewarmMs); + pageRenderDrawMs = static_cast(drawMs); + pageRenderDisplayMs = static_cast(displayMs); + if (pageRenderPrewarmMs > pageRenderPrewarmMaxMs) pageRenderPrewarmMaxMs = pageRenderPrewarmMs; + if (pageRenderDrawMs > pageRenderDrawMaxMs) pageRenderDrawMaxMs = pageRenderDrawMs; + if (pageRenderDisplayMs > pageRenderDisplayMaxMs) pageRenderDisplayMaxMs = pageRenderDisplayMs; +} + +void InputDiag::notePageDrawParts(const unsigned long blocksMs, const unsigned long statusBarMs) { + pageBlocksMs = static_cast(blocksMs); + pageStatusBarMs = static_cast(statusBarMs); +} + +void InputDiag::noteVerticalRender(const unsigned long bodyMs, const unsigned long bodyCells, + const unsigned long rubyMeasureMs, const unsigned long rubyDrawMs, + const unsigned long rubyGroups) { + vertBodyMs = static_cast(bodyMs); + vertBodyCells = static_cast(bodyCells); + vertRubyMeasureMs = static_cast(rubyMeasureMs); + vertRubyDrawMs = static_cast(rubyDrawMs); + vertRubyGroups = static_cast(rubyGroups); +} + +void InputDiag::noteGrayscaleSplit(const unsigned long lsbMs, const unsigned long lsbGlyphs, + const unsigned long lsbSdMs, const unsigned long lsbSdDraws, + const unsigned long msbMs, const unsigned long msbGlyphs, + const unsigned long msbSdMs, const unsigned long msbSdDraws) { + if (static_cast(lsbMs) <= aaWorstLsbMs) return; + // Arms noteGrayscalePhases, which is called immediately after with the same page's numbers: + // the phases only mean anything next to the worst page's totals, and the worst page is rarely + // the last one rendered. + aaWorstArmed = true; + aaWorstLsbMs = static_cast(lsbMs); + aaWorstAtMs = static_cast(millis()); + aaWorstLsbGlyphs = static_cast(lsbGlyphs); + aaWorstLsbSdMs = static_cast(lsbSdMs); + aaWorstLsbSdDraws = static_cast(lsbSdDraws); + aaWorstMsbMs = static_cast(msbMs); + aaWorstMsbGlyphs = static_cast(msbGlyphs); + aaWorstMsbSdMs = static_cast(msbSdMs); + aaWorstMsbSdDraws = static_cast(msbSdDraws); +} + +void InputDiag::noteBuildChunk(const int spineIndex, const uint16_t pageCountBefore, const uint16_t pageCountAfter, + const unsigned long durationMs) { + snapshotBuildLowIfLower("build"); + checkHeapMin("build"); + if (static_cast(durationMs) <= buildChunkMaxMs) return; + buildChunkMaxMs = static_cast(durationMs); + buildChunkMaxSpineIndex = spineIndex; + buildChunkMaxPageBefore = pageCountBefore; + buildChunkMaxPageAfter = pageCountAfter; +} + +void InputDiag::noteBuildTotal(const int spineIndex, const unsigned long totalMs, const int chunkCount) { + if (static_cast(totalMs) <= buildTotalMaxMs) return; + buildTotalMaxMs = static_cast(totalMs); + buildTotalMaxSpineIndex = spineIndex; + buildTotalMaxChunkCount = chunkCount; +} + +void InputDiag::noteBuildHeadroom(const uint32_t freeHeap, const uint32_t maxAlloc, const uint32_t words) { + if (words > buildHeadroomMaxWords) buildHeadroomMaxWords = words; + if (freeHeap >= buildHeadroomMinFree) return; + buildHeadroomMinFree = freeHeap; + buildHeadroomMinMaxAlloc = maxAlloc; + buildHeadroomMinWords = words; +} + +// Newest last, so a run of the same script reads in the order the page drew it. +void formatGlyphMisses(char* out, const size_t outSize) { + out[0] = '\0'; + size_t off = 0; + const uint32_t shown = glyphMissTotal < GLYPH_MISS_EVENTS ? glyphMissTotal : GLYPH_MISS_EVENTS; + for (uint32_t i = 0; i < shown && off < outSize; i++) { + const auto& e = glyphMissEvents[(glyphMissTotal - shown + i) % GLYPH_MISS_EVENTS]; + const int n = snprintf(out + off, outSize - off, "%sU+%04X/%u", i ? " " : "", e.codepoint, e.style); + if (n <= 0) break; + off += static_cast(n); + } +} + +void InputDiag::noteGlyphMiss(const uint32_t codepoint, const uint8_t style) { + auto& ev = glyphMissEvents[glyphMissTotal % GLYPH_MISS_EVENTS]; + ev.codepoint = codepoint; + ev.style = style; + glyphMissTotal++; +} + +void InputDiag::noteFontChoice(const char* path, const uint8_t styles, const uint8_t advanceY, const uint32_t glyphs, + const uint32_t residentBytes, const bool flash, const uint32_t flashBytes, + const uint8_t scaleNum, const uint8_t scaleDen) { + const char* name = path; + for (const char* p = path; *p; p++) { + if (*p == '/' || *p == '\\') name = p + 1; + } + strncpy(fontName, name, sizeof(fontName) - 1); + fontName[sizeof(fontName) - 1] = '\0'; + fontStyles = styles; + fontAdvanceY = advanceY; + fontGlyphs = glyphs; + fontResidentBytes = residentBytes; + fontFromFlash = flash; + fontFlashBytes = flashBytes; + fontScaleNum = scaleNum; + fontScaleDen = scaleDen; +} + +void InputDiag::notePrewarmBudget(const uint32_t budgetGlyphs, const uint32_t wantedGlyphs, const uint32_t freeHeap) { + // The budget only means something when the page actually filled it: an easy page stops well + // short and its budget says nothing about how tight the heap was. + if (wantedGlyphs >= budgetGlyphs) prewarmBudgetClips++; + if (budgetGlyphs < prewarmBudgetMin) { + prewarmBudgetMin = budgetGlyphs; + prewarmBudgetMinWanted = wantedGlyphs; + prewarmBudgetMinFree = freeHeap; + } +} + +void InputDiag::noteSdClock(const uint32_t hz) { sdClockHz = hz; } + +void InputDiag::noteFontCopy(const char* line) { + checkHeapMin("fontcopy"); + char* slot = fontCopyEvents[fontCopyTotal % FONT_COPY_EVENTS]; + snprintf(slot, sizeof(fontCopyEvents[0]), "@%lu %s", millis(), line); + fontCopyTotal++; +} + +void InputDiag::noteVerticalLayout(const uint16_t cell, const uint16_t pitch, const uint16_t rubyReserve, + const uint16_t viewportWidth, const uint16_t viewportHeight) { + vertCell = cell; + vertPitch = pitch; + vertRubyReserve = rubyReserve; + vertViewportW = viewportWidth; + vertViewportH = viewportHeight; +} + +void InputDiag::noteLayoutGiveUp(const uint8_t kind, const uint32_t tokens) { + checkHeapMin("giveup"); + layoutGiveUps++; + layoutGiveUpKind = kind; + layoutGiveUpTokens = tokens; + layoutGiveUpFree = ESP.getFreeHeap(); + layoutGiveUpMaxAlloc = ESP.getMaxAllocHeap(); +} + +void InputDiag::noteRefreshWait(const unsigned long ms) { + aaRefreshWaitMs = static_cast(ms); + if (aaRefreshWaitMs > aaRefreshWaitMaxMs) aaRefreshWaitMaxMs = aaRefreshWaitMs; +} + +void InputDiag::noteGrayscalePhases(const unsigned long lsbDrawMs, const unsigned long lsbPushMs, + const unsigned long msbDrawMs, const unsigned long msbPushMs) { + if (!aaWorstArmed) return; + aaWorstArmed = false; + aaLsbDrawMs = static_cast(lsbDrawMs); + aaLsbPushMs = static_cast(lsbPushMs); + aaMsbDrawMs = static_cast(msbDrawMs); + aaMsbPushMs = static_cast(msbPushMs); +} + +void InputDiag::noteBuildPageWrite(const unsigned long ms) { + snapshotBuildLowIfLower("pagewrite"); + checkHeapMin("pagewrite"); + buildPageWrites++; + buildPageWriteMs += static_cast(ms); +} + +void InputDiag::noteBuildFontWork(const uint32_t calls, const uint32_t ms, const uint32_t tableMax, + const uint32_t tableLimit, const uint32_t fullSkips) { + buildFontCalls = calls; + buildFontMs = ms; + buildFontTableMax = tableMax; + buildFontTableLimit = tableLimit; + buildFontFullSkips = fullSkips; +} + +void InputDiag::noteLookaheadStart() { lookaheadStarts++; } + +void InputDiag::noteLookaheadRelease() { lookaheadReleases++; } + +void InputDiag::noteAaAborted() { aaAborts++; } + +void InputDiag::noteLookaheadChunk(const int spineIndex, const uint16_t pagesBuilt, const unsigned long durationMs, + const bool completed) { + checkHeapMin("lookahead"); + lookaheadTicks++; + lookaheadPages += pagesBuilt; + lookaheadTotalMs += static_cast(durationMs); + if (completed) lookaheadCompletions++; + if (static_cast(durationMs) > lookaheadChunkMaxMs) { + lookaheadChunkMaxMs = static_cast(durationMs); + lookaheadChunkMaxSpineIndex = spineIndex; + lookaheadChunkMaxMhz = getCpuFrequencyMhz(); + } +} + +void InputDiag::noteUiPrewarmFailure() { + uiPrewarmFailCount++; + const uint32_t maxAlloc = ESP.getMaxAllocHeap(); + if (uiPrewarmFailMinAlloc == 0 || maxAlloc < uiPrewarmFailMinAlloc) { + uiPrewarmFailMinAlloc = maxAlloc; + } +} + +void InputDiag::captureLogs(const char* reason, const bool failure) { + // Keep the first capture. A failure often cascades, and the earliest report is the one that + // still names the original cause -- except that a failure outranks an informational capture + // waiting to be written: a slow render taken seconds earlier used to keep a build failure's + // own log ring from ever reaching the card. + if (capturedLogsPending && !(failure && !capturedLogsIsFailure)) return; + const std::string logs = getLastLogs(); + // The glyph misses as they stood at this moment: on a slow render they name the characters + // the page had to fetch one at a time, which the periodic report (written later, usually from + // another screen) no longer holds. + char glyphMissBuf[GLYPH_MISS_EVENTS * 12] = ""; + formatGlyphMisses(glyphMissBuf, sizeof(glyphMissBuf)); + const int len = snprintf(capturedLogs, sizeof(capturedLogs), "reason=%s\nuptime_ms=%lu\nglyph_miss=%u last=%s\n\n%s", + reason ? reason : "?", millis(), glyphMissTotal, glyphMissBuf, logs.c_str()); + if (len <= 0) return; + capturedLogsPending = true; + capturedLogsIsFailure = failure; +} + +void InputDiag::flushNow() { + // Failure paths only. The interval exists so routine flushes stay out of the intervals being + // measured; a build that just failed has nothing left to measure and may not reach the next one. + lastFlushAt = millis() - FLUSH_INTERVAL_MS; + flush(false); +} + +void InputDiag::flush(const bool inputActive) { + const unsigned long now = millis(); + if (now - lastFlushAt < FLUSH_INTERVAL_MS) { + return; + } + // Never write while a press is in flight, or while a render holds the storage mutex: the SD access + // would land inside the very interval this is measuring, or block behind a font read. + if (inputActive || RenderLock::peek()) { + return; + } + lastFlushAt = now; + writeHeapLowIfPending(); + + // The first write of a boot destroys the previous session's trail -- which, + // after a crash, is the only record of how the heap got to where it died + // (crash_report.txt carries the stack, not the approach). Set the old file + // aside once per boot so a post-mortem still has the render_log heap series. + static bool previousPreserved = false; + if (!previousPreserved) { + previousPreserved = true; + Storage.remove("/input-diag.prev.txt"); + Storage.rename(DIAG_PATH, "/input-diag.prev.txt"); + } + + // SdCardFont's mini-subset free log (caller@ms free=KB g=glyphs s=style m=metadataOnly) comes + // back with the font stage of the 1.6.5 re-fork; until then the line reports nothing. + char miniFreeBuf[4 * 48] = ""; + uint32_t miniFreeTotal = 0; + + char glyphMissBuf[GLYPH_MISS_EVENTS * 12] = ""; + formatGlyphMisses(glyphMissBuf, sizeof(glyphMissBuf)); + + HalFile file; + if (!Storage.openFileForWrite("DIAG", DIAG_PATH, file)) { + return; + } + + int len = snprintf( + reportBuf, sizeof(reportBuf), + // First line, because every question asked of this file starts with which build wrote it. + // A diagnostic read against the wrong firmware costs more than the run it came from, and + // the commit alone cannot tell two builds apart while the tree has uncommitted changes. + "build=" OST_BUILD_ID " version=" CROSSPOINT_VERSION + "\n" + "uptime_ms=%lu\n" + "cpu_mhz_now=%u\n" + "cpu_mhz_min=%u\n" + "poll_gap_max_fullspeed_ms=%u\n" + "poll_gap_max_lowpower_ms=%u\n" + "samples_lowpower=%u\n" + "debounce_episodes=%u\n" + "committed_edges=%u\n" + "render_last_ms=%u\n" + "render_max_ms=%u (%s) at=%u\n" + "render_count=%u\n" + "heap_free=%u\n" + "heap_min_free=%u\n" + "heap_max_alloc=%u\n" + "page_prewarm_ms=%u (max %u)\n" + "page_draw_ms=%u (max %u)\n" + "page_display_ms=%u (max %u)\n" + "page_blocks_ms=%u\n" + "page_statusbar_ms=%u\n" + "aa_worst_lsb_ms=%u glyphs=%u sd_ms=%u sd_draws=%u at=%u\n" + "aa_worst_msb_ms=%u glyphs=%u sd_ms=%u sd_draws=%u\n" + "vert_body_ms=%u cells=%u\n" + "vert_ruby_measure_ms=%u\n" + "vert_ruby_draw_ms=%u groups=%u\n" + "build_chunk_max_ms=%u spine=%d pages=%u..%u\n" + "build_total_max_ms=%u spine=%d chunks=%d\n" + "build_headroom_min=%u max_alloc_then=%u words_then=%u words_max=%u\n" + "lookahead=starts %u done %u ticks %u pages %u total_ms %u chunk_max_ms %u (spine %d at %u MHz) font_releases " + "%u\n" + "mini_free=%u last=%s\n" + "aa_aborts=%u\n" + "ui_prewarm_fail=%u (max_alloc_then=%u)\n" + "glyph_ondemand_last=%u max=%u (%s)\n" + "glyph_rebuild_last=%u max=%u (%s) total_ms=%u\n" + "page_scan_last=%ub/%uf zero=%u prewarm_entry_fails=%u font_slots_lost=%u\n" + "glyph_miss=%u last=%s\n" + "font=%s styles=%u advY=%u glyphs=%u resident=%u src=%s flash_kb=%u scale=%u/%u\n" + "prewarm_budget_min=%u wanted_then=%u free_then=%u clips=%u\n" + "sd_clock_hz=%u\n", + now, getCpuFrequencyMhz(), cpuMhzMin, pollGapMaxFullMs, pollGapMaxLowMs, samplesLowPower, debounceEpisodes, + committedEdges, renderLastMs, renderMaxMs, renderMaxName, renderMaxAtMs, renderCount, ESP.getFreeHeap(), + ESP.getMinFreeHeap(), ESP.getMaxAllocHeap(), pageRenderPrewarmMs, pageRenderPrewarmMaxMs, pageRenderDrawMs, + pageRenderDrawMaxMs, pageRenderDisplayMs, pageRenderDisplayMaxMs, pageBlocksMs, pageStatusBarMs, aaWorstLsbMs, + aaWorstLsbGlyphs, aaWorstLsbSdMs, aaWorstLsbSdDraws, aaWorstAtMs, aaWorstMsbMs, aaWorstMsbGlyphs, aaWorstMsbSdMs, + aaWorstMsbSdDraws, vertBodyMs, vertBodyCells, vertRubyMeasureMs, vertRubyDrawMs, vertRubyGroups, buildChunkMaxMs, + buildChunkMaxSpineIndex, buildChunkMaxPageBefore, buildChunkMaxPageAfter, buildTotalMaxMs, + buildTotalMaxSpineIndex, buildTotalMaxChunkCount, buildHeadroomMinFree == UINT32_MAX ? 0 : buildHeadroomMinFree, + buildHeadroomMinMaxAlloc, buildHeadroomMinWords, buildHeadroomMaxWords, lookaheadStarts, lookaheadCompletions, + lookaheadTicks, lookaheadPages, lookaheadTotalMs, lookaheadChunkMaxMs, lookaheadChunkMaxSpineIndex, + lookaheadChunkMaxMhz, lookaheadReleases, miniFreeTotal, miniFreeBuf, aaAborts, uiPrewarmFailCount, + uiPrewarmFailMinAlloc, onDemandGlyphsLast, onDemandGlyphsMax, onDemandGlyphsMaxName, miniRebuildsLast, + miniRebuildsMax, miniRebuildsMaxName, miniRebuildMsTotal, scanLastBytes, scanLastFonts, scanZeroCount, + prewarmEntryFailsTotal, scanFontOverflowTotal, glyphMissTotal, glyphMissBuf, fontName, fontStyles, fontAdvanceY, + fontGlyphs, fontResidentBytes, fontFromFlash ? "flash" : "sd", fontFlashBytes / 1024, fontScaleNum, fontScaleDen, + prewarmBudgetMin == UINT32_MAX ? 0 : prewarmBudgetMin, prewarmBudgetMinWanted, prewarmBudgetMinFree, + prewarmBudgetClips, sdClockHz); + writeReportPart(file, len); + + len = snprintf(reportBuf, sizeof(reportBuf), + "font_copy=%s | %s | %s\n" + "vert_layout=cell %u pitch %u ruby_reserve %u viewport %ux%u -> %u cols\n" + "layout_giveup=%u last=kind%u tokens=%u free=%u max=%u\n" + "aa_refresh_wait=%ums (max %ums)\n" + "aa_phases=lsb draw %ums push %ums | msb draw %ums push %ums\n" + "build_page_write=%u pages %ums\n" + "build_font=%u calls %ums table %u/%u full_skips %u\n" + "ui_prewarm_heap_max=%d\n" + "list_band=y%d+h%d row%d -> %d rows (screen %d)\n", + fontCopyEvents[fontCopyTotal >= FONT_COPY_EVENTS ? fontCopyTotal % FONT_COPY_EVENTS : 0], + fontCopyEvents[fontCopyTotal >= FONT_COPY_EVENTS ? (fontCopyTotal + 1) % FONT_COPY_EVENTS : 1], + fontCopyEvents[fontCopyTotal >= FONT_COPY_EVENTS ? (fontCopyTotal + 2) % FONT_COPY_EVENTS : 2], + vertCell, vertPitch, vertRubyReserve, vertViewportW, vertViewportH, + (vertPitch > 0 && vertViewportW > vertRubyReserve + vertCell) + ? static_cast((vertViewportW - vertRubyReserve - vertCell) / vertPitch + 1) + : 0u, + layoutGiveUps, layoutGiveUpKind, layoutGiveUpTokens, layoutGiveUpFree, layoutGiveUpMaxAlloc, + aaRefreshWaitMs, aaRefreshWaitMaxMs, aaLsbDrawMs, aaLsbPushMs, aaMsbDrawMs, aaMsbPushMs, + buildPageWrites, buildPageWriteMs, buildFontCalls, buildFontMs, buildFontTableMax, buildFontTableLimit, + buildFontFullSkips, uiPrewarmHeapMax, listBandY, listBandHeight, listRowHeightPx, listVisibleRowCount, + listScreenHeight); + if (len < 0) len = 0; + if (static_cast(len) >= sizeof(reportBuf)) len = static_cast(sizeof(reportBuf) - 1); + + // Heap checkpoints across the last book open, in stage order (KB free/KB largest block). + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "open_heap="); + for (uint8_t i = 0; i < OPEN_STAGE_COUNT && static_cast(len) < sizeof(reportBuf); i++) { + if (openStages[i].label[0] == '\0') continue; + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "%s:%u/%u ", openStages[i].label, openStages[i].freeKb, + openStages[i].maxAllocKb); + } + if (static_cast(len) < sizeof(reportBuf)) { + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "\n"); + } + + // Heap around the last reader teardown (KB free before, free/largest block after). + if (closeBeforeFreeKb != 0 || closeAfterFreeKb != 0) { + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "close_heap=%u -> %u/%u\n", closeBeforeFreeKb, + closeAfterFreeKb, closeAfterMaxKb); + } + + // Oldest first, so the list reads in the order the renders happened. + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "render_log="); + for (uint8_t i = 0; i < RENDER_LOG_SIZE && static_cast(len) < sizeof(reportBuf); i++) { + const RenderEntry& entry = renderLog[(renderLogNext + i) % RENDER_LOG_SIZE]; + if (entry.name[0] == '\0') continue; // ring not full yet + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "%s:%u@%u/%u%+d r%u ", entry.name, entry.ms, + entry.heapFreeKb, entry.heapMaxAllocKb, entry.heapDeltaKb, entry.miniRebuilds); + } + if (static_cast(len) < sizeof(reportBuf)) { + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "\n"); + } + writeReportPart(file, len); + + // Newest first: @ms min=B in= after= now=freeK/maxK. + len = snprintf(reportBuf, sizeof(reportBuf), "heap_min_log="); + { + const uint32_t shown = heapMinEventTotal < HEAP_MIN_EVENTS ? heapMinEventTotal : HEAP_MIN_EVENTS; + for (uint32_t i = 0; i < shown && static_cast(len) < sizeof(reportBuf); i++) { + const HeapMinEvent& e = heapMinEvents[(heapMinEventTotal - 1 - i) % HEAP_MIN_EVENTS]; + len += + snprintf(reportBuf + len, sizeof(reportBuf) - len, "%s@%lu min=%lu in=%s after=%s now=%luK/%luK", + i ? " | " : "", static_cast(e.ms), static_cast(e.minFree), e.in, + e.after, static_cast(e.freeNow / 1024), static_cast(e.maxNow / 1024)); + } + } + if (static_cast(len) < sizeof(reportBuf)) { + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "\n"); + } + writeReportPart(file, len); + + // Newest first: @ms caller= q= type (1 mutex, 4 recursive). + len = snprintf(reportBuf, sizeof(reportBuf), "mutex_log=total %lu", static_cast(mutexEventTotal)); + { + const uint32_t shown = mutexEventTotal < MUTEX_EVENTS ? mutexEventTotal : MUTEX_EVENTS; + for (uint32_t i = 0; i < shown && static_cast(len) < sizeof(reportBuf); i++) { + const MutexEvent& e = mutexEvents[(mutexEventTotal - 1 - i) % MUTEX_EVENTS]; + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, " | @%lu caller=0x%08lx q=0x%08lx t%u", + static_cast(e.ms), static_cast(e.caller), + static_cast(e.handle), static_cast(e.type)); + } + } + if (static_cast(len) < sizeof(reportBuf)) { + len += snprintf(reportBuf + len, sizeof(reportBuf) - len, "\n"); + } + writeReportPart(file, len); + // The notes are constant, so they go from flash straight to the card and never + // compete with the figures above for room in reportBuf. + file.write(reinterpret_cast(kReportNotes), sizeof(kReportNotes) - 1); + + if (capturedLogsPending) { + HalFile logFile; + if (Storage.openFileForWrite("DIAG", LOG_PATH, logFile)) { + logFile.write(capturedLogs, strnlen(capturedLogs, sizeof(capturedLogs))); + capturedLogsPending = false; + } + } + + // Drop the next interval. The SD write above sits between two samples, so measuring across it + // would report this file's own cost as the worst-case poll gap -- and it would land in the + // low-power bucket, which is the one number the whole exercise exists to read. + lastSampleAt = 0; +} + +#endif // INPUT_DIAG diff --git a/src/util/InputDiag.h b/src/util/InputDiag.h new file mode 100644 index 00000000000..5d4622abdc4 --- /dev/null +++ b/src/util/InputDiag.h @@ -0,0 +1,283 @@ +#pragma once + +#include + +// Serial-free input timing diagnostics. +// +// The USB-write-locked X3 units have no usable serial console, so the numbers that decide whether a +// button press can be seen at all have nowhere to go. This writes them to the SD card instead, which +// is already the only channel in and out of those devices. +// +// The quantity that matters is the interval between consecutive gpio.update() calls. InputManager +// commits a state change only once two consecutive samples agree (DEBOUNCE_DELAY = 5 ms), so a press +// shorter than that interval can land in a single sample and never produce an edge at all. At +// LOW_POWER_FREQ the idle loop delay is 50 ms and the loop body itself runs 16x slower, which is how +// menu presses went missing. +// +// Compiled out unless INPUT_DIAG is defined. Put it in platformio.local.ini (gitignored), never in a +// release build: the calls below become empty inlines the optimizer removes, so the shipped firmware +// pays nothing. + +#ifdef INPUT_DIAG +class InputDiag { + public: + // Once per main-loop iteration, immediately after gpio.update(). + static void sample(unsigned long nowMs, bool committedEdge, bool debouncePending); + + // One completed activity render, measured in the render task: drawing plus the panel refresh. + // The panel refresh is a fixed few hundred ms, so anything well above that is drawing -- which on + // a screen full of SD-card CJK glyphs means card reads, not pixels. + // + // The activity name is recorded per render because a running maximum cannot say *which* render was + // slow, and on a screen whose glyph cache warms on first use the first render and the tenth are + // different questions. + // Free heap at the top of a render, for the consumption figure noteRender() reports. Paired so + // the sample is taken inside the diagnostic rather than by every caller. + static void noteRenderStart(); + + // onDemandGlyphs: glyphs this render had to read one at a time because the prewarm did not + // cover them. A prewarm naming the wrong font reports success and shows up only here. + // miniRebuilds/miniRebuildMs: times this render found the resident glyph arena insufficient and + // rebuilt it, and how long that took. Zero on-demand glyphs with a rebuild count climbing per + // render is a caller warming one string at a time, which no other figure here distinguishes from + // drawing that is simply slow. + static void noteRender(const char* activityName, unsigned long durationMs, uint32_t onDemandGlyphs, + uint32_t miniRebuilds, uint32_t miniRebuildMs); + + // The band the last list screen handed FreeInkUI, the row pitch it drew at, and the row count + // that fits by that arithmetic. A row laid out below the glass is still selectable, so the + // cursor can walk off the visible area and the viewport will not follow it -- comparing this + // count against the rows actually on screen says whether the band is taller than the panel. + static void noteListBand(int bandY, int bandHeight, int rowHeight, int visibleRows, int screenHeight); + + // Bracket the frame's glyph prewarm. Reports the heap it consumed, which separates "the glyph + // caches took the memory" from "the render took it somewhere else": a file browser page turn was + // seen to consume 46 KB and never give it back, with nothing to say what took it. + static void noteUiPrewarmBegin(); + static void noteUiPrewarmEnd(); + + // Heap checkpoints across one book-open sequence, to break the fixed ~85KB reader footprint + // into its stages (epub metadata, reader font load, section load/build, first page). Slots are + // write-once until the next noteOpenBegin(), so renderBook re-runs don't overwrite the first + // open's figures. Reported as open_heap= in the diag file. + static void noteOpenBegin(); + static void noteOpenStage(uint8_t slot, const char* label); + + // Heap around the reader's teardown: free before the section/epub release, free + // and largest block after. Together with open_heap's "enter" this answers "how + // much of the open cost came back when the book was closed" -- the question the + // 30KB-at-enter crash session left open. Reported as close_heap= in the diag file. + static void noteCloseHeap(uint32_t beforeFreeKb, uint32_t afterFreeKb, uint32_t afterMaxKb); + + // What the page scope's scan pass handed to the prewarm (bytes recorded, distinct fonts) and the + // running count of prewarm() entry bails (scratch alloc failure / zero heap budget). Splits the + // "prewarm reported done in 10ms yet the draw faulted a screenful" symptom into its three + // possible causes; see the field comments in InputDiag.cpp. + static void noteScanOutcome(uint32_t scanBytes, uint8_t scanFonts, uint32_t prewarmEntryFails, + uint32_t scanFontOverflows); + + // One page render's phase breakdown, in milliseconds. renderContents already measures these for + // LOG_DBG; on a device with no serial console that measurement had nowhere to go, which is why the + // three seconds a page turn costs stayed unattributed through two wrong guesses. + static void notePageRender(unsigned long prewarmMs, unsigned long drawMs, unsigned long displayMs); + + // The draw phase split one level further: laying the page's blocks down, and the status bar. + // Needed because the body-cell loops inside renderVertical accounted for 38 ms of a 520 ms draw -- + // the rest is somewhere neither of them covers. + static void notePageDrawParts(unsigned long blocksMs, unsigned long statusBarMs); + + // Where renderVertical's time went for one page. Vertical drawing measured 2119 ms against + // horizontal's 76 ms on identical text; this splits that figure into the body cells, the pass that + // measures each ruby run, and the pass that draws it. + static void noteVerticalRender(unsigned long bodyMs, unsigned long bodyCells, unsigned long rubyMeasureMs, + unsigned long rubyDrawMs, unsigned long rubyGroups); + + // The two antialiasing planes side by side, kept for the worst LSB seen. They run identical loops + // over identical content, yet the first has measured 2192 ms against the second's 72 ms -- so the + // first pass is warming something the second then reuses. These name the two candidates: glyphs + // fetched from the card one at a time, and .pxc draws that missed the RAM slot. Whichever column + // carries the gap decides what to fix; guessing at this cost eight wrong theories once already. + static void noteGrayscaleSplit(unsigned long lsbMs, unsigned long lsbGlyphs, unsigned long lsbSdMs, + unsigned long lsbSdDraws, unsigned long msbMs, unsigned long msbGlyphs, + unsigned long msbSdMs, unsigned long msbSdDraws); + + // One Section::buildSomeMore() call: the spine item, the page-count watermark before and + // after, and how long it took. buildSomeMore has no internal time budget -- it lays out + // whatever chunk it's given as one atomic call, holding RenderLock (and, from most call + // sites, HalPowerManager::Lock) for the duration -- so a single pathological page anywhere + // in a chapter can freeze input for as long as that one call takes. render_max_ms alone + // can't say *where*: this pins the worst chunk to a spine index and page range so a repeat + // capture can point at the actual content instead of just the duration. + static void noteBuildChunk(int spineIndex, uint16_t pageCountBefore, uint16_t pageCountAfter, + unsigned long durationMs); + + // Sum of every buildSomeMore() call made to catch one render's target page up, across + // however many chunks that took. A render can be slow from many cheap chunks in a long + // loop just as easily as from one expensive one; noteBuildChunk's per-chunk max misses + // that shape entirely, so this pins the worst render-level total separately. + static void noteBuildTotal(int spineIndex, unsigned long totalMs, int chunkCount); + + // Headroom a layout pass had when it started: free heap, largest block, and the token count + // it was about to size its arrays by. The smallest of these across a session says how close + // ordinary chapters run to the point where the pass has to give up (a 2026-09-10 crash had + // it at ~1 KB, laying out 648 tokens). + static void noteBuildHeadroom(uint32_t freeHeap, uint32_t maxAlloc, uint32_t words); + + // The .cpfont the reader is pointed at, taken at load: its name, how many styles it carries, + // the em size and glyph count of the first, and the bytes it holds permanently (coverage + // intervals, kern classes, ligature pairs) before any page is drawn. A report from a device + // that "got slow after changing the font" is unreadable without this line. + // flash/flashBytes: whether the reads go to the copy in the inactive OTA slot and how many + // leading bytes of the file it holds; scaleNum/scaleDen: the glyph scale applied at load (an + // 18 pt drawn from the 16 pt file reads 18/16 here and is otherwise indistinguishable from the + // real 18 pt file in every other line of this report). + static void noteFontChoice(const char* path, uint8_t styles, uint8_t advanceY, uint32_t glyphs, + uint32_t residentBytes, bool flash, uint32_t flashBytes, uint8_t scaleNum, + uint8_t scaleDen); + + // The SPI clock the SD card was actually opened at. The X3 routes its card through the GPIO + // matrix, which is rated lower than the SDK's 40 MHz default, so a throughput figure means + // nothing without knowing which rate produced it. + static void noteSdClock(uint32_t hz); + + // The font copy in flash: what the boot check and each copy attempt decided. One preformatted + // line per event, newest last, three kept. A page that still reads the card with the copy + // switched on is unreadable without knowing which of "no candidate", "copy invalid" or + // "copy failed" it was. + static void noteFontCopy(const char* line); + + // The geometry a vertical page was actually laid out with: the full-width cell, the column + // pitch (cell + gap), the ruby reserve at the right edge, the viewport, and how many columns + // that works out to. Without these the column count on the device cannot be reconciled with + // the font size and the margin/line-spacing settings -- which is exactly what a report of + // "the page holds fewer columns now" needs (2026-09-11). + static void noteVerticalLayout(uint16_t cell, uint16_t pitch, uint16_t rubyReserve, uint16_t viewportWidth, + uint16_t viewportHeight); + + // A layout pass that refused to lay out a paragraph, line or column. Refusing is not a crash -- + // it abandons the chapter build and the reader shows "Failed to index" -- so the report has to + // name which of the six checks refused and on how many tokens, or the failure is unattributable. + // kind: 1 vertical paragraph gate, 2 vertical token heights, 3 vertical column probe, + // 4 vertical column TextBlock, 5 horizontal paragraph gate, 6 horizontal line probe. + static void noteLayoutGiveUp(uint8_t kind, uint32_t tokens); + + // Time the render spent waiting for the panel to finish the black-and-white refresh before the + // grayscale planes can be pushed. Reported on its own because it used to be counted as part of + // the first grayscale plane, where it read as a drawing cost and was chased twice as one. + static void noteRefreshWait(unsigned long ms); + + // The two grayscale plane loops, each split into composing the strip in RAM and pushing it to + // the panel. They do identical work, so a large difference between them is not drawing: it is + // the bus waiting on a panel that has not finished the black-and-white refresh. + static void noteGrayscalePhases(unsigned long lsbDrawMs, unsigned long lsbPushMs, unsigned long msbDrawMs, + unsigned long msbPushMs); + + // One laid-out page written to the card during a section build. Counted and summed so the + // storage-bound part of a build is separable from the parse/measure part before anything is + // attributed to "the build being slow". + static void noteBuildPageWrite(unsigned long ms); + + // Advance-table work a build did, sampled when the build finishes: SD fetch calls and their + // total time, how full the table got against its cap, and how many fetches were refused + // because it was already full. Past the cap every measurement of an uncached codepoint costs + // a per-glyph load, so a non-zero full_skips changes what the rest of the build is doing. + static void noteBuildFontWork(uint32_t calls, uint32_t ms, uint32_t tableMax, uint32_t tableLimit, + uint32_t fullSkips); + + // One page-glyph prewarm: how many glyphs the heap allowed and how many the page asked for. + // When the two meet, the budget bit and the rest of the page faults in one glyph at a time -- + // the number that moves when the glyphs get bigger rather than the markup more complex. + static void notePrewarmBudget(uint32_t budgetGlyphs, uint32_t wantedGlyphs, uint32_t freeHeap); + + // Codepoints the render had to fetch one at a time because the prewarmed arena did not hold + // them. The last few are printed: which characters they are says whether the prewarm missed a + // font (they will share one script or style), a whole page (the arena was evicted), or just + // the tail of a dense one. + static void noteGlyphMiss(uint32_t codepoint, uint8_t style); + + // Idle next-chapter build: one startBuild, and one buildSomeMore() tick with the pages it + // produced. Reported with the CPU clock the slowest tick ran at, since a tick that lands + // after the idle downclock would run at a fraction of the speed and look like a bad page. + static void noteLookaheadStart(); + static void noteLookaheadChunk(int spineIndex, uint16_t pagesBuilt, unsigned long durationMs, bool completed); + static void noteLookaheadRelease(); + // Grayscale pass cut short because a press was latched during the render. + static void noteAaAborted(); + + // One UI glyph prewarm that reported failure (see UiGlyphPrewarm). Records the count and the + // tightest max-alloc seen at such a failure, so a slow list screen can be attributed to the + // prewarm not landing rather than to the drawing itself. + static void noteUiPrewarmFailure(); + + // One chapter-image processing event (found/probe/extract/alt/lazy-extract), with the heap at + // that moment. Rewrites /image-diag.txt per event, same crash-surviving scheme as noteOpenStage: + // image failures happen mid-build under RenderLock where the periodic flush never runs. The + // ring keeps the last 24 events, enough for every image in the diagnostic EPUB. + static void noteImageEvent(const char* line); + // A named point for heap_min_log only: marks where a render or build has got to, so a + // fall of the heap low-water mark can be placed between two of them. + static void notePoint(const char* tag); + // Writes every heap block (used ones of 256 B and more with their first 24 bytes, free + // ones of 1 KB and more) to /heap-map-boot.txt the first time in a boot and to + // /heap-map.txt after that, so the Home heap after reading can be set beside the Home + // heap before any book. The first word of a C++ object is its vtable, which the ELF's + // symbol table names; string data reads as text. + static void dumpHeapMap(const char* label); + + // Snapshot the RTC log ring. A failure capture displaces a pending informational one: the + // periodic flush is seconds away, and a slow render taken just before a build failed used to + // keep the failure's own log ring from ever reaching the card (2026-09-11). + static void captureLogs(const char* reason, bool failure = false); + + // Write the report and any pending capture now, ignoring the usual interval. For failure paths, + // where the session may not survive to the next scheduled flush. + static void flushNow(); + + // Rewrites the snapshot on the SD card, at most every few seconds. + static void flush(bool inputActive); +}; +#else +class InputDiag { + public: + static void sample(unsigned long, bool, bool) {} + static void noteRenderStart() {} + static void noteRender(const char*, unsigned long, uint32_t, uint32_t, uint32_t) {} + static void noteListBand(int, int, int, int, int) {} + static void noteUiPrewarmBegin() {} + static void noteUiPrewarmEnd() {} + static void noteOpenBegin() {} + static void noteOpenStage(uint8_t, const char*) {} + static void noteCloseHeap(uint32_t, uint32_t, uint32_t) {} + static void noteScanOutcome(uint32_t, uint8_t, uint32_t, uint32_t) {} + static void notePageRender(unsigned long, unsigned long, unsigned long) {} + static void notePageDrawParts(unsigned long, unsigned long) {} + static void noteVerticalRender(unsigned long, unsigned long, unsigned long, unsigned long, unsigned long) {} + static void noteGrayscaleSplit(unsigned long, unsigned long, unsigned long, unsigned long, unsigned long, + unsigned long, unsigned long, unsigned long) {} + static void noteBuildChunk(int, uint16_t, uint16_t, unsigned long) {} + static void noteBuildTotal(int, unsigned long, int) {} + static void noteBuildHeadroom(uint32_t, uint32_t, uint32_t) {} + static void noteGlyphMiss(uint32_t, uint8_t) {} + static void noteFontChoice(const char*, uint8_t, uint8_t, uint32_t, uint32_t, bool, uint32_t, uint8_t, uint8_t) {} + static void notePrewarmBudget(uint32_t, uint32_t, uint32_t) {} + static void noteSdClock(uint32_t) {} + static void noteFontCopy(const char*) {} + static void noteVerticalLayout(uint16_t, uint16_t, uint16_t, uint16_t, uint16_t) {} + static void noteLayoutGiveUp(uint8_t, uint32_t) {} + static void noteRefreshWait(unsigned long) {} + static void noteGrayscalePhases(unsigned long, unsigned long, unsigned long, unsigned long) {} + static void noteBuildPageWrite(unsigned long) {} + static void noteBuildFontWork(uint32_t, uint32_t, uint32_t, uint32_t, uint32_t) {} + static void noteLookaheadStart() {} + static void noteLookaheadChunk(int, uint16_t, unsigned long, bool) {} + static void noteLookaheadRelease() {} + static void noteAaAborted() {} + static void noteUiPrewarmFailure() {} + static void noteImageEvent(const char*) {} + static void notePoint(const char*) {} + static void dumpHeapMap(const char*) {} + static void captureLogs(const char*, bool = false) {} + static void flushNow() {} + static void flush(bool) {} +}; +#endif