[Varnish] #1297: Negative times and nan in varnishlog tag ReqEnd
Varnish
varnish-bugs at varnish-cache.org
Fri May 3 14:30:57 CEST 2013
#1297: Negative times and nan in varnishlog tag ReqEnd
-----------------------------------+------------------------
Reporter: sthing | Type: defect
Status: new | Priority: normal
Milestone: | Component: varnishlog
Version: 3.0.3 | Severity: normal
Keywords: varnishlog ReqEnd nan |
-----------------------------------+------------------------
Hi.
We are seeing a lot of lines like this:
{{{
7 ReqEnd c 291988160 1367582527.447235107 1367582527.678284168
-0.230976820 nan nan
}}}
The negative time and "nan" values confuse me.
According to https://www.varnish-cache.org/trac/wiki/Varnishlog the last
three fields should be:
The fourth number (0.017112017) is the time elapsed between the session
actually being accept(2)-ed and the start of request processing for this
request. Keep in mind that sessions are only accept()ed once, so this is
time from the initial request was accepted until the current request begun
processing (in other words: other requests from the same client/session
could have been processed in the meanwhile).
The fifth number (0.000022888) is the time elapsed from the start of the
request processing until we start delivering the object to the client. For
all practical purposes, this number is the backend response time.
The sixth and last number (0.000025988) is the time from we start
delivering the object until the request completes.
The issue was mentioned in ticket #843, which was closed 13 months ago.
However that issue was about ESI not being handled.
We do use ESI on the page, and it works fine.
The server is running FreeBSD 9.1. It is a development server, no
noticeable load.
Here is the varnishlog output for one of the requests:
{{{
8 BackendClose - default
8 BackendOpen b default 192.168.1.213 44859 192.168.1.213 80
8 TxRequest b GET
8 TxURL b /da/shop/product/01-00866
8 TxProtocol b HTTP/1.1
8 TxHeader b Host: shop-elstock.thing.varnish.netimage.dk
8 TxHeader b Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
8 TxHeader b User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.63 Safari/537.31
8 TxHeader b Referer: http://shop-
elstock.thing.varnish.netimage.dk/da/
8 TxHeader b Accept-Language: da-DK,da;q=0.8,en-US;q=0.6,en;q=0.4
8 TxHeader b Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
8 TxHeader b Cookie: PHPSESSID=ds3iu1hp9g168v43k2ufcsuu07
8 TxHeader b X-Forwarded-For: 192.168.1.1
8 TxHeader b X-DeviceGroup: pc
8 TxHeader b X-Device: pc
8 TxHeader b X-Varnish: 291988160
8 TxHeader b Accept-Encoding: gzip
8 RxProtocol b HTTP/1.1
8 RxStatus b 200
8 RxResponse b OK
8 RxHeader b Date: Fri, 03 May 2013 12:02:07 GMT
8 RxHeader b Server: Apache
8 RxHeader b X-Powered-By: PHP/5.4.11
8 RxHeader b Expires: Thu, 19 Nov 1981 08:52:00 GMT
8 RxHeader b Cache-Control: no-store, no-cache, must-revalidate,
post-check=0, pre-check=0
8 RxHeader b Pragma: no-cache
8 RxHeader b Vary: Accept-Encoding
8 RxHeader b Content-Encoding: gzip
8 RxHeader b Content-Length: 3502
8 RxHeader b Content-Type: text/html; charset=UTF-8
8 Fetch_Body b 4(length) cls 0 mklen 1
8 Length b 3741
8 BackendReuse b default
7 SessionOpen c 192.168.1.1 54637 192.168.1.216:80
7 ReqStart c 192.168.1.1 54637 291988160
7 RxRequest c GET
7 RxURL c /da/shop/product/01-00866
7 RxProtocol c HTTP/1.1
7 RxHeader c Host: shop-elstock.thing.varnish.netimage.dk
7 RxHeader c Connection: keep-alive
7 RxHeader c Accept:
text/html,application/xhtml+xml,application/xml;q=0.9,*/*;q=0.8
7 RxHeader c User-Agent: Mozilla/5.0 (X11; Linux x86_64)
AppleWebKit/537.31 (KHTML, like Gecko) Chrome/26.0.1410.63 Safari/537.31
7 RxHeader c Referer: http://shop-
elstock.thing.varnish.netimage.dk/da/
7 RxHeader c Accept-Encoding: gzip,deflate,sdch
7 RxHeader c Accept-Language: da-DK,da;q=0.8,en-US;q=0.6,en;q=0.4
7 RxHeader c Accept-Charset: ISO-8859-1,utf-8;q=0.7,*;q=0.3
7 RxHeader c Cookie: PHPSESSID=ds3iu1hp9g168v43k2ufcsuu07
7 VCL_call c recv
7 VCL_acl c MATCH allow_from_IP 192.168.1.0/24
7 VCL_return c lookup
7 VCL_call c hash
7 Hash c /da/shop/product/01-00866
7 Hash c shop-elstock.thing.varnish.netimage.dk
7 VCL_return c hash
7 VCL_call c miss fetch
7 Backend c 8 default default
7 TTL c 291988160 RFC 0 -1 -1 1367582528 0 1367582527
375007920 0
7 VCL_call c fetch
7 TTL c 291988160 VCL 120 -1 -1 1367582527 -0
7 VCL_return c hit_for_pass
7 ObjProtocol c HTTP/1.1
7 ObjResponse c OK
7 ObjHeader c Date: Fri, 03 May 2013 12:02:07 GMT
7 ObjHeader c Server: Apache
7 ObjHeader c X-Powered-By: PHP/5.4.11
7 ObjHeader c Expires: Thu, 19 Nov 1981 08:52:00 GMT
7 ObjHeader c Cache-Control: no-store, no-cache, must-revalidate,
post-check=0, pre-check=0
7 ObjHeader c Pragma: no-cache
7 ObjHeader c Vary: Accept-Encoding
7 ObjHeader c Content-Encoding: gzip
7 ObjHeader c Content-Length: 3502
7 ObjHeader c Content-Type: text/html; charset=UTF-8
7 Gzip c U F E 3502 12776 80 80 27950
7 Gzip c G F E 12776 3741 80 29848 29858
7 VCL_call c deliver deliver
7 TxProtocol c HTTP/1.1
7 TxStatus c 200
7 TxResponse c OK
7 TxHeader c Server: Apache
7 TxHeader c X-Powered-By: PHP/5.4.11
7 TxHeader c Expires: Thu, 19 Nov 1981 08:52:00 GMT
7 TxHeader c Cache-Control: no-store, no-cache, must-revalidate,
post-check=0, pre-check=0
7 TxHeader c Pragma: no-cache
7 TxHeader c Vary: Accept-Encoding
7 TxHeader c Content-Encoding: gzip
7 TxHeader c Content-Type: text/html; charset=UTF-8
7 TxHeader c Transfer-Encoding: chunked
7 TxHeader c Date: Fri, 03 May 2013 12:02:07 GMT
7 TxHeader c X-Varnish: 291988160
7 TxHeader c Age: 0
7 TxHeader c Via: 1.1 varnish
7 TxHeader c Connection: keep-alive
7 VCL_call c recv
7 VCL_acl c MATCH allow_from_IP 192.168.1.0/24
7 VCL_return c lookup
7 VCL_call c hash
7 Hash c ds3iu1hp9g168v43k2ufcsuu07
7 Hash c /index.php?page_label=esi_status
7 Hash c shop-elstock.thing.varnish.netimage.dk
7 VCL_return c hash
7 Hit c 291988155
7 VCL_call c hit deliver
7 VCL_call c deliver deliver
7 Length c 0
7 ReqEnd c 291988160 1367582527.447235107 1367582527.678284168
-0.230976820 nan nan
7 Debug c herding
7 Interrupted c ReqStart
}}}
--
Ticket URL: <https://www.varnish-cache.org/trac/ticket/1297>
Varnish <https://varnish-cache.org/>
The Varnish HTTP Accelerator
More information about the varnish-bugs
mailing list