director: Include used CPU secs in director connection log messages

It's counting the process's full CPU seconds used since the handshake
started, so it's not specific to the connection itself. Still, this is
likely to be very useful in debugging whether a slow handshake was due
to CPU usage or something else.

diff --git a/src/director/director-connection.c b/src/director/director-connection.c
index fac54d4b092e3661ebf0de976d1d1710e0e0f25c..69839b0efd34788173d78265ac78937c6030b8cd 100644 (file)
--- a/src/director/director-connection.c
+++ b/src/director/director-connection.c
@@ -45,6 +45,8 @@
 #include "director-connection.h"
 
 #include <unistd.h>
+#include <sys/time.h>
+#include <sys/resource.h>
 
 #define MAX_INBUF_SIZE 1024
 #define OUTBUF_FLUSH_THRESHOLD (1024*128)
@@ -104,6 +106,7 @@ struct director_connection {
        struct director *dir;
        char *name;
        struct timeval created, connected_time, me_received_time;
+       struct timeval connected_user_cpu;
        unsigned int minor_version;
 
        struct timeval last_input, last_output;
@@ -141,6 +144,7 @@ struct director_connection {
        unsigned int wrong_host:1;
        unsigned int verifying_left:1;
        unsigned int users_unsorted:1;
+       unsigned int connected_user_cpu_set:1;
 };
 
 static bool director_connection_unref(struct director_connection *conn);
@@ -175,6 +179,7 @@ director_connection_append_stats(struct director_connection *conn, string_t *str
        int input_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->last_input);
        int output_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->last_output);
        int connected_msecs = timeval_diff_msecs(&ioloop_timeval, &conn->connected_time);
+       struct rusage usage;
 
        str_printfa(str, "bytes in=%"PRIuUOFF_T", bytes out=%"PRIuUOFF_T,
                    conn->input->v_offset, conn->output->offset);
@@ -196,6 +201,15 @@ director_connection_append_stats(struct director_connection *conn, string_t *str
        }
        str_printfa(str, ", %zu peak output buffer size",
                    conn->peak_bytes_buffered);
+       if (conn->connected_user_cpu_set &&
+           getrusage(RUSAGE_SELF, &usage) == 0) {
+               /* this isn't measuring the CPU usage used by the connection
+                  itself, but it can still be a useful measurement */
+               int diff = timeval_diff_msecs(&usage.ru_utime,
+                                             &conn->connected_user_cpu);
+               str_printfa(str, ", %d.%03d CPU secs since connected",
+                           diff / 1000, diff % 1000);
+       }
 }
 
 static void
@@ -2085,8 +2099,15 @@ static void director_connection_send_handshake(struct director_connection *conn)
 
 static void director_connection_set_connected(struct director_connection *conn)
 {
+       struct rusage usage;
+
        conn->connected = TRUE;
        conn->connected_time = ioloop_timeval;
+
+       if (getrusage(RUSAGE_SELF, &usage) == 0) {
+               conn->connected_user_cpu_set = TRUE;
+               conn->connected_user_cpu = usage.ru_utime;
+       }
 }
 
 struct director_connection *