varnishncsa bad Time taken to serve the request

[Per Buer]

Hi.

I tested this on repo.varnish-cache.org:

$ time wget --limit-rate=100k
http://repo.varnish-cache.org/debian/pool/varnish-4.0/v/varnish/varnish_4.0.0.orig.tar.gz
...

real 0m23.472s

Then from Varnishlog:
..
   22 ReqEnd       c 315341679 1407768801.649216652 1407768818.704510689
0.000195265 0.037013054 *17.018280983*
..

So. Your findings make sense. I think, but I'm not 100% certain, that the
difference in time is due to buffering, especially on the server end. The
kernel will swallow up a lot of writes that Varnish do and the thread then
thinks it is actually done. Since the thread doesn't close the connection
it won't block the worker.

I think the kernel will block on connection close to make sure the client
has gotten all the data but at that point the connection has been handed
back to the pool.

As I said, I'm not 100% that this is the correct explanation. But I'm
pretty certain it works like this and if I'm right it is not a bug,
strictly speaking.



On Mon, Aug 11, 2014 at 3:19 PM, César Sepúlveda <csepulveda at mediastre.am>
wrote:

> 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
>>>
>>
>>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>



-- 
 <http://www.varnish-software.com/> *Per Buer*
CTO | Varnish Software
Phone: +47 958 39 117 | Skype: per.buer
We Make Websites Fly!

Winner of the Red Herring Top 100 Global Award 2013
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20140811/11e0a09a/attachment-0001.html>