From 0f68c47e931de05200adeae639bcee50ea3c171d Mon Sep 17 00:00:00 2001 From: Vasil Dimov Date: Wed, 15 Jan 2025 18:22:11 +0100 Subject: [PATCH] rpc: add cpu_load to getpeerinfo Add a new field `cpu_load` to the output of `getpeerinfo` RPC. It represents the CPU time spent by the message handling thread for the given peer, weighted for the duration of the connection. That is, for example, if two peers are equally demanding and one is connected longer than the other, then they will have the same `cpu_load` number. --- cmake/bitcoin-build-config.h.in | 6 +++ cmake/introspection.cmake | 34 ++++++++++++++++ doc/release-notes-31672.md | 8 ++++ src/net.cpp | 4 ++ src/net.h | 6 +++ src/rpc/net.cpp | 10 +++++ src/util/time.cpp | 71 +++++++++++++++++++++++++++++++++ src/util/time.h | 44 ++++++++++++++++++++ test/functional/rpc_net.py | 1 + 9 files changed, 184 insertions(+) create mode 100644 doc/release-notes-31672.md diff --git a/cmake/bitcoin-build-config.h.in b/cmake/bitcoin-build-config.h.in index 56e0519fac1..f38201ad9a9 100644 --- a/cmake/bitcoin-build-config.h.in +++ b/cmake/bitcoin-build-config.h.in @@ -105,6 +105,12 @@ /* Define this symbol if the BSD sysctl(KERN_ARND) is available */ #cmakedefine HAVE_SYSCTL_ARND 1 +/* Define this symbol if you have clock_gettime() */ +#cmakedefine HAVE_CLOCK_GETTIME 1 + +/* Define this symbol if you have GetThreadTimes() */ +#cmakedefine HAVE_GETTHREADTIMES 1 + /* Define to 1 if std::system or ::wsystem is available. */ #cmakedefine HAVE_SYSTEM 1 diff --git a/cmake/introspection.cmake b/cmake/introspection.cmake index 29c93869a73..98589f42a92 100644 --- a/cmake/introspection.cmake +++ b/cmake/introspection.cmake @@ -159,6 +159,40 @@ check_cxx_source_compiles(" " HAVE_SYSCTL_ARND ) +# Check for clock_gettime() (POSIX.1b). +check_cxx_source_compiles(" + #include + + int main(int, char**) + { + timespec now; + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now); + (void)now.tv_sec; + (void)now.tv_nsec; + return 0; + } + " HAVE_CLOCK_GETTIME +) + +# Check for GetThreadTimes() (Windows). +check_cxx_source_compiles(" + #include + #include + + #include + + int main(int, char**) + { + FILETIME creation; + FILETIME exit; + FILETIME kernel; + FILETIME user; + (void)GetThreadTimes(GetCurrentThread(), &creation, &exit, &kernel, &user); + return 0; + } + " HAVE_GETTHREADTIMES +) + if(NOT MSVC) include(CheckSourceCompilesAndLinks) diff --git a/doc/release-notes-31672.md b/doc/release-notes-31672.md new file mode 100644 index 00000000000..44e176bc035 --- /dev/null +++ b/doc/release-notes-31672.md @@ -0,0 +1,8 @@ +RPC +--- + +A new field `cpu_load` has been added to the `getpeerinfo` RPC output. +It shows the CPU time (user + system) spent processing messages from the +given peer and crafting messages for it expressed 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 still not measured. (#31672) diff --git a/src/net.cpp b/src/net.cpp index 47ef2d22d7d..dfd00bc22c6 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -648,6 +648,8 @@ void CNode::CopyStats(CNodeStats& stats) stats.addrLocal = addrLocalUnlocked.IsValid() ? addrLocalUnlocked.ToStringAddrPort() : ""; X(m_conn_type); + + X(m_cpu_time); } #undef X @@ -3016,6 +3018,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 99a9d0da4b4..3e436617c39 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 from this node and crafting messages for it. */ + 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 from this node and crafting messages for it. */ + 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 bda07365e0e..224df8f7904 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 from this peer " + "and crafting messages for it expressed in per milles (‰) of the " + "duration of the connection. Will be omitted on platforms that do not " + "support this or if still not measured."}, {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 00f0f473926..eb005702628 100644 --- a/src/util/time.cpp +++ b/src/util/time.cpp @@ -3,6 +3,8 @@ // Distributed under the MIT software license, see the accompanying // file COPYING or http://www.opensource.org/licenses/mit-license.php. +#include // IWYU pragma: keep + #include #include @@ -17,6 +19,16 @@ #include #include +#ifdef HAVE_CLOCK_GETTIME +#include +#elif defined(HAVE_GETTHREADTIMES) +#include +#include + +#include +#endif + + void UninterruptibleSleep(const std::chrono::microseconds& n) { std::this_thread::sleep_for(n); } static std::atomic g_mock_time{}; //!< For testing @@ -103,3 +115,62 @@ struct timeval MillisToTimeval(std::chrono::milliseconds ms) { return MillisToTimeval(count_milliseconds(ms)); } + +std::chrono::nanoseconds ThreadCpuTime() +{ +#ifdef HAVE_CLOCK_GETTIME + // An alternative to clock_gettime() is getrusage(). + + 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(HAVE_GETTHREADTIMES) + // An alternative to GetThreadTimes() is QueryThreadCycleTime() but it + // counts CPU cycles. + + 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; + + // https://learn.microsoft.com/en-us/windows/win32/api/processthreadsapi/nf-processthreadsapi-getthreadtimes + // "Thread kernel mode and user mode times are amounts of time. For example, + // if a thread has spent one second in kernel mode, this function will fill + // the FILETIME structure specified by lpKernelTime with a 64-bit value of + // ten million. That is the number of 100-nanosecond units in one second." + 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 27cbe50581f..369424a672a 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 @@ -119,4 +121,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, {