From: Timo Sirainen Date: Mon, 24 Oct 2016 10:08:47 +0000 (+0300) Subject: lib-http: Add ioloop and lock wait information to timeout messages. X-Git-Tag: 2.2.26~49 X-Git-Url: http://git.ipfire.org/?a=commitdiff_plain;h=50ce4f6ed21fdb2b2b3bde5f41ccac825418b13f;p=thirdparty%2Fdovecot%2Fcore.git 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. --- diff --git a/src/lib-http/http-client-connection.c b/src/lib-http/http-client-connection.c index 5aeb28456a..5f8b769cba 100644 --- a/src/lib-http/http-client-connection.c +++ b/src/lib-http/http-client-connection.c @@ -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 @@ http_client_connection_get_timing_info(struct http_client_connection *conn) (*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) { diff --git a/src/lib-http/http-client-private.h b/src/lib-http/http-client-private.h index 51e01168ef..0090e41127 100644 --- a/src/lib-http/http-client-private.h +++ b/src/lib-http/http-client-private.h @@ -95,6 +95,8 @@ struct http_client_request { 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; diff --git a/src/lib-http/http-client-request.c b/src/lib-http/http-client-request.c index fcc53c5c44..eaac523fe8 100644 --- a/src/lib-http/http-client-request.c +++ b/src/lib-http/http-client-request.c @@ -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 @@ static int http_client_request_send_real(struct http_client_request *req, 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",