added server profiling information for requests

src/server/metrics.cpp

@@ -19,9 +19,27 @@
 
 #include "metrics.hpp"
 
+#include <algorithm>
 #include <time.h>
 #include <iostream>
 
+bool operator<(const metrics::sample& s, const simple_wml::string_span& name)
+{
+	return s.name < name;
+}
+
+bool operator<(const simple_wml::string_span& name, const metrics::sample& s)
+{
+	return name < s.name;
+}
+
+struct compare_samples_by_time {
+	bool operator()(const metrics::sample& a, const metrics::sample& b) const {
+		return a.processing_time < b.processing_time;
+	}
+};
+
+
 metrics::metrics() : most_consecutive_requests_(0),
                      current_requests_(0), nrequests_(0),
                      nrequests_waited_(0), started_at_(time(NULL))
@@ -45,6 +63,33 @@ void metrics::no_requests()
 	current_requests_ = 0;
 }
 
+void metrics::record_sample(const simple_wml::string_span& name,
+                            clock_t parsing_time, clock_t processing_time)
+{
+	std::pair<std::vector<sample>::iterator,std::vector<sample>::iterator>
+	    range = std::equal_range(samples_.begin(), samples_.end(), name);
+	if(range.first == range.second) {
+		//protect against DoS with memory exhaustion
+		if(samples_.size() > 30) {
+			return;
+		}
+		int index = range.first - samples_.begin();
+		simple_wml::string_span dup_name(name.duplicate());
+		sample new_sample;
+		new_sample.name = dup_name;
+		new_sample.nsamples = 0;
+		new_sample.parsing_time = 0;
+		new_sample.processing_time = 0;
+		samples_.insert(range.first, new_sample);
+
+		range.first = samples_.begin() + index;
+	}
+
+	range.first->nsamples++;
+	range.first->parsing_time += parsing_time;
+	range.first->processing_time += processing_time;
+}
+
 void metrics::game_terminated(const std::string& reason)
 {
 	terminations_[reason]++;
@@ -73,5 +118,14 @@ std::ostream& operator<<(std::ostream& out, metrics& met)
 		}
 	}
 
+	std::vector<metrics::sample> ordered_samples = met.samples_;
+	std::sort(ordered_samples.begin(), ordered_samples.end(), compare_samples_by_time());
+
+	out << "\n\nRequest types:\n";
+
+	for(std::vector<metrics::sample>::const_iterator s = ordered_samples.begin(); s != ordered_samples.end(); ++s) {
+		out << "'" << s->name << "' called " << s->nsamples << " times " << s->parsing_time << " parsing time, " << s->processing_time << " processing time\n";
+	}
+
 	return out;
 }

src/server/metrics.hpp

@@ -23,6 +23,8 @@
 #include <map>
 #include <string>
 
+#include "simple_wml.hpp"
+
 class metrics
 {
 public:
@@ -31,11 +33,22 @@ public:
 	void service_request();
 	void no_requests();
 
+	void record_sample(const simple_wml::string_span& name,
+	                   clock_t parsing_time, clock_t processing_time);
+
 	void game_terminated(const std::string& reason);
 
 	friend std::ostream& operator<<(std::ostream& out, metrics& met);
 
+	struct sample {
+		simple_wml::string_span name;
+		int nsamples;
+		clock_t parsing_time, processing_time;
+	};
+
 private:
+	std::vector<sample> samples_;
+
 	int most_consecutive_requests_;
 	int current_requests_;
 	int nrequests_;

src/server/server.cpp

@@ -44,6 +44,8 @@
 #include <sstream>
 #include <vector>
 
+#include <sys/times.h>
+
 #include <csignal>
 
 //! fatal and directly server related errors/warnings,
@@ -78,6 +80,9 @@ void exit_sigint(int signal) {
 
 namespace {
 
+// we take profiling info on every n requests
+int request_sample_frequency = 1;
+
 void send_doc(simple_wml::document& doc, network::connection connection)
 {
 	simple_wml::string_span s = doc.output_compressed();
@@ -453,6 +458,8 @@ void server::run() {
 				}
 			}
 
+			static int sample_counter = 0;
+
 			std::vector<char> buf;
 			while ((sock = network::receive_data(buf)) != network::null_connection) {
 				metrics_.service_request();
@@ -474,12 +481,32 @@ void server::run() {
 					continue;
 				}
 
+				const bool sample = (sample_counter++ % request_sample_frequency) == 0;
+
+				struct tms before_parsing, after_parsing, after_processing;
+
+				if(sample) {
+					times(&before_parsing);
+				}
+
 				char* buf_ptr = new char [buf.size()];
 				memcpy(buf_ptr, &buf[0], buf.size());
 				simple_wml::string_span compressed_buf(buf_ptr, buf.size());
 				simple_wml::document data(compressed_buf);
 				std::vector<char>().swap(buf);
+
+				if(sample) {
+					times(&after_parsing);
+				}
+
 				process_data(sock, data);
+
+				if(sample) {
+					times(&after_processing);
+					metrics_.record_sample(data.root().first_child(),
+					          after_parsing.tms_utime - before_parsing.tms_utime,
+					          after_processing.tms_utime - after_parsing.tms_utime);
+				}
 			}
 
 			metrics_.no_requests();
@@ -1586,6 +1613,8 @@ int main(int argc, char** argv) {
 			}
 		} else if ((val == "--max-threads" || val == "-T") && arg+1 != argc) {
 			max_threads = atoi(argv[++arg]);
+		} else if(val == "--request_sample_frequency" && arg+1 != argc) {
+			request_sample_frequency = atoi(argv[++arg]);
 		} else if (val[0] == '-') {
 			ERR_SERVER << "unknown option: " << val << "\n";
 			return 0;

src/server/simple_wml.cpp

@@ -397,6 +397,16 @@ const node::child_list& node::children(const char* name) const
 	return itor->second;
 }
 
+const string_span& node::first_child() const
+{
+	if(children_.empty()) {
+		static const string_span empty;
+		return empty;
+	}
+
+	return children_.begin()->first;
+}
+
 int node::output_size() const
 {
 /*

src/server/simple_wml.hpp

@@ -121,6 +121,8 @@ public:
 
 	const child_list& children(const char* name) const;
 
+	const string_span& first_child() const;
+
 	bool is_dirty() const { return output_cache_.is_null(); }
 
 	int output_size() const;