Project

General

Profile

Actions
Copy link

Bug #1734

closed

mod_proxy stalling with freebsd-kqueue event handler

Added by Anonymous over 16 years ago. Updated about 16 years ago.

Status:
Invalid
Priority:
Normal
Category:
mod_proxy
Target version:
1.4.20
ASK QUESTIONS IN Forums:

Description

About every 10:th or 20:th request to a "lighttpd proxy" will stall for server.max-keep-alive-idle seconds when run on FreeBSD 7.0 with freebsd-kqueue as event handler. With the poll handler, everything works as espected.

For clarification, no requests times out or gets dropped - they just gets stalled for a while.


The problem occurs with this simple config:
server.modules = (
    "mod_proxy" 
)
server.bind                     = "172.16.216.211" 
server.pid-file                 = "/var/run/lighttpd_lb_simple.pid" 
server.errorlog                 = "/var/log/tmp/lb_simple_error.log" 
server.event-handler            = "freebsd-kqueue" 
server.port                     = 80
server.max-keep-alive-idle      = 10
proxy.debug = 1
proxy.server  = ( "" => ( ( "host" => "172.16.216.201" ) ) )
server.document-root            = "/tmp"

Here is the debug output:


<request A start>
2008-07-24 17:56:26: (mod_proxy.c.1080) proxy - start 
2008-07-24 17:56:26: (mod_proxy.c.1118) proxy - ext found 
2008-07-24 17:56:26: (mod_proxy.c.1161) proxy - used fair balancing 
2008-07-24 17:56:26: (mod_proxy.c.1242) proxy - found a host 172.16.216.201 80 
2008-07-24 17:56:26: (mod_proxy.c.391) connect succeeded:  6 
2008-07-24 17:56:26: (mod_proxy.c.961) proxy: fdevent-in 4 
2008-07-24 17:56:26: (mod_proxy.c.645) proxy - have to read: 8275 
2008-07-24 17:56:26: (mod_proxy.c.961) proxy: fdevent-in 4 
2008-07-24 17:56:26: (mod_proxy.c.645) proxy - have to read: 1854 
2008-07-24 17:56:26: (mod_proxy.c.1015) proxy: fdevent-hup 4 
<the 10 seconds long unwanted paus>
<request B start>
2008-07-24 17:56:37: (mod_proxy.c.1080) proxy - start 
2008-07-24 17:56:37: (mod_proxy.c.1118) proxy - ext found 
2008-07-24 17:56:37: (mod_proxy.c.1161) proxy - used fair balancing 
2008-07-24 17:56:37: (mod_proxy.c.1242) proxy - found a host 172.16.216.201 80 
2008-07-24 17:56:37: (mod_proxy.c.391) connect succeeded:  7 
2008-07-24 17:56:37: (mod_proxy.c.961) proxy: fdevent-in 4 
2008-07-24 17:56:37: (mod_proxy.c.645) proxy - have to read: 8275 
2008-07-24 17:56:37: (mod_proxy.c.961) proxy: fdevent-in 4 
2008-07-24 17:56:37: (mod_proxy.c.645) proxy - have to read: 3827 
2008-07-24 17:56:37: (mod_proxy.c.1015) proxy: fdevent-hup 4 

