From 656d6863b47e1791a310397d88e25fa897e05012 Mon Sep 17 00:00:00 2001
From: "Steinar H. Gunderson" <sgunderson@bigfoot.com>
Date: Tue, 9 Apr 2013 22:29:25 +0200
Subject: [PATCH] Measure how long the serialize/exec/deserialize process
 takes.

---
 main.cpp    | 24 ++++++++++++++++++++++++
 state.proto |  2 ++
 2 files changed, 26 insertions(+)

diff --git a/main.cpp b/main.cpp
index 3bf660a..2af1996 100644
--- a/main.cpp
+++ b/main.cpp
@@ -8,6 +8,7 @@
 #include <sys/types.h>
 #include <sys/ioctl.h>
 #include <sys/poll.h>
+#include <sys/time.h>
 #include <signal.h>
 #include <errno.h>
 #include <ctype.h>
@@ -261,6 +262,9 @@ int main(int argc, char **argv)
 {
 	fprintf(stderr, "\nCubemap starting.\n");
 
+	struct timeval serialize_start;
+	bool is_reexec = false;
+
 	string config_filename = (argc == 1) ? "cubemap.config" : argv[1];
 	vector<ConfigLine> config = parse_config(config_filename);
 
@@ -273,10 +277,15 @@ int main(int argc, char **argv)
 	set<string> deserialized_stream_ids;
 	map<string, Input *> deserialized_inputs;
 	if (argc == 4 && strcmp(argv[2], "-state") == 0) {
+		is_reexec = true;
+
 		fprintf(stderr, "Deserializing state from previous process... ");
 		int state_fd = atoi(argv[3]);
 		CubemapStateProto loaded_state = read_tempfile(state_fd);
 
+		serialize_start.tv_sec = loaded_state.serialize_start_sec();
+		serialize_start.tv_usec = loaded_state.serialize_start_usec();
+
 		// Deserialize the streams.
 		for (int i = 0; i < loaded_state.streams_size(); ++i) {
 			servers->add_stream_from_serialized(loaded_state.streams(i));
@@ -404,12 +413,25 @@ int main(int argc, char **argv)
 	}
 
 	signal(SIGHUP, hup);
+	
+	struct timeval server_start;
+	gettimeofday(&server_start, NULL);
+	if (is_reexec) {
+		// Measure time from we started deserializing (below) to now, when basically everything
+		// is up and running. This is, in other words, a conservative estimate of how long our
+		// “glitch” period was, not counting of course reconnects if the configuration changed.
+		double glitch_time = server_start.tv_sec - serialize_start.tv_sec +
+			1e-6 * (server_start.tv_usec - serialize_start.tv_usec);
+		fprintf(stderr, "Re-exec happened in approx. %.0f ms.\n", glitch_time * 1000.0);
+	}
 
 	while (!hupped) {
 		usleep(100000);
 	}
 
 	// OK, we've been HUPed. Time to shut down everything, serialize, and re-exec.
+	gettimeofday(&serialize_start, NULL);
+
 	if (!stats_file.empty()) {
 		if (pthread_join(stats_thread, NULL) == -1) {
 			perror("pthread_join");
@@ -422,6 +444,8 @@ int main(int argc, char **argv)
 	}
 
 	CubemapStateProto state;
+	state.set_serialize_start_sec(serialize_start.tv_sec);
+	state.set_serialize_start_usec(serialize_start.tv_usec);
 	state.set_server_sock(server_sock);
 	state.set_port(port);
 
diff --git a/state.proto b/state.proto
index 663e9d0..1d5cf17 100644
--- a/state.proto
+++ b/state.proto
@@ -34,6 +34,8 @@ message InputProto {
 };
 
 message CubemapStateProto {
+	optional int64 serialize_start_sec = 6;
+	optional int64 serialize_start_usec = 7;
 	repeated ClientProto clients = 1;
 	repeated StreamProto streams = 2;
 	repeated InputProto inputs = 5;
-- 
2.39.2