Mercurial > dovecot > core-2.2

changeset 20686:e7fb567c73e3

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
imap: Track how much time was spent on waiting for locks.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Tue, 23 Aug 2016 13:06:09 +0300
parents fea14728eccb
children ac22dd8b5dcc
files src/imap/imap-client.c src/imap/imap-client.h src/imap/imap-commands.c
diffstat 3 files changed, 13 insertions(+), 2 deletions(-) [+]
line wrap: on
line diff
--- a/src/imap/imap-client.c	Tue Aug 23 12:55:24 2016 +0300
+++ b/src/imap/imap-client.c	Tue Aug 23 13:06:09 2016 +0300
@@ -269,7 +269,7 @@
 {
 	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 @@
 		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 @@
 		    (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),
--- a/src/imap/imap-client.h	Tue Aug 23 12:55:24 2016 +0300
+++ b/src/imap/imap-client.h	Tue Aug 23 13:06:09 2016 +0300
@@ -86,6 +86,8 @@
 	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;
 
--- a/src/imap/imap-commands.c	Tue Aug 23 12:55:24 2016 +0300
+++ b/src/imap/imap-commands.c	Tue Aug 23 13:06:09 2016 +0300
@@ -165,11 +165,12 @@
 	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 @@
 	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;