This was captured with ktrace. The trace starts with the reading of the last 1854 bytes of request A response (total 10129 bytes) from backend.
  6728 lighttpd 1216914986.556457 RET   read 1854/0x73e
  6728 lighttpd 1216914986.556479 CALL  write(3,34374489088,62)
  6728 lighttpd 1216914986.556498 GIO   fd 3 wrote 62 bytes
       "2008-07-24 17:56:26: (mod_proxy.c.1015) proxy: fdevent-hup 4 
       " 
  6728 lighttpd 1216914986.556508 RET   write 62/0x3e
  6728 lighttpd 1216914986.556548 CALL  kevent(5,140737488349040,1,0,0,140737488349072)
  6728 lighttpd 1216914986.556563 GIO   fd 5 wrote 32 bytes
       0x0000 0600 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914986.556573 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914986.556583 RET   kevent 0
  6728 lighttpd 1216914986.556593 CALL  close(6)
  6728 lighttpd 1216914986.556663 RET   close 0
  6728 lighttpd 1216914986.556693 CALL  writev(16,140737488331664,7)
  6728 lighttpd 1216914986.561549 GIO   fd 16 wrote 4096 bytes
       "HTTP/1.1 200 OK\r
        Transfer-Encoding: chunked\r
        Content-type: application/x-javascript; charset=UTF-8\r
        Pragma: public\r
        Expires: Fri, 24 Jul 2009 15:56:26 GMT\r
        Date: Thu, 24 Jul 2008 15:56:26 GMT\r
        Server: lighttpd\r
        \r
        1f87\r
        /*
<snip>
  6728 lighttpd 1216914986.561685 RET   writev 10153/0x27a9
  6728 lighttpd 1216914986.561820 CALL  ioctl(16,FIONREAD,140737488348140)
  6728 lighttpd 1216914986.561942 RET   ioctl 0
  6728 lighttpd 1216914986.562062 CALL  read(16,34375022592,767)
  6728 lighttpd 1216914986.562184 RET   read -1 errno 35 Resource temporarily unavailable
  6728 lighttpd 1216914986.562306 CALL  kevent(5,140737488348096,1,0,0,140737488348128)
  6728 lighttpd 1216914986.562430 GIO   fd 5 wrote 32 bytes
       0x0000 1000 0000 0000 0000 ffff 2100 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |..........!.....................|

  6728 lighttpd 1216914986.562550 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914986.562668 RET   kevent 0
  6728 lighttpd 1216914986.562789 CALL  kevent(5,140737488348096,1,0,0,140737488348128)
  6728 lighttpd 1216914986.562886 GIO   fd 5 wrote 32 bytes
       0x0000 1000 0000 0000 0000 ffff 2100 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |..........!.....................|

  6728 lighttpd 1216914986.563039 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914986.563157 RET   kevent 0
  6728 lighttpd 1216914986.563277 CALL  kevent(5,140737488348096,1,0,0,140737488348128)
  6728 lighttpd 1216914986.563398 GIO   fd 5 wrote 32 bytes
       0x0000 1000 0000 0000 0000 ffff 2100 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |..........!.....................|

  6728 lighttpd 1216914986.563517 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914986.563635 RET   kevent 0
  6728 lighttpd 1216914986.563755 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914986.563989 RET   gettimeofday 0
  6728 lighttpd 1216914986.564110 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914987.568562 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914987.568620 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914987.568647 RET   kevent 0
  6728 lighttpd 1216914987.568680 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914987.568854 RET   gettimeofday 0
  6728 lighttpd 1216914987.568896 CALL  shutdown(21,<invalid=1>)
  6728 lighttpd 1216914987.569523 RET   shutdown 0
  6728 lighttpd 1216914987.569548 CALL  kevent(5,140737488348080,1,0,0,140737488348112)
  6728 lighttpd 1216914987.569574 GIO   fd 5 wrote 32 bytes
       0x0000 1500 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914987.569592 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914987.569609 RET   kevent 0
  6728 lighttpd 1216914987.569630 CALL  close(21)
  6728 lighttpd 1216914987.569658 RET   close 0
  6728 lighttpd 1216914987.569680 CALL  shutdown(14,<invalid=1>)
  6728 lighttpd 1216914987.569920 RET   shutdown 0
  6728 lighttpd 1216914987.569945 CALL  kevent(5,140737488348080,1,0,0,140737488348112)
  6728 lighttpd 1216914987.569968 GIO   fd 5 wrote 32 bytes
       0x0000 0e00 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914987.569985 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914987.570002 RET   kevent 0
  6728 lighttpd 1216914987.570020 CALL  close(14)
  6728 lighttpd 1216914987.570044 RET   close 0
  6728 lighttpd 1216914987.570066 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914988.579154 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914988.579281 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914988.579349 RET   kevent 0
  6728 lighttpd 1216914988.579385 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914988.579427 RET   gettimeofday 0
  6728 lighttpd 1216914988.579467 CALL  shutdown(17,<invalid=1>)
  6728 lighttpd 1216914988.580079 RET   shutdown 0
  6728 lighttpd 1216914988.580115 CALL  kevent(5,140737488348080,1,0,0,140737488348112)
  6728 lighttpd 1216914988.580152 GIO   fd 5 wrote 32 bytes
       0x0000 1100 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914988.580179 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914988.580204 RET   kevent 0
  6728 lighttpd 1216914988.580234 CALL  close(17)
  6728 lighttpd 1216914988.580275 RET   close 0
  6728 lighttpd 1216914988.580309 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914989.587958 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914989.588017 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914989.588044 RET   kevent 0
  6728 lighttpd 1216914989.588076 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914989.588119 RET   gettimeofday 0
  6728 lighttpd 1216914989.588250 CALL  shutdown(19,<invalid=1>)
  6728 lighttpd 1216914989.588857 RET   shutdown 0
  6728 lighttpd 1216914989.588893 CALL  kevent(5,140737488348080,1,0,0,140737488348112)
  6728 lighttpd 1216914989.588931 GIO   fd 5 wrote 32 bytes
       0x0000 1300 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914989.588985 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914989.589012 RET   kevent 0
  6728 lighttpd 1216914989.589043 CALL  close(19)
  6728 lighttpd 1216914989.589084 RET   close 0
  6728 lighttpd 1216914989.589106 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914990.597854 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914990.597912 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914990.597938 RET   kevent 0
  6728 lighttpd 1216914990.597970 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914990.598013 RET   gettimeofday 0
  6728 lighttpd 1216914990.598048 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914991.607743 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914991.607800 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914991.607827 RET   kevent 0
  6728 lighttpd 1216914991.607860 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914991.607903 RET   gettimeofday 0
  6728 lighttpd 1216914991.607939 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914992.620613 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914992.620673 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914992.620700 RET   kevent 0
  6728 lighttpd 1216914992.620733 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914992.620776 RET   gettimeofday 0
  6728 lighttpd 1216914992.620812 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914993.627528 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914993.627586 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914993.627612 RET   kevent 0
  6728 lighttpd 1216914993.627644 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914993.627687 RET   gettimeofday 0
  6728 lighttpd 1216914993.627722 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914994.638502 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914994.638561 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914994.638588 RET   kevent 0
  6728 lighttpd 1216914994.638621 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914994.638663 RET   gettimeofday 0
  6728 lighttpd 1216914994.638700 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914995.647767 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914995.647809 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914995.647828 RET   kevent 0
  6728 lighttpd 1216914995.647851 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914995.647879 RET   gettimeofday 0
  6728 lighttpd 1216914995.647919 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914996.657140 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914996.657214 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914996.657242 RET   kevent 0
  6728 lighttpd 1216914996.657272 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914996.657315 RET   gettimeofday 0
  6728 lighttpd 1216914996.657349 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914997.668476 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914997.668535 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914997.668562 RET   kevent 0
  6728 lighttpd 1216914997.668595 CALL  gettimeofday(140737488349312,0)
  6728 lighttpd 1216914997.668638 RET   gettimeofday 0
  6728 lighttpd 1216914997.668678 CALL  shutdown(16,<invalid=1>)
  6728 lighttpd 1216914997.669552 RET   shutdown 0
  6728 lighttpd 1216914997.669579 CALL  kevent(5,140737488348080,1,0,0,140737488348112)
  6728 lighttpd 1216914997.669606 GIO   fd 5 wrote 32 bytes
       0x0000 1000 0000 0000 0000 ffff 0200 0000 0000 0000 0000 0000 0000 0000 0000 0000 0000                                     |................................|

  6728 lighttpd 1216914997.669624 GIO   fd 5 read 0 bytes
       "" 
  6728 lighttpd 1216914997.669641 RET   kevent 0
  6728 lighttpd 1216914997.669662 CALL  close(16)
  6728 lighttpd 1216914997.669684 RET   close 0
  6728 lighttpd 1216914997.669706 CALL  kevent(5,0,0,34374684672,1707,140737488349312)
  6728 lighttpd 1216914997.676864 GIO   fd 5 wrote 0 bytes
       "" 
  6728 lighttpd 1216914997.676897 GIO   fd 5 read 32 bytes
       0x0000 0400 0000 0000 0000 ffff 2000 0000 0000 0100 0000 0000 0000 0000 0000 0000 0000                                     |.......... .....................|

  6728 lighttpd 1216914997.676913 RET   kevent 1
  6728 lighttpd 1216914997.676933 CALL  accept(4,140737488349120,140737488349228)
  6728 lighttpd 1216914997.676957 RET   accept 6
  6728 lighttpd 1216914997.676992 CALL  fcntl(6,F_SETFD,FD_CLOEXEC)
  6728 lighttpd 1216914997.677009 RET   fcntl 0
  6728 lighttpd 1216914997.677024 CALL  fcntl(6,F_SETFL,O_RDWR|O_NONBLOCK)
  6728 lighttpd 1216914997.677040 RET   fcntl 0
  6728 lighttpd 1216914997.677056 CALL  ioctl(6,FIONREAD,140737488348092)
  6728 lighttpd 1216914997.677073 RET   ioctl 0
  6728 lighttpd 1216914997.677089 CALL  read(6,34375022592,767)
  6728 lighttpd 1216914997.677111 GIO   fd 6 read 752 bytes
<reading of the GET-request from browser for request B follows>

You can see that lighttpd is polling every second while the request is stalled.

-- martin

Actions
Copy link
 #1

Updated by Anonymous over 16 years ago

Oh, and I can't trigger the error by doing just one request at a time. The error occurs when a browser loads a webpage with several requests.

-- martin

Actions
Copy link
 #2

Updated by stbuehler over 16 years ago

  • Status changed from New to Fixed
  • Resolution set to invalid

It gets closed even before lighty sends the content (6 was the proxy fd, which i got from the error.log; but you should have seen that in the full trace too - btw, please give us the full trace next time):


2008-07-24 17:56:26: (mod_proxy.c.391) connect succeeded:  6 
[...]
CALL  close(6)

The other fd which gets closed the after keep-alive-timeout is 16, which is the connection to your browser, and that is perfectly valid.

Actions
Copy link
 #3

Updated by stbuehler about 16 years ago

  • Status changed from Fixed to Invalid
Actions
Copy link

Also available in: Atom