diff --git a/src/imap/imap-client.c b/src/imap/imap-client.c index b504601564..d9dce57e95 100644 --- a/src/imap/imap-client.c +++ b/src/imap/imap-client.c @@ -269,7 +269,7 @@ static const char *client_get_commands_status(struct client *client) { struct client_command_context *cmd, *last_cmd = NULL; unsigned int msecs_in_ioloop; - uint64_t running_usecs = 0, ioloop_wait_usecs; + uint64_t running_usecs = 0, lock_wait_usecs = 0, ioloop_wait_usecs; unsigned long long bytes_in = 0, bytes_out = 0; string_t *str; enum io_condition cond; @@ -290,6 +290,7 @@ static const char *client_get_commands_status(struct client *client) if (cmd->next != NULL) str_append_c(str, ','); running_usecs += cmd->running_usecs; + lock_wait_usecs += cmd->lock_wait_usecs; bytes_in += cmd->bytes_in; bytes_out += cmd->bytes_out; last_cmd = cmd; @@ -314,6 +315,11 @@ static const char *client_get_commands_status(struct client *client) (int)((running_usecs+999)/1000 / 1000), (int)((running_usecs+999)/1000 % 1000), cond_str, msecs_in_ioloop / 1000, msecs_in_ioloop % 1000); + if (lock_wait_usecs > 0) { + int lock_wait_msecs = (lock_wait_usecs+999)/1000; + str_printfa(str, ", %d.%03d in locks", + lock_wait_msecs/1000, lock_wait_msecs%1000); + } str_printfa(str, ", %llu B in + %llu+%"PRIuSIZE_T" B out, state=%s)", bytes_in, bytes_out, o_stream_get_buffer_used_size(client->output), diff --git a/src/imap/imap-client.h b/src/imap/imap-client.h index 9b5415e26f..95b843ed6f 100644 --- a/src/imap/imap-client.h +++ b/src/imap/imap-client.h @@ -86,6 +86,8 @@ struct client_command_context { uint64_t start_ioloop_wait_usecs; /* how many usecs this command itself has spent running */ uint64_t running_usecs; + /* how many usecs this command itself has spent waiting for locks */ + uint64_t lock_wait_usecs; /* how many bytes of client input/output command has used */ uint64_t bytes_in, bytes_out; diff --git a/src/imap/imap-commands.c b/src/imap/imap-commands.c index 397437510c..e6719404de 100644 --- a/src/imap/imap-commands.c +++ b/src/imap/imap-commands.c @@ -165,11 +165,12 @@ 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; + 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; @@ -187,6 +188,8 @@ bool command_exec(struct client_command_context *cmd) io_loop_time_refresh(); cmd->running_usecs += timeval_diff_usecs(&ioloop_timeval, &cmd_start_timeval); + cmd->lock_wait_usecs += + file_lock_wait_get_total_usecs() - cmd_start_lock_waits; cmd->bytes_in += i_stream_get_absolute_offset(cmd->client->input) - cmd_start_bytes_in; cmd->bytes_out += cmd->client->output->offset - cmd_start_bytes_out;