varnishncsa bad Time taken to serve the request
César Sepúlveda
csepulveda at mediastre.am
Mon Aug 11 20:41:36 CEST 2014
we use a fresh ubuntu install, with only one client making the request and
we have the same results.
Fresh Ubuntu 12.04 and last varnish 3.0.5.
imac-de-cesar:~ csepulveda$ wget --limit-rate=1k
http://10.0.1.78/thumbs/538907ff2982d00322387b34/2014711/thumb_53c0285317259d33326158f2_original_1768s.jpg
--2014-08-11 14:32:36--
http://10.0.1.78/thumbs/538907ff2982d00322387b34/2014711/thumb_53c0285317259d33326158f2_original_1768s.jpg
Connecting to 10.0.1.78:80... connected.
HTTP request sent, awaiting response... 200 OK
Length: 18111 (18K) [image/jpeg]
Saving to: ‘thumb_53c0285317259d33326158f2_original_1768s.jpg.9’
100%[=====================================================================================>]
18,111 1024B/s * in 18s*
2014-08-11 14:32:53 (1024 B/s) -
‘thumb_53c0285317259d33326158f2_original_1768s.jpg.9’ saved [18111/18111]
.......
11 SessionOpen c 10.0.1.135 60525 :80
11 ReqStart c 10.0.1.135 60525 1340317141
11 RxRequest c GET
11 RxURL c
/thumbs/538907ff2982d00322387b34/2014711/thumb_53c0285317259d33326158f2_original_1768s.jpg
11 RxProtocol c HTTP/1.1
11 RxHeader c User-Agent: Wget/UNKNOWN (darwin12.2.0)
11 RxHeader c Accept: */*
11 RxHeader c Host: 10.0.1.78
11 RxHeader c Connection: Keep-Alive
11 VCL_call c recv lookup
11 VCL_call c hash
11 Hash c
/thumbs/538907ff2982d00322387b34/2014711/thumb_53c0285317259d33326158f2_original_1768s.jpg
11 Hash c 10.0.1.78
11 VCL_return c hash
11 Hit c 1340317139
11 VCL_call c hit deliver
11 VCL_call c deliver deliver
11 TxProtocol c HTTP/1.1
11 TxStatus c 200
11 TxResponse c OK
11 TxHeader c Content-Type: image/jpeg
11 TxHeader c Last-Modified: Fri, 11 Jul 2014 18:09:25 GMT
11 TxHeader c Expires: Thu, 31 Dec 2037 23:55:55 GMT
11 TxHeader c Cache-Control: max-age=315360000, public,
must-revalidate, proxy-revalidate
11 TxHeader c Pragma: public
11 TxHeader c Content-Length: 18111
11 TxHeader c Accept-Ranges: bytes
11 TxHeader c Date: Mon, 11 Aug 2014 18:32:36 GMT
11 TxHeader c X-Varnish: 1340317141 1340317139
11 TxHeader c Age: 2451
11 TxHeader c Via: 1.1 varnish
11 TxHeader c Connection: keep-alive
11 Length c 18111
11 ReqEnd c 1340317141 1407781956.576860905 1407781956.577031851
0.000064373 0.000036240 *0.000134706*
11 Debug c herding
11 SessionClose c timeout
11 StatSess c 10.0.1.135 60525 0 1 1 0 0 0 393 18111
ubuntu 12.04 and last varnish 4.0.1-2
* << Request >> 2
- Begin req 1 rxreq
- Timestamp Start: 1407782319.675061 0.000000 0.000000
- Timestamp Req: 1407782319.675061 0.000000 0.000000
- ReqStart 10.0.1.135 60616
- ReqMethod GET
- ReqURL
/thumbs/538907ff2982d00322387b34/2014711/thumb_53c0285317259d33326158f2_original_1768s.jpg
- ReqProtocol HTTP/1.1
- ReqHeader User-Agent: Wget/UNKNOWN (darwin12.2.0)
- ReqHeader Accept: */*
- ReqHeader Host: 10.0.1.78
- ReqHeader Connection: Keep-Alive
- ReqHeader X-Forwarded-For: 10.0.1.135
- VCL_call RECV
- VCL_return hash
- VCL_call HASH
- VCL_return lookup
- Debug "XXXX MISS"
- VCL_call MISS
- VCL_return fetch
- Link bereq 3 fetch
- Timestamp Fetch: 1407782319.683342 0.008281 0.008281
- RespProtocol HTTP/1.1
- RespStatus 200
- RespReason OK
- RespHeader Content-Type: image/jpeg
- RespHeader Last-Modified: Fri, 11 Jul 2014 18:09:25 GMT
- RespHeader Expires: Thu, 31 Dec 2037 23:55:55 GMT
- RespHeader Cache-Control: max-age=315360000, public,
must-revalidate, proxy-revalidate
- RespHeader Pragma: public
- RespHeader Date: Mon, 11 Aug 2014 18:38:39 GMT
- RespHeader X-Varnish: 2
- RespHeader Age: 2814
- RespHeader Via: 1.1 varnish-v4
- VCL_call DELIVER
- VCL_return deliver
- Timestamp Process: 1407782319.700854 0.025793 0.017512
- RespHeader Content-Length: 18111
- Debug "RES_MODE 2"
- RespHeader Connection: keep-alive
- RespHeader Accept-Ranges: bytes
- Timestamp Resp: 1407782319.701260 0.026199 0.000406
- Debug "XXX REF 2"
- ReqAcct 202 0 202 376 18111 18487
- End
We need the most real Time taken to serve the request, do you know if i can
get it from another place?
Thanks!.
--
César Sepúlveda
Jefe de Plataforma
Mediastream Chile
Email: csepulveda at mediastre.am
Teléfono: +56 2 24029750
2014-08-11 9:19 GMT-04:00 César Sepúlveda <csepulveda at mediastre.am>:
> Hi guys.
>
> Anyone can help me, or has the same issue?
>
> Thanks!!.
>
> --
> César Sepúlveda
> Jefe de Plataforma
> Mediastream Chile
>
> Email: csepulveda at mediastre.am
> Teléfono: +56 2 24029750
>
>
> 2014-08-08 10:31 GMT-04:00 César Sepúlveda <csepulveda at mediastre.am>:
>
> a video... my english is not too good.
>>
>> https://copy.com/uaaM3nMGVAuZ8ntk
>>
>> --
>> César Sepúlveda
>> Jefe de Plataforma
>> Mediastream Chile
>>
>> Email: csepulveda at mediastre.am
>> Teléfono: +56 2 24029750
>>
>>
>> 2014-08-08 10:21 GMT-04:00 César Sepúlveda <csepulveda at mediastre.am>:
>>
>> Hi guys!.
>>>
>>> we are using varnish 3.0.5 and have an issue with Time taken to serve
>>> the request parameter (%D)
>>>
>>> we realized that the varnishncsa log is written before the download is
>>> complete: example
>>>
>>>
>>> the download:
>>> imac-de-cesar:~ csepulveda$ wget --limit-rate=100k
>>> http://xxx.xxx.com/assets/img/promo-win.jpg
>>> --2014-08-08 09:55:27-- http://xxxx.xxxx.com/assets/img/promo-win.jpg
>>> Resolving xxx.xxx.com... xx.xx.xx.xx.
>>> Connecting to xxx. xxx.com|xx.xx.xx.xx|:80... connected.
>>> HTTP request sent, awaiting response... 200 OK
>>> Length: 383810 (375K) [image/jpeg]
>>> Saving to: ‘promo-win.jpg.2’
>>>
>>> 100%[=========================================================================>]
>>> 383,810 101KB/s in 3.7s
>>>
>>> 2014-08-08 09:55:31 (101 KB/s) - ‘promo-win.jpg.2’ saved [383810/383810]
>>>
>>>
>>> The log:
>>> xx.xx.xx.xx "xx.xx.xx.xx" - [08/Aug/2014:13:55:33 +0000] "GET
>>> http://xxx.xxxx.com/assets/img/promo-win.jpg HTTP/1.0" 200 383810 "-"
>>> "Wget/UNKNOWN (darwin12.2.0)" 0.401839018 miss 0.785520
>>>
>>> The download take 3.7 seconds but varnishncsa show 0.785520.watching
>>> this with tail -f we see the log is writen when the download go on 5 or 8
>>> percent.
>>>
>>> The varnishncsa format is this:
>>> FORMAT="%h \"%{X-Forwarded-For}i\" %u %t \"%r\" %s %b \"%{Referer}i\"
>>> \"%{User-agent}i\" %{Varnish:time_firstbyte}x %{Varnish:handling}x %D"
>>>
>>> what we are doing wrong?
>>> can you help us?
>>>
>>> Thanks!.
>>>
>>> --
>>> César Sepúlveda
>>> Jefe de Plataforma
>>> Mediastream Chile
>>>
>>> Email: csepulveda at mediastre.am
>>> Teléfono: +56 2 24029750
>>>
>>
>>
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140811/53dd572f/attachment-0001.html>
More information about the varnish-misc
mailing list