Merge pull request #1228 from GolosChain/1222-view-slow-api-requests

Add setting to view slow API requests #1222

Author: afalaleev

plugins/json_rpc/include/golos/plugins/json_rpc/plugin.hpp

@@ -96,8 +96,7 @@ namespace golos {
                 APPBASE_PLUGIN_REQUIRES();
 
                 void set_program_options(boost::program_options::options_description &,
-                                         boost::program_options::options_description &) override {
-                }
+                                         boost::program_options::options_description &);
 
                 static const std::string &name() {
                     static std::string name = STEEM_JSON_RPC_PLUGIN_NAME;

plugins/json_rpc/plugin.cpp

@@ -13,6 +13,9 @@
 namespace golos {
     namespace plugins {
         namespace json_rpc {
+
+            namespace bpo = boost::program_options;
+
             struct json_rpc_error {
                 json_rpc_error() : code(0) {
                 }
@@ -273,24 +276,41 @@ namespace golos {
                 }
 
                 struct dump_rpc_time {
-                    dump_rpc_time(const fc::variant& data)
-                        : data_(data) {
+                    dump_rpc_time(const fc::variant& data, uint64_t log_rpc_calls_slower_msec)
+                        : data_(data), log_rpc_calls_slower_msec_(log_rpc_calls_slower_msec) {
 
                         dlog("data: ${data}", ("data", fc::json::to_string(data_)));
                     }
 
                     ~dump_rpc_time() {
+                        auto msecs = (fc::time_point::now() - start_).count() / 1000;
+
                         if (error_.empty()) {
                             dlog(
-                                "elapsed: ${time} sec, data: ${data}",
+                                "elapsed: ${time} msec, data: ${data}",
                                 ("data", fc::json::to_string(data_))
-                                ("time", double((fc::time_point::now() - start_).count()) / 1000000.0));
+                                ("time", msecs));
                         } else {
                             dlog(
-                                "elapsed: ${time} sec, error: '${error}', data: ${data}",
+                                "elapsed: ${time} msec, error: '${error}', data: ${data}",
                                 ("data", fc::json::to_string(data_))
                                 ("error", error_)
-                                ("time", double((fc::time_point::now() - start_).count()) / 1000000.0));
+                                ("time", msecs));
+                        }
+
+                        if (uint64_t(msecs) > log_rpc_calls_slower_msec_) {
+                            if (error_.empty()) {
+                                wlog(
+                                    "Too slow RPC call: ${time} msec, data: ${data}",
+                                    ("data", fc::json::to_string(data_))
+                                    ("time", msecs));
+                            } else {
+                                wlog(
+                                    "Too slow RPC call: ${time} msec, error: '${error}', data: ${data}",
+                                    ("data", fc::json::to_string(data_))
+                                    ("error", error_)
+                                    ("time", msecs));
+                            }
                         }
                     }
 
@@ -302,10 +322,11 @@ namespace golos {
                     fc::time_point start_ = fc::time_point::now();
                     std::string error_;
                     const fc::variant& data_;
+                    uint64_t log_rpc_calls_slower_msec_;
                 };
 
                 void rpc(const fc::variant& data, msg_pack& msg) {
-                    dump_rpc_time dump(data);
+                    dump_rpc_time dump(data, _log_rpc_calls_slower_msec);
 
                     try {
                         rpc_jsonrpc(data, msg);
@@ -406,6 +427,7 @@ namespace golos {
                 map<string, api_description> _registered_apis;
                 vector<string> _methods;
                 map<string, map<string, api_method_signature> > _method_sigs;
+                uint64_t _log_rpc_calls_slower_msec = UINT64_MAX;
             private:
                 // This is a reindex which allows to get parent plugin by method
                 // unordered_map[method] -> plugin
@@ -422,10 +444,18 @@ namespace golos {
             plugin::~plugin() {
             }
 
+            void plugin::set_program_options(bpo::options_description& cli, bpo::options_description& cfg) {
+                cfg.add_options() (
+                    "log-rpc-calls-slower-msec", bpo::value<uint64_t>()->default_value(UINT64_MAX),
+                    "Maximal milliseconds of RPC call or dump it as too slow. If not set, do not dump"
+                );
+            }
+
             void plugin::plugin_initialize(const boost::program_options::variables_map &options) {
                 ilog("json_rpc plugin: plugin_initialize() begin");
                 pimpl = std::make_unique<impl>();
                 pimpl->initialize();
+                pimpl->_log_rpc_calls_slower_msec = options.at("log-rpc-calls-slower-msec").as<uint64_t>();
                 ilog("json_rpc plugin: plugin_initialize() end");
             }
 

tests/plugin_tests/json_rpc.cpp

@@ -117,9 +117,18 @@ BOOST_FIXTURE_TEST_SUITE(json_rpc, database_fixture)
             auto &rpc_plugin  = appbase::app().register_plugin<json_rpc_plugin>();
             auto &testing_api = appbase::app().register_plugin<test_plugin::testing_api>();
 
-            boost::program_options::variables_map options;
-            rpc_plugin.plugin_initialize(options);
-            testing_api.plugin_initialize(options);
+            {
+                boost::program_options::options_description desc;
+                rpc_plugin.set_program_options(desc, desc);
+
+                boost::program_options::variables_map options;
+                boost::program_options::store(parse_command_line(0, (char**)NULL, desc), options);
+                rpc_plugin.plugin_initialize(options);
+            }
+            {
+                boost::program_options::variables_map options;
+                testing_api.plugin_initialize(options);
+            }
 
             open_database();