# HG changeset patch
# User Timo Sirainen <timo.sirainen@dovecot.fi>
# Date 1487512068 -7200
# Node ID 359be67753823df947e0b3952823d206c368f260
# Parent  e8dfebca6899faec0e1b5a08ff7832bdefba4c0f
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 -r e8dfebca6899 -r 359be6775382 src/imap/imap-client.c
--- a/src/imap/imap-client.c	Sun Feb 19 02:03:08 2017 +0200
+++ b/src/imap/imap-client.c	Sun Feb 19 15:47:48 2017 +0200
@@ -547,6 +547,7 @@
 
 	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 -r e8dfebca6899 -r 359be6775382 src/imap/imap-client.h
--- a/src/imap/imap-client.h	Sun Feb 19 02:03:08 2017 +0200
+++ b/src/imap/imap-client.h	Sun Feb 19 15:47:48 2017 +0200
@@ -69,6 +69,12 @@
 	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 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 -r e8dfebca6899 -r 359be6775382 src/imap/imap-commands.c
--- a/src/imap/imap-commands.c	Sun Feb 19 02:03:08 2017 +0200
+++ b/src/imap/imap-commands.c	Sun Feb 19 15:47:48 2017 +0200
@@ -160,20 +160,39 @@
 	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 @@
 	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 -r e8dfebca6899 -r 359be6775382 src/imap/imap-commands.h
--- a/src/imap/imap-commands.h	Sun Feb 19 02:03:08 2017 +0200
+++ b/src/imap/imap-commands.h	Sun Feb 19 15:47:48 2017 +0200
@@ -60,6 +60,10 @@
 			     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);