Varnish 503ing on ~1/100 POSTs
Ronan Mullally
ronan at iol.ie
Wed Mar 23 17:25:43 CET 2011
On Thu, 10 Mar 2011, Tollef Fog Heen wrote:
> | I'm seeing intermittant 503s on POSTs to a fairly busy VBulletin website.
> | The current load is light (up to a couple of thousand active sessions,
> | peak is around five thousand). Varnish has a fairly simple config with
> | a director consisting of two Apache backends:
>
> This looks a bit odd:
>
> | backend backend1 {
> | .host = "1.2.3.4";
> | .port = "80";
> | .connect_timeout = 5s;
> | .first_byte_timeout = 90s;
> | .between_bytes_timeout = 90s;
> | A typical request is below. The first attempt fails with:
> |
> | 33 FetchError c http first read error: -1 0 (Success)
>
> This just means the backend closed the connection on us.
>
> | there is presumably a restart and the second attempt (sometimes to
> | backend1, sometimes backend2) fails with:
> |
> | 33 FetchError c backend write error: 11 (Resource temporarily unavailable)
>
> This is a timeout, however:
>
> | 33 ReqEnd c 657185708 1299604110.559967279 1299604113.447372913 0.000037670 2.887368441 0.000037193
>
> That 2.89s backend response time doesn't add up with your timeouts. Can
> you see if you can get a tcpdump of what's going on?
Varnishlog and output from TCP for a typical occurance is below. If you
need any further details let me know.
-Ronan
16 ReqStart c 202.168.71.170 39173 403520520
16 RxRequest c POST
16 RxURL c /ajax.php
16 RxProtocol c HTTP/1.1
16 RxHeader c Via: 1.1 APSRVMY35001
16 RxHeader c Cookie: __utma=216440341.583483764.1291872570.1299827399.1300063501.123; __utmz=216440341.1292919894.10.2....
16 RxHeader c Referer: http://www.redcafe.net/f8/
16 RxHeader c Content-Type: application/x-www-form-urlencoded; charset=UTF-8
16 RxHeader c User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6
16 RxHeader c Host: www.redcafe.net
16 RxHeader c Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
16 RxHeader c Accept-Language: en-gb,en;q=0.5
16 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
16 RxHeader c Keep-Alive: 115
16 RxHeader c X-Requested-With: XMLHttpRequest
16 RxHeader c Pragma: no-cache
16 RxHeader c Cache-Control: no-cache
16 RxHeader c Connection: Keep-Alive
16 RxHeader c Content-Length: 82
16 VCL_call c recv
16 VCL_return c pass
16 VCL_call c hash
16 VCL_return c hash
16 VCL_call c pass
16 VCL_return c pass
16 Backend c 53 redcafe redcafe1
53 TxRequest b POST
53 TxURL b /ajax.php
53 TxProtocol b HTTP/1.1
53 TxHeader b Via: 1.1 APSRVMY35001
53 TxHeader b Cookie: __utma=216440341.583483764.1291872570.1299827399.1300063501.123; __utmz=216440341.1292919894.10.2....
53 TxHeader b Referer: http://www.redcafe.net/f8/
53 TxHeader b Content-Type: application/x-www-form-urlencoded; charset=UTF-8
53 TxHeader b User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6
53 TxHeader b Host: www.redcafe.net
53 TxHeader b Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
53 TxHeader b Accept-Language: en-gb,en;q=0.5
53 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
53 TxHeader b X-Requested-With: XMLHttpRequest
53 TxHeader b Pragma: no-cache
53 TxHeader b Cache-Control: no-cache
53 TxHeader b Content-Length: 82
53 TxHeader b X-Forwarded-For: 202.168.71.170
53 TxHeader b X-Varnish: 403520520
16 FetchError c http first read error: -1 0 (Success)
53 BackendClose b redcafe1
16 Backend c 52 redcafe redcafe2
52 TxRequest b POST
52 TxURL b /ajax.php
52 TxProtocol b HTTP/1.1
52 TxHeader b Via: 1.1 APSRVMY35001
52 TxHeader b Cookie: __utma=216440341.583483764.1291872570.1299827399.1300063501.123; __utmz=216440341.1292919894.10.2....
52 TxHeader b Referer: http://www.redcafe.net/f8/
52 TxHeader b Content-Type: application/x-www-form-urlencoded; charset=UTF-8
52 TxHeader b User-Agent: Mozilla/5.0 (Windows; U; Windows NT 6.1; en-GB; rv:1.9.2) Gecko/20100115 Firefox/3.6
52 TxHeader b Host: www.redcafe.net
52 TxHeader b Accept: text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
52 TxHeader b Accept-Language: en-gb,en;q=0.5
52 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.7
52 TxHeader b X-Requested-With: XMLHttpRequest
52 TxHeader b Pragma: no-cache
52 TxHeader b Cache-Control: no-cache
52 TxHeader b Content-Length: 82
52 TxHeader b X-Forwarded-For: 202.168.71.170
52 TxHeader b X-Varnish: 403520520
16 FetchError c backend write error: 11 (Resource temporarily unavailable)
52 BackendClose b redcafe2
16 VCL_call c error
16 VCL_return c deliver
16 VCL_call c deliver
16 VCL_return c deliver
16 TxProtocol c HTTP/1.1
16 TxStatus c 503
16 TxResponse c Service Unavailable
16 TxHeader c Server: Varnish
16 TxHeader c Retry-After: 0
16 TxHeader c Content-Type: text/html; charset=utf-8
16 TxHeader c Content-Length: 2623
16 TxHeader c Date: Mon, 14 Mar 2011 11:16:11 GMT
16 TxHeader c X-Varnish: 403520520
16 TxHeader c Age: 2
16 TxHeader c Via: 1.1 varnish
16 TxHeader c Connection: close
16 Length c 2623
16 ReqEnd c 403520520 1300101369.629967451 1300101371.923255682 0.000078917 2.293243885 0.000044346
16 SessionClose c error
16 StatSess c 202.168.71.170 39173 2 1 1 0 1 0 235 2623
First attempt (redcafe1 backend)
2011-03-14 11:16:09.892897 IP 193.27.1.46.22809 > 193.27.1.44.80: . ack 2433 win 91 <nop,nop,timestamp 211654747 270145421>
0x0000: 4500 0034 d23d 4000 4006 e3f5 c11b 012e E..4.=@. at .......
0x0010: c11b 012c 5919 0050 41f0 4706 4cdf c051 ...,Y..PA.G.L..Q
0x0020: 8010 005b 35a1 0000 0101 080a 0c9d 985b ...[5..........[
0x0030: 101a 178d ....
2011-03-14 11:16:09.926678 IP 193.27.1.46.22809 > 193.27.1.44.80: P 400:1549(1149) ack 2433 win 91 <nop,nop,timestamp 211654755 270145421>
0x0000: 4500 04b1 d23e 4000 4006 df77 c11b 012e E....>@. at ..w....
0x0010: c11b 012c 5919 0050 41f0 4706 4cdf c051 ...,Y..PA.G.L..Q
0x0020: 8018 005b 8934 0000 0101 080a 0c9d 9863 ...[.4.........c
0x0030: 101a 178d 504f 5354 202f 616a 6178 2e70 ....POST./ajax.p
0x0040: 6870 2048 5454 502f 312e 310d 0a56 6961 hp.HTTP/1.1..Via
0x0050: 3a20 312e 3120 4150 5352 564d 5933 3530 :.1.1.APSRVMY350
0x0060: 3031 0d0a 436f 6f6b 6965 3a20 5f5f 7574 01..Cookie:.__ut
0x0070: 6d61 3d32 3136 3434 3033 3431 2e35 3833 ma=216440341.583
0x0080: 3438 3337 3634 2e31 3239 3138 3732 3537 483764.129187257
0x0090: 302e 3132 3939 3832 3733 3939 2e31 3330 0.1299827399.130
0x00a0: 3030 3633 3530 312e 3132 333b 205f 5f75 0063501.123;.__u
0x00b0: 746d 7a3d 3231 3634 3430 3334 312e 3132 tmz=216440341.12
0x00c0: 3932 3931 3938 3934 2e31 302e 322e 7574 92919894.10.2.ut
0x00d0: 6d63 636e 3d28 6f72 6761 6e69 6329 7c75 mccn=(organic)|u
...
0x0230: 3742 692d 3332 3335 3438 5f69 2d31 3330 7Bi-323548_i-130
0x0240: 3030 3632 3533 375f 2537 440d 0a52 6566 0062537_%7D..Ref
0x0250: 6572 6572 3a20 6874 7470 3a2f 2f77 7777 erer:.http://www
0x0260: 2e72 6564 6361 6665 2e6e 6574 2f66 382f .redcafe.net/f8/
0x0270: 0d0a 436f 6e74 656e 742d 5479 7065 3a20 ..Content-Type:.
0x0280: 6170 706c 6963 6174 696f 6e2f 782d 7777 application/x-ww
0x0290: 772d 666f 726d 2d75 726c 656e 636f 6465 w-form-urlencode
0x02a0: 643b 2063 6861 7273 6574 3d55 5446 2d38 d;.charset=UTF-8
0x02b0: 0d0a 5573 6572 2d41 6765 6e74 3a20 4d6f ..User-Agent:.Mo
0x02c0: 7a69 6c6c 612f 352e 3020 2857 696e 646f zilla/5.0.(Windo
0x02d0: 7773 3b20 553b 2057 696e 646f 7773 204e ws;.U;.Windows.N
0x02e0: 5420 362e 313b 2065 6e2d 4742 3b20 7276 T.6.1;.en-GB;.rv
0x02f0: 3a31 2e39 2e32 2920 4765 636b 6f2f 3230 :1.9.2).Gecko/20
0x0300: 3130 3031 3135 2046 6972 6566 6f78 2f33 100115.Firefox/3
0x0310: 2e36 0d0a 486f 7374 3a20 7777 772e 7265 .6..Host:.www.re
0x0320: 6463 6166 652e 6e65 740d 0a41 6363 6570 dcafe.net..Accep
0x0330: 743a 2074 6578 742f 6874 6d6c 2c61 7070 t:.text/html,app
0x0340: 6c69 6361 7469 6f6e 2f78 6874 6d6c 2b78 lication/xhtml+x
0x0350: 6d6c 2c61 7070 6c69 6361 7469 6f6e 2f78 ml,application/x
0x0360: 6d6c 3b71 3d30 2e39 2c2a 2f2a 3b71 3d30 ml;q=0.9,*/*;q=0
0x0370: 2e38 0d0a 4163 6365 7074 2d4c 616e 6775 .8..Accept-Langu
0x0380: 6167 653a 2065 6e2d 6762 2c65 6e3b 713d age:.en-gb,en;q=
0x0390: 302e 350d 0a41 6363 6570 742d 4368 6172 0.5..Accept-Char
0x03a0: 7365 743a 2049 534f 2d38 3835 392d 312c set:.ISO-8859-1,
0x03b0: 7574 662d 383b 713d 302e 372c 2a3b 713d utf-8;q=0.7,*;q=
0x03c0: 302e 370d 0a58 2d52 6571 7565 7374 6564 0.7..X-Requested
0x03d0: 2d57 6974 683a 2058 4d4c 4874 7470 5265 -With:.XMLHttpRe
0x03e0: 7175 6573 740d 0a50 7261 676d 613a 206e quest..Pragma:.n
0x03f0: 6f2d 6361 6368 650d 0a43 6163 6865 2d43 o-cache..Cache-C
0x0400: 6f6e 7472 6f6c 3a20 6e6f 2d63 6163 6865 ontrol:.no-cache
0x0410: 0d0a 436f 6e74 656e 742d 4c65 6e67 7468 ..Content-Length
0x0420: 3a20 3832 0d0a 582d 466f 7277 6172 6465 :.82..X-Forwarde
0x0430: 642d 466f 723a 2032 3032 2e31 3638 2e37 d-For:.202.168.7
0x0440: 312e 3137 300d 0a58 2d56 6172 6e69 7368 1.170..X-Varnish
0x0450: 3a20 3430 3335 3230 3532 300d 0a0d 0a73 :.403520520....s
0x0460: 6563 7572 6974 7974 6f6b 656e 3d31 3330 ecuritytoken=130
0x0470: 3030 3937 3737 302d 3539 3938 3235 3061 0097770-5998250a
0x0480: 6336 6662 3932 3431 6435 3335 3835 6366 c6fb9241d53585cf
0x0490: 3863 6537 3039 3534 6333 6531 6362 3430 8ce70954c3e1cb40
0x04a0: 2664 6f3d 7365 6375 7269 7479 746f 6b65 &do=securitytoke
0x04b0: 6e n
2011-03-14 11:16:09.926769 IP 193.27.1.46.22809 > 193.27.1.44.80: F 1549:1549(0) ack 2433 win 91 <nop,nop,timestamp 211654755 270145421>
0x0000: 4500 0034 d23f 4000 4006 e3f3 c11b 012e E..4.?@. at .......
0x0010: c11b 012c 5919 0050 41f0 4b83 4cdf c051 ...,Y..PA.K.L..Q
0x0020: 8011 005b 311b 0000 0101 080a 0c9d 9863 ...[1..........c
0x0030: 101a 178d ....
2011-03-14 11:16:09.926870 IP 193.27.1.44.80 > 193.27.1.46.22809: . ack 1550 win 36 <nop,nop,timestamp 270145439 211654755>
0x0000: 4500 0034 a05f 4000 4006 15d4 c11b 012c E..4._ at .@......,
0x0010: c11b 012e 0050 5919 4cdf c051 41f0 4b84 .....PY.L..QA.K.
0x0020: 8010 0024 3140 0000 0101 080a 101a 179f ...$1 at ..........
0x0030: 0c9d 9863 ...c
Second attempt (redcafe2 backend)
2011-03-14 11:16:11.923056 IP 193.27.1.46.55567 > 193.27.1.45.80: P 6711:7778(1067) ack 148116 win 757 <nop,nop,timestamp 211655255 270122029>
0x0000: 4500 045f b04c 4000 4006 01bb c11b 012e E.._.L at .@.......
0x0010: c11b 012d d90f 0050 3df9 5730 48af 6a67 ...-...P=.W0H.jg
0x0020: 8018 02f5 88e3 0000 0101 080a 0c9d 9a57 ...............W
0x0030: 1019 bc2d 504f 5354 202f 616a 6178 2e70 ...-POST./ajax.p
0x0040: 6870 2048 5454 502f 312e 310d 0a56 6961 hp.HTTP/1.1..Via
0x0050: 3a20 312e 3120 4150 5352 564d 5933 3530 :.1.1.APSRVMY350
0x0060: 3031 0d0a 436f 6f6b 6965 3a20 5f5f 7574 01..Cookie:.__ut
0x0070: 6d61 3d32 3136 3434 3033 3431 2e35 3833 ma=216440341.583
0x0080: 3438 3337 3634 2e31 3239 3138 3732 3537 483764.129187257
0x0090: 302e 3132 3939 3832 3733 3939 2e31 3330 0.1299827399.130
0x00a0: 3030 3633 3530 312e 3132 333b 205f 5f75 0063501.123;.__u
0x00b0: 746d 7a3d 3231 3634 3430 3334 312e 3132 tmz=216440341.12
0x00c0: 3932 3931 3938 3934 2e31 302e 322e 7574 92919894.10.2.ut
0x00d0: 6d63 636e 3d28 6f72 6761 6e69 6329 7c75 mccn=(organic)|u
...
0x0230: 3742 692d 3332 3335 3438 5f69 2d31 3330 7Bi-323548_i-130
0x0240: 3030 3632 3533 375f 2537 440d 0a52 6566 0062537_%7D..Ref
0x0250: 6572 6572 3a20 6874 7470 3a2f 2f77 7777 erer:.http://www
0x0260: 2e72 6564 6361 6665 2e6e 6574 2f66 382f .redcafe.net/f8/
0x0270: 0d0a 436f 6e74 656e 742d 5479 7065 3a20 ..Content-Type:.
0x0280: 6170 706c 6963 6174 696f 6e2f 782d 7777 application/x-ww
0x0290: 772d 666f 726d 2d75 726c 656e 636f 6465 w-form-urlencode
0x02a0: 643b 2063 6861 7273 6574 3d55 5446 2d38 d;.charset=UTF-8
0x02b0: 0d0a 5573 6572 2d41 6765 6e74 3a20 4d6f ..User-Agent:.Mo
0x02c0: 7a69 6c6c 612f 352e 3020 2857 696e 646f zilla/5.0.(Windo
0x02d0: 7773 3b20 553b 2057 696e 646f 7773 204e ws;.U;.Windows.N
0x02e0: 5420 362e 313b 2065 6e2d 4742 3b20 7276 T.6.1;.en-GB;.rv
0x02f0: 3a31 2e39 2e32 2920 4765 636b 6f2f 3230 :1.9.2).Gecko/20
0x0300: 3130 3031 3135 2046 6972 6566 6f78 2f33 100115.Firefox/3
0x0310: 2e36 0d0a 486f 7374 3a20 7777 772e 7265 .6..Host:.www.re
0x0320: 6463 6166 652e 6e65 740d 0a41 6363 6570 dcafe.net..Accep
0x0330: 743a 2074 6578 742f 6874 6d6c 2c61 7070 t:.text/html,app
0x0340: 6c69 6361 7469 6f6e 2f78 6874 6d6c 2b78 lication/xhtml+x
0x0350: 6d6c 2c61 7070 6c69 6361 7469 6f6e 2f78 ml,application/x
0x0360: 6d6c 3b71 3d30 2e39 2c2a 2f2a 3b71 3d30 ml;q=0.9,*/*;q=0
0x0370: 2e38 0d0a 4163 6365 7074 2d4c 616e 6775 .8..Accept-Langu
0x0380: 6167 653a 2065 6e2d 6762 2c65 6e3b 713d age:.en-gb,en;q=
0x0390: 302e 350d 0a41 6363 6570 742d 4368 6172 0.5..Accept-Char
0x03a0: 7365 743a 2049 534f 2d38 3835 392d 312c set:.ISO-8859-1,
0x03b0: 7574 662d 383b 713d 302e 372c 2a3b 713d utf-8;q=0.7,*;q=
0x03c0: 302e 370d 0a58 2d52 6571 7565 7374 6564 0.7..X-Requested
0x03d0: 2d57 6974 683a 2058 4d4c 4874 7470 5265 -With:.XMLHttpRe
0x03e0: 7175 6573 740d 0a50 7261 676d 613a 206e quest..Pragma:.n
0x03f0: 6f2d 6361 6368 650d 0a43 6163 6865 2d43 o-cache..Cache-C
0x0400: 6f6e 7472 6f6c 3a20 6e6f 2d63 6163 6865 ontrol:.no-cache
0x0410: 0d0a 436f 6e74 656e 742d 4c65 6e67 7468 ..Content-Length
0x0420: 3a20 3832 0d0a 582d 466f 7277 6172 6465 :.82..X-Forwarde
0x0430: 642d 466f 723a 2032 3032 2e31 3638 2e37 d-For:.202.168.7
0x0440: 312e 3137 300d 0a58 2d56 6172 6e69 7368 1.170..X-Varnish
0x0450: 3a20 3430 3335 3230 3532 300d 0a0d 0a :.403520520....
2011-03-14 11:16:11.923115 IP 193.27.1.46.55567 > 193.27.1.45.80: F 7778:7778(0) ack 148116 win 757 <nop,nop,timestamp 211655255 270122029>
0x0000: 4500 0034 b04d 4000 4006 05e5 c11b 012e E..4.M at .@.......
0x0010: c11b 012d d90f 0050 3df9 5b5b 48af 6a67 ...-...P=.[[H.jg
0x0020: 8011 02f5 562f 0000 0101 080a 0c9d 9a57 ....V/.........W
0x0030: 1019 bc2d ...-
2011-03-14 11:16:11.923442 IP 193.27.1.45.80 > 193.27.1.46.55567: . ack 7778 win 137 <nop,nop,timestamp 270122517 211655255>
0x0000: 4500 0034 9178 4000 4006 24ba c11b 012d E..4.x at .@.$....-
0x0010: c11b 012e 0050 d90f 48af 6a67 3df9 5b5b .....P..H.jg=.[[
0x0020: 8010 0089 56b4 0000 0101 080a 1019 be15 ....V...........
0x0030: 0c9d 9a57 ...W
2011-03-14 11:16:11.923454 IP 193.27.1.45.80 > 193.27.1.46.55567: . ack 7779 win 137 <nop,nop,timestamp 270122517 211655255>
0x0000: 4500 0034 9179 4000 4006 24b9 c11b 012d E..4.y at .@.$....-
0x0010: c11b 012e 0050 d90f 48af 6a67 3df9 5b5c .....P..H.jg=.[\
0x0020: 8010 0089 56b3 0000 0101 080a 1019 be15 ....V...........
0x0030: 0c9d 9a57 ...W
More information about the varnish-misc
mailing list