dovecot-2.2: imap: Include in tagged reply how much running time...

[dovecot at dovecot.org]

details:   http://hg.dovecot.org/dovecot-2.2/rev/abf2727d469a
changeset: 18432:abf2727d469a
user:      Timo Sirainen <tss at iki.fi>
date:      Tue Apr 21 14:06:22 2015 +0300
description:
imap: Include in tagged reply how much running time each IMAP command takes.
The running time doesn't include time spent waiting for the client on
ioloop.

diffstat:

 src/imap/imap-client.c   |  24 ++++++++++++++++++++----
 src/imap/imap-client.h   |   8 ++++++++
 src/imap/imap-commands.c |  13 +++++++++++++
 3 files changed, 41 insertions(+), 4 deletions(-)

diffs (105 lines):

diff -r 7a09ddcd62b4 -r abf2727d469a src/imap/imap-client.c
--- a/src/imap/imap-client.c	Tue Apr 21 14:03:52 2015 +0300
+++ b/src/imap/imap-client.c	Tue Apr 21 14:06:22 2015 +0300
@@ -379,6 +379,7 @@
 {
 	struct client *client = cmd->client;
 	const char *tag = cmd->tag;
+	int time_msecs;
 
 	if (client->output->closed || cmd->cancel)
 		return;
@@ -389,10 +390,24 @@
 	if (tag == NULL || *tag == '\0')
 		tag = "*";
 
-	o_stream_nsend_str(client->output, tag);
-	o_stream_nsend(client->output, " ", 1);
-	o_stream_nsend_str(client->output, data);
-	o_stream_nsend(client->output, "\r\n", 2);
+	T_BEGIN {
+		string_t *str = t_str_new(256);
+		str_printfa(str, "%s %s", tag, data);
+		if (cmd->start_time.tv_sec != 0) {
+			if (str_data(str)[str_len(str)-1] == '.')
+				str_truncate(str, str_len(str)-1);
+			io_loop_time_refresh();
+			time_msecs = timeval_diff_msecs(&ioloop_timeval,
+							&cmd->start_time);
+			time_msecs -= cmd->usecs_in_ioloop/1000;
+			if (time_msecs >= 0) {
+				str_printfa(str, " (%d.%03d secs).",
+					    time_msecs/1000, time_msecs%1000);
+			}
+		}
+		str_append(str, "\r\n");
+		o_stream_nsend(client->output, str_data(str), str_len(str));
+	} T_END;
 
 	client->last_output = ioloop_time;
 }
@@ -459,6 +474,7 @@
 		str = t_str_new(256);
 		imap_write_args(str, *args_r);
 		cmd->args = p_strdup(cmd->pool, str_c(str));
+		cmd->start_time = ioloop_timeval;
 
 		cmd->client->input_lock = NULL;
 		return TRUE;
diff -r 7a09ddcd62b4 -r abf2727d469a src/imap/imap-client.h
--- a/src/imap/imap-client.h	Tue Apr 21 14:03:52 2015 +0300
+++ b/src/imap/imap-client.h	Tue Apr 21 14:06:22 2015 +0300
@@ -74,6 +74,14 @@
 
 	struct imap_parser *parser;
 	enum client_command_state state;
+	/* time when command handling was started - typically this is after
+	   reading all the parameters. */
+	struct timeval start_time;
+	/* time when an unfinished command handling entered back to ioloop.
+	   used for calculating usecs_in_ioloop */
+	struct timeval last_ioloop_time;
+	/* how much time was spent waiting for the client in ioloop */
+	uint64_t usecs_in_ioloop;
 
 	struct client_sync_context *sync;
 
diff -r 7a09ddcd62b4 -r abf2727d469a src/imap/imap-commands.c
--- a/src/imap/imap-commands.c	Tue Apr 21 14:03:52 2015 +0300
+++ b/src/imap/imap-commands.c	Tue Apr 21 14:06:22 2015 +0300
@@ -3,6 +3,8 @@
 #include "imap-common.h"
 #include "array.h"
 #include "buffer.h"
+#include "ioloop.h"
+#include "time-util.h"
 #include "imap-commands.h"
 
 #include <stdlib.h>
@@ -151,8 +153,15 @@
 bool command_exec(struct client_command_context *cmd)
 {
 	const struct command_hook *hook;
+	long long diff;
 	bool finished;
 
+	if (cmd->last_ioloop_time.tv_sec != 0) {
+		diff = timeval_diff_usecs(&ioloop_timeval, &cmd->last_ioloop_time);
+		if (diff > 0)
+			cmd->usecs_in_ioloop += diff;
+	}
+
 	array_foreach(&command_hooks, hook)
 		hook->pre(cmd);
 	finished = cmd->func(cmd);
@@ -160,6 +169,10 @@
 		hook->post(cmd);
 	if (cmd->state == CLIENT_COMMAND_STATE_DONE)
 		finished = TRUE;
+	if (!finished) {
+		io_loop_time_refresh();
+		cmd->last_ioloop_time = ioloop_timeval;
+	}
 	return finished;
 }