Mercurial > dovecot > core-2.2

changeset 20951:1d037671b39a

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
lib-http: Add ioloop and lock wait information to timeout messages. It'll now log for example: 9007 Request timed out (Request sent 7.087 secs ago, 0.076 in other ioloops, 7.012 in locks, connected 7.087 secs ago) Which points out that the problem wasn't really with the HTTP, but with locking. This likely should be fixed in some way also in lib-http so that it gives a bit of extra time for reading the request, but that's a separate fix.
author Timo Sirainen <timo.sirainen@dovecot.fi>
date Mon, 24 Oct 2016 13:08:47 +0300
parents 65b95f54ea59
children 99b7f460f1c0
files src/lib-http/http-client-connection.c src/lib-http/http-client-private.h src/lib-http/http-client-request.c
diffstat 3 files changed, 24 insertions(+), 0 deletions(-) [+]
line wrap: on
line diff
--- a/src/lib-http/http-client-connection.c	Mon Oct 24 12:17:44 2016 +0300
+++ b/src/lib-http/http-client-connection.c	Mon Oct 24 13:08:47 2016 +0300
@@ -11,6 +11,7 @@
 #include "istream-timeout.h"
 #include "ostream.h"
 #include "time-util.h"
+#include "file-lock.h"
 #include "iostream-rawlog.h"
 #include "iostream-ssl.h"
 #include "http-response-parser.h"
@@ -199,6 +200,24 @@
 				    (*requestp)->attempts + 1,
 				    total_msecs/1000, total_msecs%1000);
 		}
+		int other_ioloop_msecs = (ioloop_global_wait_usecs -
+			(*requestp)->sent_global_ioloop_usecs + 999) / 1000;
+		if (conn->client->ioloop != NULL) {
+			int http_ioloop_msecs =
+				(io_loop_get_wait_usecs(conn->client->ioloop) + 999) / 1000;
+			other_ioloop_msecs -= http_ioloop_msecs;
+			str_printfa(str, ", %d.%03d in http ioloop",
+				    http_ioloop_msecs/1000, http_ioloop_msecs%1000);
+		}
+		str_printfa(str, ", %d.%03d in other ioloops",
+			    other_ioloop_msecs/1000, other_ioloop_msecs%1000);
+
+		int lock_msecs = (file_lock_wait_get_total_usecs() -
+				  (*requestp)->sent_lock_usecs + 999) / 1000;
+		if (lock_msecs > 0) {
+			str_printfa(str, ", %d.%03d in locks",
+				    lock_msecs/1000, lock_msecs%1000);
+		}
 	} else {
 		str_append(str, "No requests");
 		if (conn->conn.last_input != 0) {
--- a/src/lib-http/http-client-private.h	Mon Oct 24 12:17:44 2016 +0300
+++ b/src/lib-http/http-client-private.h	Mon Oct 24 13:08:47 2016 +0300
@@ -95,6 +95,8 @@
 
 	unsigned int attempts;
 	unsigned int redirects;
+	uint64_t sent_global_ioloop_usecs;
+	uint64_t sent_lock_usecs;
 
 	unsigned int delayed_error_status;
 	const char *delayed_error;
--- a/src/lib-http/http-client-request.c	Mon Oct 24 12:17:44 2016 +0300
+++ b/src/lib-http/http-client-request.c	Mon Oct 24 13:08:47 2016 +0300
@@ -9,6 +9,7 @@
 #include "time-util.h"
 #include "istream.h"
 #include "ostream.h"
+#include "file-lock.h"
 #include "dns-lookup.h"
 #include "http-url.h"
 #include "http-date.h"
@@ -1006,6 +1007,8 @@
 
 	req->state = HTTP_REQUEST_STATE_PAYLOAD_OUT;
 	req->sent_time = ioloop_timeval;
+	req->sent_lock_usecs = file_lock_wait_get_total_usecs();
+	req->sent_global_ioloop_usecs = ioloop_global_wait_usecs;
 	o_stream_cork(output);
 	if (o_stream_sendv(output, iov, N_ELEMENTS(iov)) < 0) {
 		*error_r = t_strdup_printf("write(%s) failed: %s",