perf(daemon): memoize the external debug.log miss

When following the debug.log of a node this session did not launch, every
poll re-read the last 2 MB of the file and re-scanned it for the process
banner. If that node logs to its console instead, the banner is never
there, so the full re-scan repeated on every poll for the life of the
process.

- A miss is now remembered by pid and file size: if nothing has changed
  since the last miss, or the file is growing but the backoff has not
  elapsed, the scan is skipped.
- The retry schedule re-scans quickly during a fresh-node grace window
  (the banner flushes a beat after the pid appears) and then backs off
  from 4 s, doubling to a 60 s cap. The memo is cleared on a successful
  tie and when the followed process goes away.

Tests: the retry delay is fast within the grace window and then steps
4, 8, 16 s up to the 60 s cap.

Co-Authored-By: Claude Opus 4.8 <noreply@anthropic.com>
This commit is contained in:
2026-10-13 17:42:30 -05:00
co-authored by Claude Opus 4.8
parent 1cd4ea4026
commit 2c9e99c022
4 changed files with 52 additions and 1 deletions
+23 -1
View File
@@ -6793,6 +6793,7 @@ void App::pumpExternalDaemonLog()
if (!ext_log_tied_) return;
ext_log_tied_ = false;
ext_log_pid_ = 0;
ext_log_miss_pid_ = 0; ext_log_miss_size_ = 0; ext_log_backoff_ = 0.0; ext_log_retry_at_ = 0.0;
daemon_busy_.reset();
node_rebuilding_ = false;
busy_first_seen_ = {};
@@ -6817,6 +6818,16 @@ void App::pumpExternalDaemonLog()
const std::uintmax_t size = std::filesystem::file_size(path, ec);
if (ec) { untie(); return; }
const double nowLog = ImGui::GetTime();
if (!ext_log_tied_ && pid == ext_log_miss_pid_ &&
size == ext_log_miss_size_ && nowLog < ext_log_retry_at_) {
return; // nothing changed since the last miss, and not yet time to retry
}
if (!ext_log_tied_ && pid == ext_log_miss_pid_ &&
size != ext_log_miss_size_ && nowLog < ext_log_retry_at_ &&
(nowLog - ext_log_miss_since_) >= 15.0) {
return; // growing but past the fresh-node grace: honour the backoff even as it grows
}
if (!ext_log_tied_ || pid != ext_log_pid_ || size < ext_log_offset_) {
// (Re)tie: this process's lines from the last 2 MB, into a fresh tracker. The banner may be older than
// the window on a long-running node; a rebuild still in progress logged its markers recently.
@@ -6826,9 +6837,20 @@ void App::pumpExternalDaemonLog()
const size_t at = daemon::externalLogFeedOffset(window, from > 0,
daemon::EmbeddedDaemon::processStartUtc(pid));
untie();
if (at == std::string::npos) return; // not that process's log (it may log to its console)
if (at == std::string::npos) { // not that process's log (it may log to its console)
if (pid != ext_log_miss_pid_) { // new pid: reset the schedule
ext_log_miss_pid_ = pid;
ext_log_miss_since_ = nowLog;
ext_log_backoff_ = 0.0;
}
ext_log_miss_size_ = size;
// fresh node: banner flushes a beat after the pid; later, back off 4 -> 60 s
ext_log_retry_at_ = nowLog + daemon::nextExternalLogRetryDelay(nowLog - ext_log_miss_since_, ext_log_backoff_);
return;
}
daemon_busy_.reset();
ext_log_tied_ = true;
ext_log_miss_pid_ = 0; ext_log_miss_size_ = 0; ext_log_backoff_ = 0.0; ext_log_retry_at_ = 0.0;
ext_log_pid_ = pid;
ext_log_offset_ = from + window.size();
DEBUG_LOGF("[busy] following the debug.log of a node this session didn't launch (pid %ld)\n", pid);
+5
View File
@@ -1479,6 +1479,11 @@ private:
long ext_log_pid_ = 0;
std::uintmax_t ext_log_offset_ = 0;
double ext_log_next_at_ = 0.0;
long ext_log_miss_pid_ = 0; // pid whose banner we failed to find
std::uintmax_t ext_log_miss_size_ = 0; // file size at that miss
double ext_log_miss_since_ = 0.0; // when this pid first missed (fresh-node grace)
double ext_log_retry_at_ = 0.0; // next allowed re-scan (ImGui::GetTime)
double ext_log_backoff_ = 0.0; // current backoff seconds (0 until grace elapses)
void abortRpcBusyCanary();
void feedDaemonBusy(const std::string& chunk);
void resetDaemonBusy();
+11
View File
@@ -141,6 +141,17 @@ inline bool shouldConfirmStop(bool stopsDaemon, const DaemonBusyTracker& tracker
return stopsDaemon && (tracker.rebuilding() || rpcBusyWhileAlive);
}
// Retry schedule after failing to find a pid's banner in debug.log: re-scan fast during the fresh-node grace
// window, then back off 4 s doubling to a 60 s cap. `backoff` is the caller's running state (0 until grace ends).
inline double nextExternalLogRetryDelay(double ageSinceMiss, double& backoff,
double graceWindow = 15.0, double fast = 2.0,
double base = 4.0, double cap = 60.0)
{
if (ageSinceMiss < graceWindow) return fast;
backoff = (backoff < base) ? base : (backoff * 2.0 < cap ? backoff * 2.0 : cap);
return backoff;
}
/**
* Where to start feeding a DaemonBusyTracker from the last `window` of the debug.log of a node someone else
* started at `processStartUtc` (UTC seconds). Only lines that process wrote count: a node started with
+13
View File
@@ -6755,6 +6755,19 @@ void testDebugLogTailRules()
EXPECT_TRUE(externalLogFeedOffset(midRun, false, t0) == std::string::npos); // whole file, no banner: can't tell
EXPECT_TRUE(externalLogFeedOffset(oldRun + newRun, false, 0) == std::string::npos);
// C107: the miss-retry schedule: fast in the grace window, then 4,8,...,60 s cap.
{
double b = 0.0;
EXPECT_NEAR(dragonx::daemon::nextExternalLogRetryDelay(0.0, b), 2.0, 1e-9);
EXPECT_NEAR(dragonx::daemon::nextExternalLogRetryDelay(14.9, b), 2.0, 1e-9);
EXPECT_NEAR(b, 0.0, 1e-9);
EXPECT_NEAR(dragonx::daemon::nextExternalLogRetryDelay(15.0, b), 4.0, 1e-9);
EXPECT_NEAR(dragonx::daemon::nextExternalLogRetryDelay(20.0, b), 8.0, 1e-9);
EXPECT_NEAR(dragonx::daemon::nextExternalLogRetryDelay(30.0, b), 16.0, 1e-9);
for (int i = 0; i < 6; ++i) dragonx::daemon::nextExternalLogRetryDelay(100.0, b);
EXPECT_NEAR(b, 60.0, 1e-9);
}
#ifdef _WIN32
const long self = static_cast<long>(GetCurrentProcessId());
#else