imap: Track how much time was spent on waiting for locks.

diff --git a/src/imap/imap-client.c b/src/imap/imap-client.c
index b5046015643f4c778701d522445a73c299685f77..d9dce57e958955fea7e556a3f184929f5560032f 100644 (file)
--- 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 9b5415e26f20fd83232658c72061e3c7e123fc97..95b843ed6fb2775b2b729e24178fd3f261e874d7 100644 (file)
--- 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 397437510c73b504d7b4a101893c3f5400edf385..e6719404debb81cde5054a21c5946136e7ce6b3f 100644 (file)
--- 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;