Measure how long the serialize/exec/deserialize process takes.
authorSteinar H. Gunderson <sgunderson@bigfoot.com>
Tue, 9 Apr 2013 20:29:25 +0000 (22:29 +0200)
committerSteinar H. Gunderson <sgunderson@bigfoot.com>
Tue, 9 Apr 2013 20:29:25 +0000 (22:29 +0200)
main.cpp
state.proto

index 3bf660a..2af1996 100644 (file)
--- 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);
 
index 663e9d0..1d5cf17 100644 (file)
@@ -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;