Skip to content

Commit

Permalink
lib-http: Add ioloop and lock wait information to timeout messages.
Browse files Browse the repository at this point in the history
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.
  • Loading branch information
sirainen committed Oct 24, 2016
1 parent 240efa2 commit 9407950
Show file tree
Hide file tree
Showing 3 changed files with 24 additions and 0 deletions.
19 changes: 19 additions & 0 deletions src/lib-http/http-client-connection.c
Expand Up @@ -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"
Expand Down Expand Up @@ -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) {
Expand Down
2 changes: 2 additions & 0 deletions src/lib-http/http-client-private.h
Expand Up @@ -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;
Expand Down
3 changes: 3 additions & 0 deletions src/lib-http/http-client-request.c
Expand Up @@ -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"
Expand Down Expand Up @@ -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",
Expand Down

0 comments on commit 9407950

Please sign in to comment.