Merge 19c8336d97 into c5e44a0435

32d55e28af test: Use the correct node for doubled keypath test (Ava Chow)

Pull request description:

  #29124 had a silent merge conflict with #32350 which resulted in it using the wrong node. Fix the test to use the correct v22 node.

ACKs for top commit:
  maflcko:
    lgtm ACK 32d55e28af
  rkrux:
    ACK 32d55e28af
  BrandonOdiwuor:
    Code Review ACK 32d55e28af

Tree-SHA512: 1e0231985beb382b16e1d608c874750423d0502388db0c8ad450b22d17f9d96f5e16a6b44948ebda5efc750f62b60d0de8dd20131f449427426a36caf374af92

doc/release-notes-31672.md

@@ -0,0 +1,9 @@
+RPC
+---
+
+A new field `cpu_load` has been added to the `getpeerinfo` RPC output. It
+shows the CPU time (user + system) spent processing messages to/from the
+peer, in per milles (‰) of the duration of the connection. The field is
+optional and will be omitted on platforms that do not support this or if not
+yet measured. Note that high CPU time is not necessarily a bad thing - new
+valid transactions and blocks require CPU time to be validated. (#31672)

src/net.cpp

@@ -660,6 +660,8 @@ void CNode::CopyStats(CNodeStats& stats)
     stats.addrLocal = addrLocalUnlocked.IsValid() ? addrLocalUnlocked.ToStringAddrPort() : "";
 
     X(m_conn_type);
+
+    X(m_cpu_time);
 }
 #undef X
 
@@ -3050,6 +3052,8 @@ void CConnman::ThreadMessageHandler()
                 if (pnode->fDisconnect)
                     continue;
 
+                CpuTimer timer{[&pnode](std::chrono::nanoseconds elapsed) { pnode->m_cpu_time += elapsed; }};
+
                 // Receive messages
                 bool fMoreNodeWork = m_msgproc->ProcessMessages(pnode, flagInterruptMsgProc);
                 fMoreWork |= (fMoreNodeWork && !pnode->fPauseSend);

src/net.h

@@ -31,6 +31,7 @@
 #include <util/check.h>
 #include <util/sock.h>
 #include <util/threadinterrupt.h>
+#include <util/time.h>
 
 #include <atomic>
 #include <condition_variable>
@@ -220,6 +221,8 @@ public:
     TransportProtocolType m_transport_type;
     /** BIP324 session id string in hex, if any. */
     std::string m_session_id;
+    /** CPU time spent processing messages to/from the peer. */
+    std::chrono::nanoseconds m_cpu_time;
 };
 
 
@@ -969,6 +972,9 @@ public:
         m_min_ping_time = std::min(m_min_ping_time.load(), ping_time);
     }
 
+    /** CPU time spent processing messages to/from the peer. */
+    std::atomic<std::chrono::nanoseconds> m_cpu_time;
+
 private:
     const NodeId id;
     const uint64_t nLocalHostNonce;

src/rpc/net.cpp

@@ -143,6 +143,11 @@ static RPCHelpMan getpeerinfo()
                     {RPCResult::Type::NUM_TIME, "last_block", "The " + UNIX_EPOCH_TIME + " of the last block received from this peer"},
                     {RPCResult::Type::NUM, "bytessent", "The total bytes sent"},
                     {RPCResult::Type::NUM, "bytesrecv", "The total bytes received"},
+                    {RPCResult::Type::NUM, "cpu_load", /*optional=*/true, "The CPU time (user + system) spent "
+                        "processing messages to/from the peer, in per milles (‰) of the connection duration. "
+                        "Will be omitted on platforms that do not support this or if still not measured. "
+                        "Note that high CPU time is not necessarily a bad thing - new valid transactions "
+                        "and blocks require CPU time to be validated."},
                     {RPCResult::Type::NUM_TIME, "conntime", "The " + UNIX_EPOCH_TIME + " of the connection"},
                     {RPCResult::Type::NUM, "timeoffset", "The time offset in seconds"},
                     {RPCResult::Type::NUM, "pingtime", /*optional=*/true, "The last ping time in milliseconds (ms), if any"},
@@ -205,6 +210,8 @@ static RPCHelpMan getpeerinfo()
 
     UniValue ret(UniValue::VARR);
 
