wallet/rpc: time GetFilteredNotes walks and slow RPCs

GetFilteredNotes logged "GetFilteredNotes ignoreLocked=N" on every call.
The balance RPCs run it on every GUI poll, so that line was log spam on
a fast wallet, and on a slow one the gaps between its timestamps were
the only timing there was. Those gaps also count lock waits and the
previous RPC's own post-processing.

It now logs one summary per walk: the filters, txs that passed the
tx-level checks out of the wallet total, notes examined, notes skipped
as spent, entries returned, and the walk time. The summary is always
written when the walk takes >= 500ms (that long under cs_main stalls
block connection) and otherwise only with -debug=bench. The line has no
lock-wait figure: every caller already holds LOCK2(cs_main, cs_wallet)
and CCriticalSection is recursive, so the inner LOCK2 never waits.

Lock waits are measured where they happen instead. CRPCTable::execute
logs "RPC <method> took <n>ms" under the same >= 500ms / -debug=bench
rule. The per-locked-note line moves to -debug=zrpcunsafe, since it
logs txid prefixes.

No behaviour change otherwise.

Co-Authored-By: Claude Opus 5.5 <noreply@anthropic.com>

src/rpc/server.cpp

@@ -640,6 +640,23 @@ std::string JSONRPCExecBatch(const UniValue& vReq)
     return ret.write() + "\n";
 }
 
+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.
+class RPCCallTimer {
+    const std::string& strMethod;
+    const int64_t nTimeStart;
+public:
+    explicit RPCCallTimer(const std::string& method) : strMethod(method), nTimeStart(GetTimeMicros()) {}
+    ~RPCCallTimer() {
+        const int64_t nMs = (GetTimeMicros() - nTimeStart) / 1000;
+        if (nMs >= 500 || LogAcceptCategory("bench"))
+            LogPrintf("RPC %s took %dms\n", strMethod, nMs);
+    }
+};
+}
+
 UniValue CRPCTable::execute(const std::string &strMethod, const UniValue &params) const
 {
     // Find method
@@ -674,6 +691,7 @@ UniValue CRPCTable::execute(const std::string &strMethod, const UniValue &params
     try
     {
         // Execute
+        RPCCallTimer timer(strMethod);
         return pcmd->actor(params, false, CPubKey());
     }
     catch (const std::exception& e)

src/wallet/wallet.cpp

@@ -5751,7 +5751,11 @@ void CWallet::GetFilteredNotes(
 {
     LOCK2(cs_main, cs_wallet);
 
-    LogPrintf("%s ignoreLocked=%d\n", __func__, ignoreLocked);
+    // 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 size_t nEntriesBefore = saplingEntries.size();
+    unsigned int nTxs = 0, nNotes = 0, nSpent = 0;
 
     for (auto & p : mapWallet) {
         CWalletTx wtx = p.second;
@@ -5776,10 +5780,12 @@ void CWallet::GetFilteredNotes(
                 continue;
             }
         }
+        nTxs++;
 
         for (auto & pair : wtx.mapSaplingNoteData) {
             SaplingOutPoint op = pair.first;
             SaplingNoteData nd = pair.second;
+            nNotes++;
 
             auto maybe_pt = SaplingNotePlaintext::decrypt(
                 wtx.vShieldedOutput[op.n].encCiphertext,
@@ -5799,6 +5805,7 @@ void CWallet::GetFilteredNotes(
             }
 
             if (ignoreSpent && nd.nullifier && IsSaplingSpent(*nd.nullifier)) {
+                nSpent++;
                 continue;
             }
 
@@ -5815,7 +5822,7 @@ void CWallet::GetFilteredNotes(
 
             // skip locked notes
              if (ignoreLocked && IsLockedNote(op)) {
-                 LogPrintf("%s: skipping locked note %s\n", __func__, op.hash.ToString().substr(0,10).c_str());
+                 LogPrint("zrpcunsafe", "%s: skipping locked note %s\n", __func__, op.hash.ToString().substr(0,10).c_str());
                  continue;
              }
 
@@ -5824,6 +5831,15 @@ void CWallet::GetFilteredNotes(
                 op, pa, note, notePt.memo(), wtx.GetDepthInMainChain() });
         }
     }
+
+    // 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")) {
+        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);
+    }
 }