diff --git a/configure.ac b/configure.ac index cc153807f7..a48ed01ad0 100644 --- a/configure.ac +++ b/configure.ac @@ -841,6 +841,42 @@ fi AC_SEARCH_LIBS([clock_gettime],[rt]) +AC_MSG_CHECKING([for clock_gettime w/ CLOCK_THREAD_CPUTIME_ID]) +AC_COMPILE_IFELSE([AC_LANG_PROGRAM([[ + #include + ]],[[ + timespec now; + clock_gettime(CLOCK_THREAD_CPUTIME_ID, &now); + (void)now.tv_sec; + (void)now.tv_nsec; + ]]) +],[ + AC_MSG_RESULT([yes]) + AC_DEFINE([HAVE_CLOCK_GETTIME], [1], [Define this symbol if you have clock_gettime]) +],[ + AC_MSG_RESULT([no]) +]) + +AC_MSG_CHECKING([for GetThreadTimes]) +AC_COMPILE_IFELSE([AC_LANG_PROGRAM([[ + #include + #include + + #include + ]],[[ + FILETIME creation; + FILETIME exit; + FILETIME kernel; + FILETIME user; + (void)GetThreadTimes(GetCurrentThread(), &creation, &exit, &kernel, &user); + ]]) +],[ + AC_MSG_RESULT([yes]) + AC_DEFINE([HAVE_GETTHREADTIMES], [1], [Define this symbol if you have GetThreadTimes]) +],[ + AC_MSG_RESULT([no]) +]) + if test "$TARGET_OS" != "windows"; then dnl All windows code is PIC, forcing it on just adds useless compile warnings AX_CHECK_COMPILE_FLAG([-fPIC], [PIC_FLAGS="-fPIC"]) diff --git a/doc/release-notes-31672.md b/doc/release-notes-31672.md new file mode 100644 index 0000000000..44e176bc03 --- /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 961bc30785..3576cfba67 100644 --- a/src/net.cpp +++ b/src/net.cpp @@ -643,6 +643,8 @@ void CNode::CopyStats(CNodeStats& stats) stats.addrLocal = addrLocalUnlocked.IsValid() ? addrLocalUnlocked.ToStringAddrPort() : ""; X(m_conn_type); + + X(m_cpu_time); } #undef X @@ -2958,6 +2960,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 da1120c09e..bb1bbc165b 100644 --- a/src/net.h +++ b/src/net.h @@ -31,6 +31,7 @@ #include #include #include +#include #include #include @@ -222,6 +223,8 @@ public: std::string m_session_id; /** whether this peer forced its connection by evicting another */ bool m_forced_inbound; + /** CPU time spent processing messages from this node and crafting messages for it. */ + std::chrono::nanoseconds m_cpu_time; }; @@ -955,6 +958,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 d816e11ef8..557cfaa74d 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"}, @@ -206,6 +211,8 @@ static RPCHelpMan getpeerinfo() UniValue ret(UniValue::VARR); + const auto now{GetTime()}; + for (const CNodeStats& stats : vstats) { UniValue obj(UniValue::VOBJ); CNodeStateStats statestats; @@ -240,6 +247,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 f08eb5300a..db16de2398 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 @@ -14,6 +16,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 @@ -72,3 +84,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 108560e0e0..66f3394cd6 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 using namespace std::chrono_literals; @@ -116,4 +118,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 77784c89c4..88b92dc934 100755 --- a/test/functional/rpc_net.py +++ b/test/functional/rpc_net.py @@ -139,6 +139,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, {