+    const auto now{GetTime<std::chrono::seconds>()};
+
     for (const CNodeStats& stats : vstats) {
         UniValue obj(UniValue::VOBJ);
         CNodeStateStats statestats;
@@ -239,6 +246,9 @@ static RPCHelpMan getpeerinfo()
         obj.pushKV("last_block", count_seconds(stats.m_last_block_time));
         obj.pushKV("bytessent", stats.nSendBytes);
         obj.pushKV("bytesrecv", stats.nRecvBytes);
+        if (stats.m_cpu_time > 0s && now > stats.m_connected) {
+            obj.pushKV("cpu_load", /* ‰ */1000.0 * stats.m_cpu_time / (now - stats.m_connected));
+        }
         obj.pushKV("conntime", count_seconds(stats.m_connected));
         obj.pushKV("timeoffset", Ticks<std::chrono::seconds>(statestats.time_offset));
         if (stats.m_last_ping_time > 0us) {

src/util/time.cpp

@@ -17,6 +17,16 @@
 #include <string_view>
 #include <thread>
 
+#ifdef WIN32
+#include <windows.h>
+#include <winnt.h>
+
+#include <processthreadsapi.h>
+#else
+#include <time.h>
+#endif
+
+
 void UninterruptibleSleep(const std::chrono::microseconds& n) { std::this_thread::sleep_for(n); }
 
 static std::atomic<std::chrono::seconds> g_mock_time{}; //!< For testing
@@ -128,3 +138,54 @@ struct timeval MillisToTimeval(std::chrono::milliseconds ms)
 {
     return MillisToTimeval(count_milliseconds(ms));
 }
+
+std::chrono::nanoseconds ThreadCpuTime()
+{
+#ifdef CLOCK_THREAD_CPUTIME_ID
+    timespec t;
+    if (clock_gettime(CLOCK_THREAD_CPUTIME_ID, &t) == -1) {
+        return std::chrono::nanoseconds{0};
+    }
+    return std::chrono::seconds{t.tv_sec} + std::chrono::nanoseconds{t.tv_nsec};
+#elif defined(WIN32)
+    FILETIME creation;
+    FILETIME exit;
+    FILETIME kernel;
+    FILETIME user;
+    // GetThreadTimes():
+    // https://learn.microsoft.com/en-us/windows/win32/api/processthreadsapi/nf-processthreadsapi-getthreadtimes
+    if (GetThreadTimes(GetCurrentThread(), &creation, &exit, &kernel, &user) == 0) {
+        return std::chrono::nanoseconds{0};
+    }
+
+    // https://learn.microsoft.com/en-us/windows/win32/api/minwinbase/ns-minwinbase-filetime
+    // "... you should copy the low- and high-order parts of the file time to a
+    // ULARGE_INTEGER structure, perform 64-bit arithmetic on the QuadPart
+    // member ..."
+
+    ULARGE_INTEGER kernel_;
+    kernel_.LowPart = kernel.dwLowDateTime;
+    kernel_.HighPart = kernel.dwHighDateTime;
+
+    ULARGE_INTEGER user_;
+    user_.LowPart = user.dwLowDateTime;
+    user_.HighPart = user.dwHighDateTime;
+
+    // The units of the returned values from GetThreadTimes() are "100-nanosecond periods".
+    // So, we multiply by 100 to get nanoseconds.
+    return std::chrono::nanoseconds{(kernel_.QuadPart + user_.QuadPart) * 100};
+#else
+    return std::chrono::nanoseconds{0};
+#endif
+}
+
+std::chrono::nanoseconds operator+=(std::atomic<std::chrono::nanoseconds>& a, std::chrono::nanoseconds b)
+{
+    std::chrono::nanoseconds expected;
+    std::chrono::nanoseconds desired;
+    do {
+        expected = a.load();
+        desired = expected + b;
+    } while (!a.compare_exchange_weak(expected, desired));
+    return desired;
+}

src/util/time.h

@@ -6,8 +6,10 @@
 #ifndef BITCOIN_UTIL_TIME_H
 #define BITCOIN_UTIL_TIME_H
 
+#include <atomic>
 #include <chrono> // IWYU pragma: export
 #include <cstdint>
+#include <functional>
 #include <optional>
 #include <string>
 #include <string_view>
@@ -145,4 +147,46 @@ struct timeval MillisToTimeval(int64_t nTimeout);
  */
 struct timeval MillisToTimeval(std::chrono::milliseconds ms);
 
+/**
+ * Retrieve the CPU time (user + system) spent by the current thread.
+ */
+std::chrono::nanoseconds ThreadCpuTime();
+
+/**
+ * Measure CPU time spent by the current thread.
+ * A clock is started when a CpuTimer is created. When the object is destroyed
+ * the elapsed CPU time is calculated and a callback function is invoked,
+ * providing it the elapsed CPU time.
+ */
+class CpuTimer
+{
+public:
+    using FinishedCB = std::function<void(std::chrono::nanoseconds)>;
+
+    /**
+     * Construct a timer.
+     * @param[in] finished_cb A callback to invoke when this object is destroyed.
+     */
+    CpuTimer(const FinishedCB& finished_cb)
+        : m_start{ThreadCpuTime()},
+          m_finished_cb{finished_cb}
+    {
+    }
+
+    ~CpuTimer()
+    {
+        m_finished_cb(ThreadCpuTime() - m_start);
+    }
+
+private:
+    const std::chrono::nanoseconds m_start;
+    FinishedCB m_finished_cb;
+};
+
+/**
+ * Add `b` nanoseconds to a nanoseconds atomic.
+ * @return The value of `a` immediately after the operation.
+ */
+std::chrono::nanoseconds operator+=(std::atomic<std::chrono::nanoseconds>& a, std::chrono::nanoseconds b);
+
 #endif // BITCOIN_UTIL_TIME_H

test/functional/rpc_net.py

@@ -142,6 +142,7 @@ class NetTest(BitcoinTestFramework):
         # The next two fields will vary for v2 connections because we send a rng-based number of decoy messages
         peer_info.pop("bytesrecv")
         peer_info.pop("bytessent")
+        peer_info.pop("cpu_load", None)
         assert_equal(
             peer_info,
             {

test/functional/wallet_backwards_compatibility.py

@@ -87,7 +87,7 @@ class BackwardsCompatibilityTest(BitcoinTestFramework):
         # 0.21.x and 22.x would both produce bad derivation paths when topping up an inactive hd chain
         # Make sure that this is being automatically cleaned up by migration
         node_master = self.nodes[1]
-        node_v22 = self.nodes[self.num_nodes - 5]
+        node_v22 = self.nodes[self.num_nodes - 3]
         wallet_name = "bad_deriv_path"
         node_v22.createwallet(wallet_name=wallet_name, descriptors=False)
         bad_deriv_wallet = node_v22.get_wallet_rpc(wallet_name)