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

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),

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;
 

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;