On Thu, Aug 11, 2011 at 9:19 PM, about bus <about...@gmail.com> 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.
