From 21586b353a4fc8213f788d7936aa9bfe16e3346e Mon Sep 17 00:00:00 2001 From: DanS Date: Thu, 15 Oct 2026 16:48:44 -0500 Subject: [PATCH] wallet/rpc: monotonic timers and a quieter default slow-walk line Review follow-ups to the GetFilteredNotes / RPC timing logs: - Time with std::chrono::steady_clock instead of GetTimeMicros(), which is the system clock. A wall-clock step otherwise writes false ">= 500ms" lines unconditionally; on a WSL2 host the clock was seen stepping +3.6s every ~32s. - A long-poll getblocktemplate deliberately blocks (with cs_main released) until a new block arrives, so it is logged only under -debug=bench. - Log the method as "RPC method= took ms". A bare " rescan " token followed by "ms" matches ObsidianDragon's rescan-finished log heuristic. - The always-on slow-walk line keeps just the filters and the walk time; the wallet-size counts (txs, notes, spent, entries) are logged only with -debug=bench, so a shared debug.log doesn't carry them. - The -txindex=0 startup line names the version. Co-Authored-By: Claude Opus 5.5 --- src/init.cpp | 4 ++-- src/rpc/server.cpp | 22 +++++++++++++++------- src/wallet/wallet.cpp | 13 +++++++++---- 3 files changed, 26 insertions(+), 13 deletions(-) diff --git a/src/init.cpp b/src/init.cpp index 2e79b57d2..42a5a6dbc 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -2508,8 +2508,8 @@ bool AppInit2(boost::thread_group& threadGroup, CScheduler& scheduler) // located each note's block by re-reading its tx through the txindex, so on a -txindex=0 node // every fully shielded tx was skipped and these never moved those notes. Now they will. if (!fTxIndex && (pwalletMain->fSweepEnabled || pwalletMain->fSaplingConsolidationEnabled)) { - LogPrintf("%s: -txindex=0 with -zsweep/-consolidation: shielded notes that versions before this " - "fix never saw on such nodes are now included in sweeps and consolidations\n", __func__); + LogPrintf("%s: -txindex=0 with -zsweep/-consolidation: fully shielded notes, which versions before " + "v1.3.1 never saw on such nodes, are now included in sweeps and consolidations\n", __func__); } //Set Automatic Coinbase Shielding (default ON, conditional: self-guards diff --git a/src/rpc/server.cpp b/src/rpc/server.cpp index 4555e3081..bdb95c4d4 100644 --- a/src/rpc/server.cpp +++ b/src/rpc/server.cpp @@ -26,6 +26,7 @@ #include "util.h" #include "util/strencodings.h" #include "asyncrpcqueue.h" +#include #include #include #include @@ -643,16 +644,23 @@ std::string JSONRPCExecBatch(const UniValue& vReq) namespace { // Logs an RPC whose wall time reached 500ms, or every RPC under -debug=bench. That time includes // waiting for cs_main / cs_wallet behind block connection or another RPC, which the callee's own -// timers can't see because they start once the locks are held. +// timers can't see because they start once the locks are held. A long-poll getblocktemplate waits +// for a new block with cs_main released, so it is only logged under -debug=bench. The method is +// logged as method=: a bare " " token would match the GUI's " rescan " log heuristic. class RPCCallTimer { const std::string& strMethod; - const int64_t nTimeStart; + const bool fLongPoll; + const std::chrono::steady_clock::time_point start; public: - explicit RPCCallTimer(const std::string& method) : strMethod(method), nTimeStart(GetTimeMicros()) {} + RPCCallTimer(const std::string& method, const UniValue& params) + : strMethod(method), + fLongPoll(method == "getblocktemplate" && params.size() > 0 && params[0].isObject() && + !find_value(params[0], "longpollid").isNull()), + start(std::chrono::steady_clock::now()) {} ~RPCCallTimer() { - const int64_t nMs = (GetTimeMicros() - nTimeStart) / 1000; - if (nMs >= 500 || LogAcceptCategory("bench")) - LogPrintf("RPC %s took %dms\n", strMethod, nMs); + const int64_t nMs = std::chrono::duration_cast(std::chrono::steady_clock::now() - start).count(); + if ((nMs >= 500 && !fLongPoll) || LogAcceptCategory("bench")) + LogPrintf("RPC method=%s took %dms\n", strMethod, nMs); } }; } @@ -691,7 +699,7 @@ UniValue CRPCTable::execute(const std::string &strMethod, const UniValue ¶ms try { // Execute - RPCCallTimer timer(strMethod); + RPCCallTimer timer(strMethod, params); return pcmd->actor(params, false, CPubKey()); } catch (const std::exception& e) diff --git a/src/wallet/wallet.cpp b/src/wallet/wallet.cpp index ff86165de..5e4d54640 100644 --- a/src/wallet/wallet.cpp +++ b/src/wallet/wallet.cpp @@ -45,6 +45,7 @@ #include #include #include +#include #include #include #include "zcash/zip32.h" @@ -5762,7 +5763,7 @@ void CWallet::GetFilteredNotes( // Every caller already holds LOCK2, so the lock above never waits and this times the walk alone. // Time spent waiting for the locks shows up in the RPC's own "took" line (rpc/server.cpp). - const int64_t nTimeStart = GetTimeMicros(); + const std::chrono::steady_clock::time_point walkStart = std::chrono::steady_clock::now(); const size_t nEntriesBefore = saplingEntries.size(); unsigned int nTxs = 0, nNotes = 0, nSpent = 0; @@ -5850,12 +5851,16 @@ void CWallet::GetFilteredNotes( } // A slow walk holds cs_main long enough to stall block connection, so it is always logged; a - // fast one only with -debug=bench (the balance RPCs run it on every GUI poll). - const int64_t nWalkMs = (GetTimeMicros() - nTimeStart) / 1000; - if (nWalkMs >= 500 || LogAcceptCategory("bench")) { + // fast one only with -debug=bench (the balance RPCs run it on every GUI poll). The wallet-size + // counts go to the default log only with -debug=bench too. + const int64_t nWalkMs = std::chrono::duration_cast(std::chrono::steady_clock::now() - walkStart).count(); + if (LogAcceptCategory("bench")) { LogPrintf("%s: minDepth=%d ignoreSpent=%d requireSpendingKey=%d ignoreLocked=%d txs=%u/%u notes=%u spent=%u entries=%u walk=%dms\n", __func__, minDepth, ignoreSpent, requireSpendingKey, ignoreLocked, nTxs, (unsigned int)mapWallet.size(), nNotes, nSpent, (unsigned int)(saplingEntries.size() - nEntriesBefore), nWalkMs); + } else if (nWalkMs >= 500) { + LogPrintf("%s: minDepth=%d ignoreSpent=%d requireSpendingKey=%d ignoreLocked=%d walk=%dms\n", + __func__, minDepth, ignoreSpent, requireSpendingKey, ignoreLocked, nWalkMs); } }