From: Timo Sirainen <timo.sirainen@dovecot.fi>
Date: Sun, 19 Feb 2017 13:47:48 +0000 (+0200)
Subject: imap: Fix running time in tagged command replies.
X-Git-Tag: 2.3.0.rc1~2065
X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=b98f1ffc049e8c4c1677173ea65830aa07b3ef87;p=thirdparty%2Fdovecot%2Fcore.git

imap: Fix running time in tagged command replies.

The timing information was updated only after command_exec() returned.
Most of the commands were handled within a single command_exec() though,
so at the time when tagline was sent the running_usecs was still zero.

The msecs in ioloop timing was correct though, because it relied only on
the command start timing info.
---

diff --git a/src/imap/imap-client.c b/src/imap/imap-client.c
index 516f23f560..83a2fa5ae7 100644
--- a/src/imap/imap-client.c
+++ b/src/imap/imap-client.c
@@ -542,6 +542,7 @@ client_cmd_append_timing_stats(struct client_command_context *cmd,
 
 	if (cmd->stats.start_time.tv_sec == 0)
 		return;
+	command_stats_flush(cmd);
 
 	ioloop_wait_usecs = io_loop_get_wait_usecs(current_ioloop);
 	msecs_in_cmd = (cmd->stats.running_usecs + 999) / 1000;
diff --git a/src/imap/imap-client.h b/src/imap/imap-client.h
index b363b3e589..26a91ec0c1 100644
--- a/src/imap/imap-client.h
+++ b/src/imap/imap-client.h
@@ -69,6 +69,12 @@ struct client_command_stats {
 	uint64_t bytes_in, bytes_out;
 };
 
+struct client_command_stats_start {
+	struct timeval timeval;
+	uint64_t lock_wait_usecs;
+	uint64_t bytes_in, bytes_out;
+};
+
 struct client_command_context {
 	struct client_command_context *prev, *next;
 	struct client *client;
@@ -94,6 +100,7 @@ struct client_command_context {
 	struct imap_parser *parser;
 	enum client_command_state state;
 	struct client_command_stats stats;
+	struct client_command_stats_start stats_start;
 
 	struct client_sync_context *sync;
 
diff --git a/src/imap/imap-commands.c b/src/imap/imap-commands.c
index 70df94adcb..809ad5770d 100644
--- a/src/imap/imap-commands.c
+++ b/src/imap/imap-commands.c
@@ -160,20 +160,39 @@ void command_hook_unregister(command_hook_callback_t *pre,
 	i_panic("command_hook_unregister(): hook not registered");
 }
 
+static void command_stats_start(struct client_command_context *cmd)
+{
+	cmd->stats_start.timeval = ioloop_timeval;
+	cmd->stats_start.lock_wait_usecs = file_lock_wait_get_total_usecs();
+	cmd->stats_start.bytes_in = i_stream_get_absolute_offset(cmd->client->input);
+	cmd->stats_start.bytes_out = cmd->client->output->offset;
+}
+
+void command_stats_flush(struct client_command_context *cmd)
+{
+	io_loop_time_refresh();
+	cmd->stats.running_usecs +=
+		timeval_diff_usecs(&ioloop_timeval, &cmd->stats_start.timeval);
+	cmd->stats.lock_wait_usecs +=
+		file_lock_wait_get_total_usecs() -
+		cmd->stats_start.lock_wait_usecs;
+	cmd->stats.bytes_in += i_stream_get_absolute_offset(cmd->client->input) -
+		cmd->stats_start.bytes_in;
+	cmd->stats.bytes_out += cmd->client->output->offset -
+		cmd->stats_start.bytes_out;
+	/* allow flushing multiple times */
+	command_stats_start(cmd);
+}
+
 bool command_exec(struct client_command_context *cmd)
 {
 	const struct command_hook *hook;
 	bool finished;
-	struct timeval cmd_start_timeval;
-	uint64_t cmd_start_bytes_in, cmd_start_bytes_out, cmd_start_lock_waits;
 
 	i_assert(!cmd->executing);
 
 	io_loop_time_refresh();
-	cmd_start_lock_waits = file_lock_wait_get_total_usecs();
-	cmd_start_timeval = ioloop_timeval;
-	cmd_start_bytes_in = i_stream_get_absolute_offset(cmd->client->input);
-	cmd_start_bytes_out = cmd->client->output->offset;
+	command_stats_start(cmd);
 
 	cmd->executing = TRUE;
 	array_foreach(&command_hooks, hook)
@@ -185,14 +204,7 @@ bool command_exec(struct client_command_context *cmd)
 	if (cmd->state == CLIENT_COMMAND_STATE_DONE)
 		finished = TRUE;
 
-	io_loop_time_refresh();
-	cmd->stats.running_usecs +=
-		timeval_diff_usecs(&ioloop_timeval, &cmd_start_timeval);
-	cmd->stats.lock_wait_usecs +=
-		file_lock_wait_get_total_usecs() - cmd_start_lock_waits;
-	cmd->stats.bytes_in += i_stream_get_absolute_offset(cmd->client->input) -
-		cmd_start_bytes_in;
-	cmd->stats.bytes_out += cmd->client->output->offset - cmd_start_bytes_out;
+	command_stats_flush(cmd);
 	return finished;
 }
 
diff --git a/src/imap/imap-commands.h b/src/imap/imap-commands.h
index 9a14daf072..7f2f67e6b7 100644
--- a/src/imap/imap-commands.h
+++ b/src/imap/imap-commands.h
@@ -60,6 +60,10 @@ void command_hook_unregister(command_hook_callback_t *pre,
 			     command_hook_callback_t *post);
 /* Execute command and hooks */
 bool command_exec(struct client_command_context *cmd);
+/* Finish counting command statistics. This is called automatically when
+   command_exec() returns, but it should be called explicitly if the stats are
+   needed during command_exec(). */
+void command_stats_flush(struct client_command_context *cmd);
 
 struct command *command_find(const char *name);