dovecot-2.2: lib-http: Debug log now includes where HTTP request...

[dovecot at dovecot.org]

details:   http://hg.dovecot.org/dovecot-2.2/rev/b162e39909d7
changeset: 17625:b162e39909d7
user:      Timo Sirainen <tss at iki.fi>
date:      Fri Jul 11 14:17:17 2014 +0300
description:
lib-http: Debug log now includes where HTTP requests spent their time on.

diffstat:

 src/lib-http/http-client-connection.c |  11 ++++++++---
 src/lib-http/http-client-private.h    |   3 +++
 src/lib-http/http-client-request.c    |   2 ++
 3 files changed, 13 insertions(+), 3 deletions(-)

diffs (67 lines):

diff -r 94cdc5bcb308 -r b162e39909d7 src/lib-http/http-client-connection.c
--- a/src/lib-http/http-client-connection.c	Fri Jul 11 12:10:02 2014 +0300
+++ b/src/lib-http/http-client-connection.c	Fri Jul 11 14:17:17 2014 +0300
@@ -400,7 +400,9 @@
 	i_assert(conn->incoming_payload != NULL);
 	i_assert(conn->conn.io == NULL);
 
-	http_client_connection_debug(conn, "Response payload stream destroyed");
+	http_client_connection_debug(conn,
+		"Response payload stream destroyed (%u ms after initial response)",
+		timeval_diff_msecs(&ioloop_timeval, &req->response_time));
 
 	/* caller is allowed to change the socket fd to blocking while reading
 	   the payload. make sure here that it's switched back. */
@@ -548,6 +550,7 @@
 			http_client_connection_unref(&conn);
 			return;
 		}
+		req->response_time = ioloop_timeval;
 
 		/* Got some response; cancel response timeout */
 		if (conn->to_response != NULL)
@@ -584,8 +587,10 @@
 		} 
 
 		http_client_connection_debug(conn,
-			"Got %u response for request %s",
-			response.status, http_client_request_label(req));
+			"Got %u response for request %s (took %u ms + %u ms in queue)",
+			response.status, http_client_request_label(req),
+			timeval_diff_msecs(&req->response_time, &req->sent_time),
+			timeval_diff_msecs(&req->sent_time, &req->submit_time));
 
 		/* make sure connection output is unlocked if 100-continue failed */
 		if (req->payload_sync && !conn->payload_continue)
diff -r 94cdc5bcb308 -r b162e39909d7 src/lib-http/http-client-private.h
--- a/src/lib-http/http-client-private.h	Fri Jul 11 12:10:02 2014 +0300
+++ b/src/lib-http/http-client-private.h	Fri Jul 11 14:17:17 2014 +0300
@@ -71,6 +71,9 @@
 	struct ostream *payload_output;
 
 	struct timeval release_time;
+	struct timeval submit_time;
+	struct timeval sent_time;
+	struct timeval response_time;
 
 	unsigned int attempts;
 	unsigned int redirects;
diff -r 94cdc5bcb308 -r b162e39909d7 src/lib-http/http-client-request.c
--- a/src/lib-http/http-client-request.c	Fri Jul 11 12:10:02 2014 +0300
+++ b/src/lib-http/http-client-request.c	Fri Jul 11 14:17:17 2014 +0300
@@ -433,6 +433,7 @@
 void http_client_request_submit(struct http_client_request *req)
 {
 	req->client->pending_requests++;
+	req->submit_time = ioloop_timeval;
 
 	http_client_request_do_submit(req);
 	http_client_request_debug(req, "Submitted");
@@ -724,6 +725,7 @@
 	iov[2].iov_len = 2;
 
 	req->state = HTTP_REQUEST_STATE_PAYLOAD_OUT;
+	req->sent_time = ioloop_timeval;
 	o_stream_cork(output);
 	if (o_stream_sendv(output, iov, N_ELEMENTS(iov)) < 0) {
 		*error_r = t_strdup_printf("write(%s) failed: %s",