campaignd: Add --timings option to report request servicing timings

Yes, this requires making campaignd::server::request public so I don't
lose my mind writing friend declarations.

src/server/campaignd/options.cpp

@@ -41,6 +41,7 @@ command_line::command_line(const std::vector<std::string>& 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<std::string>& args)
 		("log-debug", po::value<std::string>(), "sets the severity level of the specified log domain(s) to 'debug'.")
 		("log-none", po::value<std::string>(), "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<std::string>& args)
 	if(vm.count("log-precise")) {
 		log_precise_timestamps = true;
 	}
+	if(vm.count("timings")) {
+		report_timings = true;
+	}
 }
 
 } // end namespace campaignd

src/server/campaignd/options.hpp

@@ -62,6 +62,8 @@ public:
 	std::map<std::string, int> 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_;

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 <csignal>
 #include <ctime>
@@ -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_ptr<simple_wml::docum
 
 		if(j != handlers_.end()) {
 			// Call the handler.
-			j->second(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)) {

src/server/campaignd/server.hpp

@@ -43,7 +43,6 @@ public:
 
 	server& operator=(const config& server) = delete;
 
-private:
 	/**
 	 * Client request information object.
 	 *
@@ -84,6 +83,8 @@ private:
 
 	friend std::ostream& operator<<(std::ostream& o, const request& r);
 
+private:
+
 	typedef std::function<void (server*, const request& req)> request_handler;
 	typedef std::map<std::string, request_handler> request_handlers_table;