Mercurial > dovecot > core-2.2

changeset 19161:127c88e75185

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
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.
author Timo Sirainen <tss@iki.fi>
date Mon, 21 Sep 2015 14:02:47 +0300
parents 1076679adf9f
children e39e5867fa7b
files src/imap/imap-client.c src/imap/imap-client.h src/imap/imap-commands.c
diffstat 3 files changed, 36 insertions(+), 27 deletions(-) [+]
line wrap: on
line diff
--- 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;
--- 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;
 
--- 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;
 }