We recently found out that a specific request occasionally have slowness, looking at the varnishlog it tells that backend is not the root cause of this problem. This request is not set to be cached in Varnish, thus pass to backend directly.<div>
<br></div><div>This is what varnishlog shown me:<br><div><br></div><div> 319 ReqEnd c 1168207229 1332059091.889164209 1332059091.921136379 3.414758205 0.031944752 0.000027418<br><div><br></div><div>I have read through <a href="https://www.varnish-cache.org/trac/wiki/Varnishlog">https://www.varnish-cache.org/trac/wiki/Varnishlog</a> but couldn't understand well on the meaning of the fourth number (3.414758205). I am hoping to find out what has actually caused 3.414758205 seconds delay in this case.</div>
</div></div><div><br></div><div>I am using Varnish 3.0.2, below is the related varnishlog output if you are interested to find out more:</div><div><br></div><div>=====================================================</div>
<div><div> 3603 TxRequest - GET</div><div> 3603 TxURL - /player-tote-backend/s/order/placeOrderWP?serial=-1954678523&data=%7B%22list%22%3A%5B%7B%22selNum%22%3A2%2C%22win%22%3A1%2C%22place%22%3A1%2C%22price%22%3A0.76%2C%22lwin%22%3A11%2C%22lplace%22%3A3%2C%22row%22%3A1%7D%5D%2C%22type%22%3A%22BET%22%2C%22cardId</div>
<div> 3603 TxProtocol - HTTP/1.1</div><div> 3603 TxHeader - x-requested-with: XMLHttpRequest</div><div> 3603 TxHeader - Accept-Language: en-sg</div><div> 3603 TxHeader - Referer: <a href="http://hosthidden.net/player-tote/tote/main/7293">http://hosthidden.net/player-tote/tote/main/7293</a></div>
<div> 3603 TxHeader - Accept: application/json, text/javascript, */*; q=0.01</div><div> 3603 TxHeader - Content-Type: application/x-www-form-urlencoded;charset=utf-8</div><div> 3603 TxHeader - Accept-Encoding: gzip, deflate</div>
<div> 3603 TxHeader - User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0; MALC)</div><div> 3603 TxHeader - Host: <a href="http://hosthidden.net">hosthidden.net</a></div><div> 3603 TxHeader - Cookie: __utma=1.1015690728.1332058884.1332058884.1332058884.1; __utmb=1.3.10.1332058884; __utmz=1.1332058884.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); JSESSIONID=4e6117aadd6cb6652f0c9c32ff79; sto-id-RACING_LOGIN_Varnish_GRP04=IDBABAKM; __utmc=1;</div>
<div> 3603 TxHeader - X-Forwarded-For: 119.74.200.110 , 220.255.2.25, 172.16.16.236</div><div> 3603 TxHeader - X-Cookie.ViewMode: dollar</div><div> 3603 TxHeader - X-Cookie.Lang: en_US</div><div> 3603 TxHeader - X-Varnish: 1168207229</div>
<div><br></div><div> 319 ReqStart c 172.16.16.236 16818 1168207229</div><div> 319 RxRequest c GET</div><div> 319 RxURL c /player-tote-backend/s/order/placeOrderWP?serial=-1954678523&data=%7B%22list%22%3A%5B%7B%22selNum%22%3A2%2C%22win%22%3A1%2C%22place%22%3A1%2C%22price%22%3A0.76%2C%22lwin%22%3A11%2C%22lplace%22%3A3%2C%22row%22%3A1%7D%5D%2C%22type%22%3A%22BET%22%2C%22cardId</div>
<div> 319 RxProtocol c HTTP/1.1</div><div> 319 RxHeader c x-requested-with: XMLHttpRequest</div><div> 319 RxHeader c Accept-Language: en-sg</div><div> 319 RxHeader c Referer: <a href="http://hosthidden.net/player-tote/tote/main/7293">http://hosthidden.net/player-tote/tote/main/7293</a></div>
<div> 319 RxHeader c Accept: application/json, text/javascript, */*; q=0.01</div><div> 319 RxHeader c Content-Type: application/x-www-form-urlencoded;charset=utf-8</div><div> 319 RxHeader c Accept-Encoding: gzip, deflate</div>
<div> 319 RxHeader c User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows NT 6.1; Trident/5.0; MALC)</div><div> 319 RxHeader c Host: <a href="http://hosthidden.net">hosthidden.net</a></div><div> 319 RxHeader c Connection: Keep-Alive</div>
<div> 319 RxHeader c Cookie: __utma=1.1015690728.1332058884.1332058884.1332058884.1; __utmb=1.3.10.1332058884; __utmz=1.1332058884.1.1.utmcsr=(direct)|utmccn=(direct)|utmcmd=(none); JSESSIONID=4e6117aadd6cb6652f0c9c32ff79; sto-id-RACING_LOGIN_Varnish_GRP04=IDBABAKM; __utmc=1;</div>
<div> 319 RxHeader c X-Forwarded-For: 119.74.200.110 , 220.255.2.25</div><div> 319 VCL_call c recv pass</div><div> 319 VCL_call c hash</div><div> 319 Hash c /player-tote-backend/s/order/placeOrderWP?serial=-1954678523&data=%7B%22list%22%3A%5B%7B%22selNum%22%3A2%2C%22win%22%3A1%2C%22place%22%3A1%2C%22price%22%3A0.76%2C%22lwin%22%3A11%2C%22lplace%22%3A3%2C%22row%22%3A1%7D%5D%2C%22type%22%3A%22BET%22%2C%22cardI</div>
<div> 319 Hash c dollar</div><div> 319 Hash c en_US</div><div> 319 VCL_return c hash</div><div> 319 VCL_call c pass pass</div><div> 319 Backend c 3603 member member31</div><div> 319 TTL c 1168207229 RFC 0 -1 -1 1332059092 0 1332059091 869893200 0</div>
<div> 319 VCL_call c fetch</div><div> 319 TTL c 1168207229 VCL 86400 -1 -1 1332059092 -0</div><div> 319 VCL_return c deliver</div><div> 319 ObjProtocol c HTTP/1.1</div><div> 319 ObjResponse c OK</div>
<div> 319 ObjHeader c Server: GlassFish Server Open Source Edition 3.1.2</div><div> 319 ObjHeader c i: 191</div><div> 319 ObjHeader c spero-elapse-time: 30.233ms</div><div> 319 ObjHeader c Pragma: no-cache</div>
<div> 319 ObjHeader c Cache-Control: no-cache</div><div> 319 ObjHeader c Expires: Mon, 26 Jul 1997 05:00:00 GMT</div><div> 319 ObjHeader c X-Last-Serial: 1118320844</div><div> 319 ObjHeader c Content-Type: text/javascript;charset=UTF-8</div>
<div> 319 ObjHeader c Content-Language: en-SG</div><div> 319 ObjHeader c Content-Length: 171</div><div> 319 ObjHeader c Date: Sun, 18 Mar 2012 08:24:51 GMT</div><div> 319 VCL_call c deliver deliver</div><div>
319 TxProtocol c HTTP/1.1</div><div> 319 TxStatus c 200</div><div> 319 TxResponse c OK</div><div> 319 TxHeader c Server: GlassFish Server Open Source Edition 3.1.2</div><div> 319 TxHeader c i: 191</div>
<div> 319 TxHeader c spero-elapse-time: 30.233ms</div><div> 319 TxHeader c Pragma: no-cache</div><div> 319 TxHeader c Cache-Control: no-cache</div><div> 319 TxHeader c Expires: Mon, 26 Jul 1997 05:00:00 GMT</div>
<div> 319 TxHeader c X-Last-Serial: 1118320844</div><div> 319 TxHeader c Content-Type: text/javascript;charset=UTF-8</div><div> 319 TxHeader c Content-Language: en-SG</div><div> 319 TxHeader c Content-Length: 171</div>
<div> 319 TxHeader c Accept-Ranges: bytes</div><div> 319 TxHeader c Date: Sun, 18 Mar 2012 08:24:51 GMT</div><div> 319 TxHeader c X-Varnish: 1168207229</div><div> 319 TxHeader c Age: 0</div><div> 319 TxHeader c Via: 1.1 varnish</div>
<div> 319 TxHeader c Connection: keep-alive</div><div> 319 Length c 171</div><div> 319 ReqEnd c 1168207229 1332059091.889164209 1332059091.921136379 3.414758205 0.031944752 0.000027418</div></div><div>===================================================== <br>
</div><div><br></div><div><br></div>