Analyse ReqEnd in Varnishlog

Sun Mar 18 09:46:21 CET 2012

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.

This is what varnishlog shown me:

  319 ReqEnd       c 1168207229 1332059091.889164209 1332059091.921136379
3.414758205 0.031944752 0.000027418

I have read through https://www.varnish-cache.org/trac/wiki/Varnishlog 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.

I am using Varnish 3.0.2, below is the related varnishlog output if you are
interested to find out more:

=====================================================
 3603 TxRequest    - GET
 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
 3603 TxProtocol   - HTTP/1.1
 3603 TxHeader     - x-requested-with: XMLHttpRequest
 3603 TxHeader     - Accept-Language: en-sg
 3603 TxHeader     - Referer:
http://hosthidden.net/player-tote/tote/main/7293
 3603 TxHeader     - Accept: application/json, text/javascript, */*; q=0.01
 3603 TxHeader     - Content-Type:
application/x-www-form-urlencoded;charset=utf-8
 3603 TxHeader     - Accept-Encoding: gzip, deflate
 3603 TxHeader     - User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows
NT 6.1; Trident/5.0; MALC)
 3603 TxHeader     - Host: hosthidden.net
 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;
 3603 TxHeader     - X-Forwarded-For: 119.74.200.110 , 220.255.2.25,
172.16.16.236
 3603 TxHeader     - X-Cookie.ViewMode: dollar
 3603 TxHeader     - X-Cookie.Lang: en_US
 3603 TxHeader     - X-Varnish: 1168207229

  319 ReqStart     c 172.16.16.236 16818 1168207229
  319 RxRequest    c GET
  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
  319 RxProtocol   c HTTP/1.1
  319 RxHeader     c x-requested-with: XMLHttpRequest
  319 RxHeader     c Accept-Language: en-sg
  319 RxHeader     c Referer:
http://hosthidden.net/player-tote/tote/main/7293
  319 RxHeader     c Accept: application/json, text/javascript, */*; q=0.01
  319 RxHeader     c Content-Type:
application/x-www-form-urlencoded;charset=utf-8
  319 RxHeader     c Accept-Encoding: gzip, deflate
  319 RxHeader     c User-Agent: Mozilla/5.0 (compatible; MSIE 9.0; Windows
NT 6.1; Trident/5.0; MALC)
  319 RxHeader     c Host: hosthidden.net
  319 RxHeader     c Connection: Keep-Alive
  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;
  319 RxHeader     c X-Forwarded-For: 119.74.200.110 , 220.255.2.25
  319 VCL_call     c recv pass
  319 VCL_call     c hash
  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
  319 Hash         c dollar
  319 Hash         c en_US
  319 VCL_return   c hash
  319 VCL_call     c pass pass
  319 Backend      c 3603 member member31
  319 TTL          c 1168207229 RFC 0 -1 -1 1332059092 0 1332059091
869893200 0
  319 VCL_call     c fetch
  319 TTL          c 1168207229 VCL 86400 -1 -1 1332059092 -0
  319 VCL_return   c deliver
  319 ObjProtocol  c HTTP/1.1
  319 ObjResponse  c OK
  319 ObjHeader    c Server: GlassFish Server Open Source Edition 3.1.2
  319 ObjHeader    c i: 191
  319 ObjHeader    c spero-elapse-time: 30.233ms
  319 ObjHeader    c Pragma: no-cache
  319 ObjHeader    c Cache-Control: no-cache
  319 ObjHeader    c Expires: Mon, 26 Jul 1997 05:00:00 GMT
  319 ObjHeader    c X-Last-Serial: 1118320844
  319 ObjHeader    c Content-Type: text/javascript;charset=UTF-8
  319 ObjHeader    c Content-Language: en-SG
  319 ObjHeader    c Content-Length: 171
  319 ObjHeader    c Date: Sun, 18 Mar 2012 08:24:51 GMT
  319 VCL_call     c deliver deliver
  319 TxProtocol   c HTTP/1.1
  319 TxStatus     c 200
  319 TxResponse   c OK
  319 TxHeader     c Server: GlassFish Server Open Source Edition 3.1.2
  319 TxHeader     c i: 191
  319 TxHeader     c spero-elapse-time: 30.233ms
  319 TxHeader     c Pragma: no-cache
  319 TxHeader     c Cache-Control: no-cache
  319 TxHeader     c Expires: Mon, 26 Jul 1997 05:00:00 GMT
  319 TxHeader     c X-Last-Serial: 1118320844
  319 TxHeader     c Content-Type: text/javascript;charset=UTF-8
  319 TxHeader     c Content-Language: en-SG
  319 TxHeader     c Content-Length: 171
  319 TxHeader     c Accept-Ranges: bytes
  319 TxHeader     c Date: Sun, 18 Mar 2012 08:24:51 GMT
  319 TxHeader     c X-Varnish: 1168207229
  319 TxHeader     c Age: 0
  319 TxHeader     c Via: 1.1 varnish
  319 TxHeader     c Connection: keep-alive
  319 Length       c 171
  319 ReqEnd       c 1168207229 1332059091.889164209 1332059091.921136379
3.414758205 0.031944752 0.000027418
=====================================================
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20120318/26d20b53/attachment.html>