[Author Prev][Author Next][Thread Prev][Thread Next][Author Index][Thread Index]

[Libevent-users] Re: libevent http and lost requests



On Thu, Aug 11, 2011 at 9:19 PM, about bus <aboutbus@xxxxxxxxx> wrote:
Hello!

I have a simple my own libevent-based http server written on C, use evhttp.h functions.
I use it like backend with nginx server (about ~2K requests per second).
Sometimes in nginx error log appears error: "(60: Operation timed out) while reading response header from upstream"
Timeout value is 75 seconds in nginx config file, but my http server does not need so long time to handle one request.
Average request time is about 0.01 second (information from nginx access log).

I've used tcpdump to figure out what's going wrong.
There is a network activity on timeouted requests:

nginx -> syn > httpserver
httpserver -> syn-ack > nginx
nginx -> ack > httpserver
nginx -> GET /query/xxx/yyy > httpserver
httpserver -> ack > nginx
...
75 seconds left (timeout)
...
nginx -> fin > httpserver
httpserver -> ack > nginx

Only after this time (75 seconds) libevent calls my http_handler callback.
Message about new http request appears in http server log file.
After less than one second http server ready to send response back to nginx.
But 75 seconds were lost I don't know where, and connection where closed.

So, how I can figure out why libevent holds request for 75 seconds?
Why libevent gives request for handling only when nginx tries to close connection to my http server?

Thanks!

I've added debug output to next libevent functions:
* event_add - add file descriptor to kqueue for monitoring network activity.
* kq_dispatch - return file descriptor when event appeared on it.

### Previous request which used the same file descriptor.
### Sending answer back to nginx.
2011.08.15 18:58:14 [warn] ===  event_add: event: 0x8022deb48 (fd: 115),  EV_WRITE  call 0x800796f50
2011.08.15 18:58:14 [warn] ===  kq_dispatch: fd: 115 kevent reports filter: -2 (EVFILT_WRITE)
2011.08.15 18:58:14 [warn] ===  event_active: 0x8022deb48 (fd: 115), res 4, callback 0x800796f50
2011.08.15 18:58:14 [warn] ===  evhttp_write_cb: fd: 115
2011.08.15 18:58:14 [warn] ===  kq_dispatch: fd: 115 kevent reports filter: -2 (EVFILT_WRITE)

### New request from nginx, it will be failed and reported by nginx as timeout error.
### Accepting connection and adding file descriptor to kqueue for looking READ event.
2011.08.15 18:58:15 [warn] ===  evhttp_socket_cb: fd: 115
2011.08.15 18:58:15 [warn] ===  evhttp_get_request_connection: fd: 115 new request from 127.0.0.1:57661
2011.08.15 18:58:15 [warn] ===  event_add: event: 0x8022de768 (fd: 115),  EV_WRITE  call 0x800796f50
2011.08.15 18:58:15 [warn] ===  event_add: event: 0x8022de6e0 (fd: 115), EV_READ   call 0x8007971a0

### Receiving event from kqueue for our file descriptor after 30 seconds!
### Receiving GET query, preparing and sending answer back to nginx.
2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter: -1 (EVFILT_READ)
2011.08.15 18:58:45 [warn] ===  event_active: 0x8022de6e0 (fd: 115), res 2, callback 0x8007971a0
2011.08.15 18:58:45 [warn] ===  evhttp_read_cb: fd: 115 len: 434: data: GET /QUERY/XXX/YYY/ <--headers-->
2011.08.15 18:58:45 v[3]        http_handler_input: id: 383131
2011.08.15 18:58:45 v[3]        http_handler: id: 383131 ip: XX.XX.XX.XX remote: 127.0.0.1:57661 uri: /brick/1/2/448/11/65/
2011.08.15 18:58:45 [warn] ===  event_add: event: 0x8022de768 (fd: 115),  EV_WRITE  call 0x800796f50
2011.08.15 18:58:45 v[3]        http_handler_output: id: 383131
2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter: -2 (EVFILT_WRITE)
2011.08.15 18:58:45 [warn] ===  event_active: 0x8022de768 (fd: 115), res 4, callback 0x800796f50
2011.08.15 18:58:45 [warn] ===  evhttp_write_cb: fd: 115
2011.08.15 18:58:45 [warn] ===  kq_dispatch: fd: 115 kevent reports filter: -2 (EVFILT_WRITE)

### New request from nginx.
2011.08.15 18:58:55 [warn] ===  evhttp_socket_cb: fd: 115
2011.08.15 18:58:55 [warn] ===  evhttp_get_request_connection: fd: 115 new request from 127.0.0.1:62217

So, our socket waited EV_READ event in kqueue for 30 seconds, and got it only when nginx has closed connection.

I can reproduce this issue when run my http server on FreeBSD 7.2 and FreeBSD 8.1
Today I've tried to run http server on Debian Lenny 2.6.26 - everything working fine.