From 4245043331dd62b26e141299ed607d75c4b8726d Mon Sep 17 00:00:00 2001 From: Jouzo <15011228+Jouzo@users.noreply.github.com> Date: Sat, 21 May 2022 14:39:04 +0100 Subject: [PATCH 1/2] Introduce new CRPCStats class to save key RPC statistics (#970) * Add CRPCStats to log RPC usage * Use CLockFreeMutex * Copy map via getMap method --- src/Makefile.am | 2 + src/httprpc.cpp | 15 +- src/init.cpp | 4 + src/rpc/register.h | 3 + src/rpc/stats.cpp | 203 ++++++++++++++++++++++++++++ src/rpc/stats.h | 118 ++++++++++++++++ test/functional/feature_rpcstats.py | 73 ++++++++++ test/functional/rpc_help.py | 2 +- test/functional/test_runner.py | 1 + test/lint/check-rpc-mappings.py | 1 + test/lint/lint-includes.sh | 1 + 11 files changed, 419 insertions(+), 4 deletions(-) create mode 100644 src/rpc/stats.cpp create mode 100644 src/rpc/stats.h create mode 100644 test/functional/feature_rpcstats.py diff --git a/src/Makefile.am b/src/Makefile.am index 5c3fdb5ece..932c135d9c 100644 --- a/src/Makefile.am +++ b/src/Makefile.am @@ -217,6 +217,7 @@ DEFI_CORE_H = \ rpc/request.h \ rpc/server.h \ rpc/util.h \ + rpc/stats.h \ scheduler.h \ script/descriptor.h \ script/keyorigin.h \ @@ -603,6 +604,7 @@ libdefi_common_a_SOURCES = \ psbt.cpp \ rpc/rawtransaction_util.cpp \ rpc/util.cpp \ + rpc/stats.cpp \ scheduler.cpp \ script/descriptor.cpp \ script/sign.cpp \ diff --git a/src/httprpc.cpp b/src/httprpc.cpp index 8dfc133351..48d1d08d67 100644 --- a/src/httprpc.cpp +++ b/src/httprpc.cpp @@ -9,6 +9,7 @@ #include #include #include +#include #include #include #include @@ -148,7 +149,7 @@ static bool RPCAuthorized(const std::string& strAuth, std::string& strAuthUserna static bool CorsHandler(HTTPRequest *req) { auto host = corsOriginHost; - // If if it's empty assume cors is disallowed. Do nothing and proceed, + // If if it's empty assume cors is disallowed. Do nothing and proceed, // with request as usual. if (host.empty()) return false; @@ -157,7 +158,7 @@ static bool CorsHandler(HTTPRequest *req) { req->WriteHeader("Access-Control-Allow-Credentials", "true"); req->WriteHeader("Access-Control-Allow-Methods", "POST, GET, OPTIONS"); req->WriteHeader("Access-Control-Allow-Headers", "Content-Type, Authorization"); - + // If it's a Cors preflight request, short-circuit and return. We have // set what's needed already. if (req->GetRequestMethod() == HTTPRequest::OPTIONS) { @@ -171,8 +172,9 @@ static bool CorsHandler(HTTPRequest *req) { static bool HTTPReq_JSONRPC(HTTPRequest* req, const std::string &) { + int64_t time = GetTimeMillis(); // Handle CORS - if (CorsHandler(req)) + if (CorsHandler(req)) return true; // JSONRPC handles only POST @@ -230,6 +232,8 @@ static bool HTTPReq_JSONRPC(HTTPRequest* req, const std::string &) req->WriteHeader("Content-Type", "application/json"); req->WriteReply(HTTP_OK, strReply); + + if (statsRPC.isActive()) statsRPC.add(jreq.strMethod, GetTimeMillis() - time, strReply.length()); } catch (const UniValue& objError) { JSONErrorReply(req, objError, jreq.id); return false; @@ -279,6 +283,7 @@ bool StartHTTPRPC() assert(eventBase); httpRPCTimerInterface = MakeUnique(eventBase); RPCSetTimerInterface(httpRPCTimerInterface.get()); + if (statsRPC.isActive()) statsRPC.load(); return true; } @@ -298,4 +303,8 @@ void StopHTTPRPC() RPCUnsetTimerInterface(httpRPCTimerInterface.get()); httpRPCTimerInterface.reset(); } + + if (statsRPC.isActive()) statsRPC.save(); } + +CRPCStats statsRPC; diff --git a/src/init.cpp b/src/init.cpp index 2f775dc02d..102c84818b 100644 --- a/src/init.cpp +++ b/src/init.cpp @@ -40,6 +40,7 @@ #include #include #include +#include #include #include #include @@ -591,6 +592,7 @@ void SetupServerArgs() gArgs.AddArg("-rpcworkqueue=", strprintf("Set the depth of the work queue to service RPC calls (default: %d)", DEFAULT_HTTP_WORKQUEUE), ArgsManager::ALLOW_ANY | ArgsManager::DEBUG_ONLY, OptionsCategory::RPC); gArgs.AddArg("-server", "Accept command line and JSON-RPC commands", ArgsManager::ALLOW_ANY, OptionsCategory::RPC); gArgs.AddArg("-rpcallowcors=", "Allow CORS requests from the given host origin. Include scheme and port (eg: -rpcallowcors=http://127.0.0.1:5000)", ArgsManager::ALLOW_ANY, OptionsCategory::RPC); + gArgs.AddArg("-rpcstats", strprintf("Log RPC stats. (default: %u)", DEFAULT_RPC_STATS), ArgsManager::ALLOW_ANY, OptionsCategory::RPC); #if HAVE_DECL_DAEMON gArgs.AddArg("-daemon", "Run in the background as a daemon and accept commands", ArgsManager::ALLOW_ANY, OptionsCategory::OPTIONS); @@ -2066,5 +2068,7 @@ bool AppInitMain(InitInterfaces& interfaces) )); } + if (!gArgs.GetBoolArg("-rpcstats", DEFAULT_RPC_STATS)) statsRPC.setActive(false); + return true; } diff --git a/src/rpc/register.h b/src/rpc/register.h index cbccea1ea7..ffa74bb1a5 100644 --- a/src/rpc/register.h +++ b/src/rpc/register.h @@ -13,6 +13,8 @@ class CRPCTable; void RegisterBlockchainRPCCommands(CRPCTable &tableRPC); /** Register P2P networking RPC commands */ void RegisterNetRPCCommands(CRPCTable &tableRPC); +/** Register stats RPC commands */ +void RegisterStatsRPCCommands(CRPCTable &tableRPC); /** Register miscellaneous RPC commands */ void RegisterMiscRPCCommands(CRPCTable &tableRPC); /** Register mining RPC commands */ @@ -45,6 +47,7 @@ static inline void RegisterAllCoreRPCCommands(CRPCTable &t) { RegisterBlockchainRPCCommands(t); RegisterNetRPCCommands(t); + RegisterStatsRPCCommands(t); RegisterMiscRPCCommands(t); RegisterMiningRPCCommands(t); RegisterRawTransactionRPCCommands(t); diff --git a/src/rpc/stats.cpp b/src/rpc/stats.cpp new file mode 100644 index 0000000000..9cf237264f --- /dev/null +++ b/src/rpc/stats.cpp @@ -0,0 +1,203 @@ +#include + +#include +#include + +UniValue RPCStats::toJSON() { + UniValue stats(UniValue::VOBJ), + latencyObj(UniValue::VOBJ), + payloadObj(UniValue::VOBJ), + historyArr(UniValue::VARR); + + latencyObj.pushKV("min", latency.min); + latencyObj.pushKV("avg", latency.avg); + latencyObj.pushKV("max", latency.max); + + payloadObj.pushKV("min", payload.min); + payloadObj.pushKV("avg", payload.avg); + payloadObj.pushKV("max", payload.max); + + for (auto const &entry : history) { + UniValue historyObj(UniValue::VOBJ); + historyObj.pushKV("timestamp", entry.timestamp); + historyObj.pushKV("latency", entry.latency); + historyObj.pushKV("payload", entry.payload); + historyArr.push_back(historyObj); + } + + stats.pushKV("name", name); + stats.pushKV("count", count); + stats.pushKV("lastUsedTime", lastUsedTime); + stats.pushKV("latency", latencyObj); + stats.pushKV("payload", payloadObj); + stats.pushKV("history", historyArr); + return stats; +} + +RPCStats RPCStats::fromJSON(UniValue json) { + RPCStats stats; + + stats.name = json["name"].get_str(); + stats.lastUsedTime = json["lastUsedTime"].get_int64(); + stats.count = json["count"].get_int64(); + if (!json["latency"].isNull()) { + auto latencyObj = json["latency"].get_obj(); + stats.latency = { + latencyObj["min"].get_int64(), + latencyObj["avg"].get_int64(), + latencyObj["max"].get_int64() + }; + } + + if (!json["payload"].isNull()) { + auto payloadObj = json["payload"].get_obj(); + stats.payload = { + payloadObj["min"].get_int64(), + payloadObj["avg"].get_int64(), + payloadObj["max"].get_int64() + }; + } + + if (!json["history"].isNull()) { + auto historyArr = json["history"].get_array(); + for (const auto &entry : historyArr.getValues()) { + auto historyObj = entry.get_obj(); + StatHistoryEntry historyEntry { + historyObj["timestamp"].get_int64(), + historyObj["latency"].get_int64(), + historyObj["payload"].get_int64() + }; + stats.history.push_back(historyEntry); + } + } + return stats; +} + +void CRPCStats::add(const std::string& name, const int64_t latency, const int64_t payload) +{ + auto stats = CRPCStats::get(name); + if (stats) { + stats->count++; + stats->lastUsedTime = GetSystemTimeInSeconds(); + stats->latency = { + std::min(latency, stats->latency.min), + stats->latency.avg + (latency - stats->latency.avg) / stats->count, + std::max(latency, stats->latency.max) + }; + stats->payload = { + std::min(payload, stats->payload.min), + stats->payload.avg + (payload - stats->payload.avg) / stats->count, + std::max(payload, stats->payload.max) + }; + } else { + stats = { name, latency, payload }; + } + stats->history.push_back({ stats->lastUsedTime, latency, payload }); + + CLockFreeGuard lock(lock_stats); + map[name] = *stats; +} + +UniValue CRPCStats::toJSON() { + auto map = CRPCStats::getMap(); + + UniValue ret(UniValue::VARR); + for (auto &[_, stats] : map) { + ret.push_back(stats.toJSON()); + } + return ret; +} + +static UniValue getrpcstats(const JSONRPCRequest& request) +{ + RPCHelpMan{"getrpcstats", + "\nGet RPC stats for selected command.\n", + { + {"command", RPCArg::Type::STR, RPCArg::Optional::NO, "The command to get stats for."} + }, + RPCResult{ + " {\n" + " \"name\": (string) The RPC command name.\n" + " \"latency\": (json object) Min, max and average latency.\n" + " \"payload\": (json object) Min, max and average payload size in bytes.\n" + " \"count\": (numeric) The number of times this command as been used.\n" + " \"lastUsedTime\": (numeric) Last used time as timestamp.\n" + " \"history\": (json array) History of last 5 RPC calls.\n" + " [\n" + " {\n" + " \"timestamp\": (numeric)\n" + " \"latency\": (numeric)\n" + " \"payload\": (numeric)\n" + " }\n" + " ]\n" + "}" + }, + RPCExamples{ + HelpExampleCli("getrpcstats", "getblockcount") + + HelpExampleRpc("getrpcstats", "\"getblockcount\"") + }, + }.Check(request); + + if (!statsRPC.isActive()) { + throw JSONRPCError(RPC_INVALID_REQUEST, "Rpcstats is desactivated."); + } + + auto command = request.params[0].get_str(); + auto stats = statsRPC.get(command); + if (!stats) { + throw JSONRPCError(RPC_INVALID_PARAMS, "No stats for this command."); + } + return stats->toJSON(); +} + +static UniValue listrpcstats(const JSONRPCRequest& request) +{ + RPCHelpMan{"listrpcstats", + "\nList used RPC commands.\n", + {}, + RPCResult{ + "[\n" + " {\n" + " \"name\": (string) The RPC command name.\n" + " \"latency\": (json object) Min, max and average latency.\n" + " \"payload\": (json object) Min, max and average payload size in bytes.\n" + " \"count\": (numeric) The number of times this command as been used.\n" + " \"lastUsedTime\": (numeric) Last used time as timestamp.\n" + " \"history\": (json array) History of last 5 RPC calls.\n" + " [\n" + " {\n" + " \"timestamp\": (numeric)\n" + " \"latency\": (numeric)\n" + " \"payload\": (numeric)\n" + " }\n" + " ]\n" + " }\n" + "]" + }, + RPCExamples{ + HelpExampleCli("listrpcstats", "") + + HelpExampleRpc("listrpcstats", "") + }, + }.Check(request); + + if (!statsRPC.isActive()) { + throw JSONRPCError(RPC_INVALID_REQUEST, "Rpcstats is desactivated."); + } + + return statsRPC.toJSON(); +} + +// clang-format off +static const CRPCCommand commands[] = +{ // category name actor (function) argNames + // --------------------- ------------------------ ----------------------- ---------- + { "stats", "getrpcstats", &getrpcstats, {"command"} }, + { "stats", "listrpcstats", &listrpcstats, {} }, +}; +// clang-format on + +void RegisterStatsRPCCommands(CRPCTable &t) +{ + for (unsigned int vcidx = 0; vcidx < ARRAYLEN(commands); vcidx++) + t.appendCommand(commands[vcidx].name, &commands[vcidx]); +} diff --git a/src/rpc/stats.h b/src/rpc/stats.h new file mode 100644 index 0000000000..1ad3a9693a --- /dev/null +++ b/src/rpc/stats.h @@ -0,0 +1,118 @@ +#ifndef DEFI_RPC_STATS_H +#define DEFI_RPC_STATS_H + +#include +#include +#include +#include +#include + +#include + +const char * const DEFAULT_STATSFILE = "stats.log"; +static const uint8_t RPC_STATS_HISTORY_SIZE = 5; +const bool DEFAULT_RPC_STATS = true; + +struct MinMaxStatEntry { + int64_t min; + int64_t avg; + int64_t max; + + MinMaxStatEntry() = default; + MinMaxStatEntry(int64_t val) : MinMaxStatEntry(val, val, val) {}; + MinMaxStatEntry(int64_t min, int64_t avg, int64_t max) : min(min), avg(avg), max(max) {}; +}; + +struct StatHistoryEntry { + int64_t timestamp; + int64_t latency; + int64_t payload; +}; + +struct RPCStats { + std::string name; + int64_t lastUsedTime; + MinMaxStatEntry latency; + MinMaxStatEntry payload; + int64_t count; + boost::circular_buffer history; + + RPCStats() : history(RPC_STATS_HISTORY_SIZE) {} + + RPCStats(const std::string& name, int64_t latency, int64_t payload) : name(name), latency(latency), payload(payload), history(RPC_STATS_HISTORY_SIZE) { + lastUsedTime = GetSystemTimeInSeconds(); + count = 1; + }; + + UniValue toJSON(); + static RPCStats fromJSON(UniValue json); +}; + +/** + * DeFi Blockchain RPC Stats class. + */ +class CRPCStats +{ +private: + CLockFreeMutex lock_stats; + std::map map; + std::atomic_bool active{DEFAULT_RPC_STATS}; + +public: + bool isActive() { + return active.load(); + } + void setActive(bool isActive) { + active.store(isActive); + } + + void add(const std::string& name, const int64_t latency, const int64_t payload); + + std::optional get(const std::string& name) { + CLockFreeGuard lock(lock_stats); + + auto it = map.find(name); + if (it == map.end()) { + return {}; + } + return it->second; + }; + std::map getMap() { + CLockFreeGuard lock(lock_stats); + return map; + }; + UniValue toJSON(); + + void save() { + fs::path statsPath = GetDataDir() / DEFAULT_STATSFILE; + fsbridge::ofstream file(statsPath); + + file << toJSON().write() << '\n'; + file.close(); + }; + + void load() { + fs::path statsPath = GetDataDir() / DEFAULT_STATSFILE; + fsbridge::ifstream file(statsPath); + if (!file.is_open()) return; + + std::string line; + file >> line; + + if (!line.size()) return; + + UniValue arr(UniValue::VARR); + arr.read((const std::string)line); + + CLockFreeGuard lock(lock_stats); + for (const auto &val : arr.getValues()) { + auto name = val["name"].get_str(); + map[name] = RPCStats::fromJSON(val); + } + file.close(); + }; +}; + +extern CRPCStats statsRPC; + +#endif // DEFI_RPC_STATS_H diff --git a/test/functional/feature_rpcstats.py b/test/functional/feature_rpcstats.py new file mode 100644 index 0000000000..5a7acb6efa --- /dev/null +++ b/test/functional/feature_rpcstats.py @@ -0,0 +1,73 @@ +#!/usr/bin/env python3 +# Copyright (c) 2014-2019 The Bitcoin Core developers +# Copyright (c) DeFi Blockchain Developers +# Distributed under the MIT software license, see the accompanying +# file LICENSE or http://www.opensource.org/licenses/mit-license.php. +"""Test RPC stats.""" + +import time + +from test_framework.test_framework import DefiTestFramework +from test_framework.util import ( + assert_equal, +) +from test_framework.authproxy import JSONRPCException + +class RPCstats(DefiTestFramework): + def set_test_params(self): + self.num_nodes = 2 + self.setup_clean_chain = True + self.extra_args = [ + ['-acindex=1', '-txnotokens=0', '-amkheight=50', '-bayfrontheight=50', '-bayfrontgardensheight=50'], + ['-acindex=1', '-txnotokens=0', '-amkheight=50', '-bayfrontheight=50', '-bayfrontgardensheight=50', '-rpcstats=0'], + ] + + def run_test(self): + self.nodes[0].generate(101) + + self.nodes[0].getnewaddress("", "legacy") + self.nodes[0].getnewaddress("", "legacy") + + self.nodes[0].listunspent() + time.sleep(1) # sleep to get different timestamp + self.nodes[0].listunspent() + + listrpcstats = self.nodes[0].listrpcstats() + assert(any(elem for elem in listrpcstats if elem["name"] == "getnewaddress")) + assert(any(elem for elem in listrpcstats if elem["name"] == "listunspent")) + + getrpcstats = self.nodes[0].getrpcstats("listunspent") + assert_equal(getrpcstats["name"], "listunspent") + assert_equal(getrpcstats["count"], 2) + + # test history's circular buffer of 5 elements + [historyEntry1, historyEntry2] = getrpcstats["history"] + for _ in range(0, 4): + time.sleep(1) + self.nodes[0].listunspent() + + getrpcstats = self.nodes[0].getrpcstats("listunspent") + assert_equal(getrpcstats["count"], 6) + assert(historyEntry1 not in getrpcstats["history"]) + assert_equal(getrpcstats["history"][0], historyEntry2) + + try: + self.nodes[0].getrpcstats("WRONGCMD") + except JSONRPCException as e: + errorString = e.error['message'] + assert("No stats for this command." in errorString) + + try: + self.nodes[1].getrpcstats("listunspent") + except JSONRPCException as e: + errorString = e.error['message'] + assert("Rpcstats is desactivated." in errorString) + + try: + self.nodes[1].listrpcstats() + except JSONRPCException as e: + errorString = e.error['message'] + assert("Rpcstats is desactivated." in errorString) + +if __name__ == '__main__': + RPCstats().main () diff --git a/test/functional/rpc_help.py b/test/functional/rpc_help.py index 3e47dd1c22..ab149be1fa 100755 --- a/test/functional/rpc_help.py +++ b/test/functional/rpc_help.py @@ -33,7 +33,7 @@ def test_categories(self): # command titles titles = [line[3:-3] for line in node.help().splitlines() if line.startswith('==')] - components = ['Accounts', 'Blockchain', 'Control', 'Generating', 'Icxorderbook', 'Loan', 'Masternodes', 'Mining', 'Network', 'Oracles', 'Poolpair', 'Rawtransactions', 'Spv', 'Tokens', 'Util', 'Vault'] + components = ['Accounts', 'Blockchain', 'Control', 'Generating', 'Icxorderbook', 'Loan', 'Masternodes', 'Mining', 'Network', 'Oracles', 'Poolpair', 'Rawtransactions', 'Spv', 'Stats', 'Tokens', 'Util', 'Vault'] if self.is_wallet_compiled(): components.append('Wallet') diff --git a/test/functional/test_runner.py b/test/functional/test_runner.py index 2114591eed..1ce58f730c 100755 --- a/test/functional/test_runner.py +++ b/test/functional/test_runner.py @@ -125,6 +125,7 @@ 'feature_communitybalance_reorg.py', 'feature_auth_return_change.py', 'feature_setgov.py', + 'feature_rpcstats.py', 'feature_futures.py', 'interface_zmq.py', 'feature_restore_utxo.py', diff --git a/test/lint/check-rpc-mappings.py b/test/lint/check-rpc-mappings.py index bb4e021eca..ec672aafac 100755 --- a/test/lint/check-rpc-mappings.py +++ b/test/lint/check-rpc-mappings.py @@ -16,6 +16,7 @@ "src/rpc/mining.cpp", "src/rpc/misc.cpp", "src/rpc/net.cpp", + "src/rpc/stats.cpp", "src/rpc/rawtransaction.cpp", "src/wallet/rpcwallet.cpp", "src/masternodes/mn_rpc.cpp", diff --git a/test/lint/lint-includes.sh b/test/lint/lint-includes.sh index eafb9a72f2..cb30aed1c8 100755 --- a/test/lint/lint-includes.sh +++ b/test/lint/lint-includes.sh @@ -86,6 +86,7 @@ EXPECTED_BOOST_INCLUDES=( boost/variant/apply_visitor.hpp boost/variant/static_visitor.hpp boost/multiprecision/cpp_int.hpp + boost/circular_buffer.hpp ) for BOOST_INCLUDE in $(git grep '^#include ' | sort -u); do From 9c975650140e9515187e96b18da8e795cd2cb00f Mon Sep 17 00:00:00 2001 From: jouzo Date: Sun, 22 May 2022 15:26:08 +0100 Subject: [PATCH 2/2] Use atomic_bool for CLockFreeGuard --- src/rpc/stats.h | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/rpc/stats.h b/src/rpc/stats.h index 1ad3a9693a..0a5afecc2c 100644 --- a/src/rpc/stats.h +++ b/src/rpc/stats.h @@ -54,7 +54,7 @@ struct RPCStats { class CRPCStats { private: - CLockFreeMutex lock_stats; + std::atomic_bool lock_stats{false}; std::map map; std::atomic_bool active{DEFAULT_RPC_STATS};