Mercurial > dovecot > core-2.2
changeset 21594:359be6775382
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.
| author | Timo Sirainen <timo.sirainen@dovecot.fi> |
|---|---|
| date | Sun, 19 Feb 2017 15:47:48 +0200 |
| parents | e8dfebca6899 |
| children | b6b3381b9660 |
| files | src/imap/imap-client.c src/imap/imap-client.h src/imap/imap-commands.c src/imap/imap-commands.h |
| diffstat | 4 files changed, 38 insertions(+), 14 deletions(-) [+] |
line wrap: on
line diff
--- 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;
--- 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;
--- 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; }
--- 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);