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 516f23f560c1adad75eaa1d9b7b13d15f1df9c6d..83a2fa5ae728d9870e82e46b35314e06373d217e 100644 (file)
--- 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 b363b3e5895ceb266c1076d83d7c3d5c9ffa273c..26a91ec0c1bd40dc61051c409f4d17a5b5392a74 100644 (file)
--- 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 70df94adcb60027edd44b39d6a8a425ccc13eeb0..809ad5770d4c18e9912ed5398ebd04a3f3235c9d 100644 (file)
--- 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 9a14daf072268793c29ed61e340afeafc815d143..7f2f67e6b78c49f0004faa0ab588e3624ad327b9 100644 (file)
--- 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);