diff --git a/src/server/campaignd/options.cpp b/src/server/campaignd/options.cpp index dbe50a1a0bb8..a5def93470e2 100644 --- a/src/server/campaignd/options.cpp +++ b/src/server/campaignd/options.cpp @@ -41,6 +41,7 @@ command_line::command_line(const std::vector& args) , show_log_domains(false) , log_domain_levels() , log_precise_timestamps(false) + , report_timings(false) , argv0_(args.at(0)) , args_(args.begin() + 1, args.end()) , help_text_() @@ -67,6 +68,7 @@ command_line::command_line(const std::vector& args) ("log-debug", po::value(), "sets the severity level of the specified log domain(s) to 'debug'.") ("log-none", po::value(), "disables logging for the specified log domain(s).") ("log-precise", "shows the timestamps in log output with more precision.") + ("timings", "outputs timings for serviced requests to stderr.") ; po::options_description opts; @@ -122,6 +124,9 @@ command_line::command_line(const std::vector& args) if(vm.count("log-precise")) { log_precise_timestamps = true; } + if(vm.count("timings")) { + report_timings = true; + } } } // end namespace campaignd diff --git a/src/server/campaignd/options.hpp b/src/server/campaignd/options.hpp index 9887406ecc85..ba028e33380c 100644 --- a/src/server/campaignd/options.hpp +++ b/src/server/campaignd/options.hpp @@ -62,6 +62,8 @@ class command_line std::map log_domain_levels; /** Whether to use higher precision for log timestamps. */ bool log_precise_timestamps; + /** Whether to report timing information for server requests. */ + bool report_timings; private: std::string argv0_; diff --git a/src/server/campaignd/server.cpp b/src/server/campaignd/server.cpp index 359e49bed3c6..61342c1e151e 100644 --- a/src/server/campaignd/server.cpp +++ b/src/server/campaignd/server.cpp @@ -40,6 +40,7 @@ #include "server/campaignd/options.hpp" #include "game_version.hpp" #include "hash.hpp" +#include "utils/optimer.hpp" #include #include @@ -73,6 +74,24 @@ namespace campaignd { namespace { +bool timing_reports_enabled = false; + +void timing_report_function(const util::ms_optimer& tim, const campaignd::server::request& req, const std::string& label = {}) +{ + if(timing_reports_enabled) { + if(label.empty()) { + LOG_CS << req << "Time elapsed: " << tim << " ms\n"; + } else { + LOG_CS << req << "Time elapsed [" << label << "]: " << tim << " ms\n"; + } + } +} + +inline util::ms_optimer service_timer(const campaignd::server::request& req, const std::string& label = {}) +{ + return util::ms_optimer{std::bind(timing_report_function, std::placeholders::_1, req, label)}; +} + // // Auxiliary shortcut functions // @@ -449,7 +468,9 @@ void server::handle_request(socket_ptr socket, std::shared_ptrsecond(this, request(c.key, c.cfg, socket)); + request req{c.key, c.cfg, socket}; + auto st = service_timer(req); + j->second(this, req); } else { send_error("Unrecognized [" + c.key + "] request.",socket); } @@ -1728,6 +1749,10 @@ int run_campaignd(int argc, char** argv) lg::precise_timestamps(true); } + if(cmdline.report_timings) { + campaignd::timing_reports_enabled = true; + } + std::cerr << "Wesnoth campaignd v" << game_config::revision << " starting...\n"; if(server_path.empty() || !filesystem::is_directory(server_path)) { diff --git a/src/server/campaignd/server.hpp b/src/server/campaignd/server.hpp index 06e48feab9f8..e0cb45cae8b4 100644 --- a/src/server/campaignd/server.hpp +++ b/src/server/campaignd/server.hpp @@ -43,7 +43,6 @@ class server : public server_base server& operator=(const config& server) = delete; -private: /** * Client request information object. * @@ -84,6 +83,8 @@ class server : public server_base friend std::ostream& operator<<(std::ostream& o, const request& r); +private: + typedef std::function request_handler; typedef std::map request_handlers_table;