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