Mercurial > dovecot > core-2.2

changeset 22651:61402b07ad0a

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
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.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Sun, 05 Nov 2017 22:38:27 +0200
parents e010a312c871
children 09523ad05bef
files src/director/director-connection.c
diffstat 1 files changed, 21 insertions(+), 0 deletions(-) [+]
line wrap: on
line diff
--- a/src/director/director-connection.c	Sun Nov 05 22:37:27 2017 +0200
+++ b/src/director/director-connection.c	Sun Nov 05 22:38:27 2017 +0200
@@ -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 *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 @@
 	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 @@
 	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 @@
 	}
 	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_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 *