dovecot-2.2: imap: Improved command timing information reporting.

[dovecot at dovecot.org]

details:   http://hg.dovecot.org/dovecot-2.2/rev/127c88e75185
changeset: 19161:127c88e75185
user:      Timo Sirainen <tss at iki.fi>
date:      Mon Sep 21 14:02:47 2015 +0300
description:
imap: Improved command timing information reporting.
We now report also the time we spent waiting on ioloop. Also fixed reporting
command timing information when multiple commands were running in parallel
(e.g. SEARCH + FETCH). If multiple commands are running in parallel they all
report the same ioloop wait time, because there's no easy way to know which
one of them caused the wait.

diffstat:

 src/imap/imap-client.c   |  38 +++++++++++++++++++++++++-------------
 src/imap/imap-client.h   |   9 ++++-----
 src/imap/imap-commands.c |  16 +++++++---------
 3 files changed, 36 insertions(+), 27 deletions(-)

diffs (119 lines):

diff -r 1076679adf9f -r 127c88e75185 src/imap/imap-client.c
--- a/src/imap/imap-client.c	Mon Sep 21 13:59:41 2015 +0300
+++ b/src/imap/imap-client.c	Mon Sep 21 14:02:47 2015 +0300
@@ -396,11 +396,32 @@
 	return 1;
 }
 
+static void
+client_cmd_append_timing_stats(struct client_command_context *cmd,
+			       string_t *str)
+{
+	unsigned int msecs_in_cmd, msecs_in_ioloop;
+	uint64_t ioloop_wait_usecs;
+
+	if (cmd->start_time.tv_sec == 0)
+		return;
+
+	ioloop_wait_usecs = io_loop_get_wait_usecs(current_ioloop);
+	msecs_in_cmd = (cmd->running_usecs + 999) / 1000;
+	msecs_in_ioloop = (ioloop_wait_usecs -
+			   cmd->start_ioloop_wait_usecs + 999) / 1000;
+
+	if (str_data(str)[str_len(str)-1] == '.')
+		str_truncate(str, str_len(str)-1);
+	str_printfa(str, " (%d.%03d + %d.%03d secs).",
+		    msecs_in_cmd / 1000, msecs_in_cmd % 1000,
+		    msecs_in_ioloop / 1000, msecs_in_ioloop % 1000);
+}
+
 void client_send_tagline(struct client_command_context *cmd, const char *data)
 {
 	struct client *client = cmd->client;
 	const char *tag = cmd->tag;
-	int time_msecs;
 
 	if (client->output->closed || cmd->cancel)
 		return;
@@ -414,18 +435,7 @@
 	T_BEGIN {
 		string_t *str = t_str_new(256);
 		str_printfa(str, "%s %s", tag, data);
-		if (cmd->start_time.tv_sec != 0) {
-			if (str_data(str)[str_len(str)-1] == '.')
-				str_truncate(str, str_len(str)-1);
-			io_loop_time_refresh();
-			time_msecs = timeval_diff_msecs(&ioloop_timeval,
-							&cmd->start_time);
-			time_msecs -= cmd->usecs_in_ioloop/1000;
-			if (time_msecs >= 0) {
-				str_printfa(str, " (%d.%03d secs).",
-					    time_msecs/1000, time_msecs%1000);
-			}
-		}
+		client_cmd_append_timing_stats(cmd, str);
 		str_append(str, "\r\n");
 		o_stream_nsend(client->output, str_data(str), str_len(str));
 	} T_END;
@@ -496,6 +506,8 @@
 		imap_write_args(str, *args_r);
 		cmd->args = p_strdup(cmd->pool, str_c(str));
 		cmd->start_time = ioloop_timeval;
+		cmd->start_ioloop_wait_usecs =
+			io_loop_get_wait_usecs(current_ioloop);
 
 		cmd->client->input_lock = NULL;
 		return TRUE;
diff -r 1076679adf9f -r 127c88e75185 src/imap/imap-client.h
--- a/src/imap/imap-client.h	Mon Sep 21 13:59:41 2015 +0300
+++ b/src/imap/imap-client.h	Mon Sep 21 14:02:47 2015 +0300
@@ -77,11 +77,10 @@
 	/* time when command handling was started - typically this is after
 	   reading all the parameters. */
 	struct timeval start_time;
-	/* time when an unfinished command handling entered back to ioloop.
-	   used for calculating usecs_in_ioloop */
-	struct timeval last_ioloop_time;
-	/* how much time was spent waiting for the client in ioloop */
-	uint64_t usecs_in_ioloop;
+	/* io_loop_get_wait_usecs()'s value when the command was started */
+	uint64_t start_ioloop_wait_usecs;
+	/* how many usecs this command itself has spent running */
+	uint64_t running_usecs;
 
 	struct client_sync_context *sync;
 
diff -r 1076679adf9f -r 127c88e75185 src/imap/imap-commands.c
--- a/src/imap/imap-commands.c	Mon Sep 21 13:59:41 2015 +0300
+++ b/src/imap/imap-commands.c	Mon Sep 21 14:02:47 2015 +0300
@@ -156,12 +156,10 @@
 	const struct command_hook *hook;
 	long long diff;
 	bool finished;
+	struct timeval cmd_start_timeval;
 
-	if (cmd->last_ioloop_time.tv_sec != 0) {
-		diff = timeval_diff_usecs(&ioloop_timeval, &cmd->last_ioloop_time);
-		if (diff > 0)
-			cmd->usecs_in_ioloop += diff;
-	}
+	io_loop_time_refresh();
+	cmd_start_timeval = ioloop_timeval;
 
 	array_foreach(&command_hooks, hook)
 		hook->pre(cmd);
@@ -170,10 +168,10 @@
 		hook->post(cmd);
 	if (cmd->state == CLIENT_COMMAND_STATE_DONE)
 		finished = TRUE;
-	if (!finished) {
-		io_loop_time_refresh();
-		cmd->last_ioloop_time = ioloop_timeval;
-	}
+
+	io_loop_time_refresh();
+	cmd->running_usecs +=
+		timeval_diff_usecs(&ioloop_timeval, &cmd_start_timeval);
 	return finished;
 }