diff --git a/doc/release-notes-31672.md b/doc/release-notes-31672.md new file mode 100644 index 00000000000..1a6b5cd27fb --- /dev/null +++ b/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) diff --git a/src/net.cpp b/src/net.cpp index fc0edc1a5c1..f5e840c27f5 100644 --- a/src/net.cpp +++ b/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); diff --git a/src/net.h b/src/net.h index 9fdec52115e..cdac608e377 100644 --- a/src/net.h +++ b/src/net.h @@ -31,6 +31,7 @@ #include #include #include +#include #include #include @@ -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 m_cpu_time; + private: const NodeId id; const uint64_t nLocalHostNonce; diff --git a/src/rpc/net.cpp b/src/rpc/net.cpp index 3a5b8abdf26..e6408722fe1 100644 --- a/src/rpc/net.cpp +++ b/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()}; + 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(statestats.time_offset)); if (stats.m_last_ping_time > 0us) { diff --git a/src/util/time.cpp b/src/util/time.cpp index 62d2c98debd..c63ea71f0ae 100644 --- a/src/util/time.cpp +++ b/src/util/time.cpp @@ -17,6 +17,16 @@ #include #include +#ifdef WIN32 +#include +#include + +#include +#else +#include +#endif + + void UninterruptibleSleep(const std::chrono::microseconds& n) { std::this_thread::sleep_for(n); } static std::atomic 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& 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; +} diff --git a/src/util/time.h b/src/util/time.h index 6bfa469a52a..1770373232e 100644 --- a/src/util/time.h +++ b/src/util/time.h @@ -6,8 +6,10 @@ #ifndef BITCOIN_UTIL_TIME_H #define BITCOIN_UTIL_TIME_H +#include #include // IWYU pragma: export #include +#include #include #include #include @@ -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; + + /** + * 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& a, std::chrono::nanoseconds b); + #endif // BITCOIN_UTIL_TIME_H diff --git a/test/functional/rpc_net.py b/test/functional/rpc_net.py index 41ecbbed22d..a450ae381db 100755 --- a/test/functional/rpc_net.py +++ b/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, {