<div dir="ltr">Looking at the last Timestamp line, Varnish pushed that to the kernel very quickly. What kind of equipment do you have between varnish and curl?<div><br></div><div>To me it sounds like you get a miss once in a while and that's what causing the delay. To debug, I remove the "unset resp.http.x-varnish" you surely have in vcl_deliver. Then test again and find in the logs the exact request with the same x-varnish header.</div><div><br></div><div>If varnish is still outputting the data super fast, try wireshark, and maybe look at open sockets.</div></div><div class="gmail_extra"><br clear="all"><div><div class="gmail_signature" data-smartmail="gmail_signature"><div dir="ltr"><div>-- <br></div>Guillaume Quintard<br></div></div></div>
<br><div class="gmail_quote">On Tue, Jul 11, 2017 at 2:57 PM, Kevin Lemonnier <span dir="ltr"><<a href="mailto:kevin.lemonnier@cognix-systems.com" target="_blank">kevin.lemonnier@cognix-systems.com</a>></span> wrote:<br><blockquote class="gmail_quote" style="margin:0 0 0 .8ex;border-left:1px #ccc solid;padding-left:1ex">Hi,<br>
<br>
I've posted on serverfault and on IRC, but since this is a bit (or very)<br>
urgent, I'll try it here too.<br>
<br>
I have a strange problem with varnish, it's in front of an API and it's<br>
caching the whole responses. It mostly works fine, but from time to time<br>
a request will take 5 seconds (or rarely 10 seconds, or 15 seconds ..<br>
always an increment of 5) more than usual to return.<br>
<br>
I've tried bypassing the HAProxy in front, same, and I checked, it does<br>
that whether the URL is already cached or not (I've checked the Age<br>
header). So it can't be the backend since the page is in cache, it's not<br>
what's in front of varnish, that leaves only varnish itself as the cause<br>
of that problem.<br>
<br>
Any idea as to what could cause that 5 seconds delay ? I've checked<br>
varnishlog, during that delay varnish isn't doing anything. I've also<br>
tried manually making another request during that delay, and varnish<br>
answered fine so it's not frozen or anything, it works fine. And at the<br>
end of that 5 seconds, it's outputting the log for the request as usual,<br>
nothing weird in it. Example :<br>
<br>
* << Request >> 132712<br>
* Begin req 132711 rxreq<br>
* Timestamp Start: 1499701302.309413 0.000000 0.000000<br>
* Timestamp Req: 1499701302.309413 0.000000 0.000000<br>
* ReqStart 127.0.0.1 43955<br>
* ReqMethod GET<br>
* ReqURL /url<br>
* ReqProtocol HTTP/1.1<br>
* ReqHeader User-Agent: curl/7.38.0<br>
* ReqHeader Host: host<br>
* ReqHeader Accept: ///<br>
* ReqHeader X-Forwarded-Proto: https<br>
* ReqHeader X-Forwarded-For: ip<br>
* ReqHeader Connection: close<br>
* ReqUnset X-Forwarded-For: ip<br>
* ReqHeader X-Forwarded-For: ip, 127.0.0.1<br>
* VCL_call RECV<br>
* ReqUnset X-Forwarded-For: ip, 127.0.0.1<br>
* ReqHeader X-Forwarded-For: ip, 127.0.0.1, 127.0.0.1<br>
* VCL_return hash<br>
* VCL_call HASH<br>
* VCL_return lookup<br>
* Hit 2147582482<br>
* VCL_call HIT<br>
* VCL_return deliver<br>
* RespProtocol HTTP/1.1<br>
* RespStatus 200<br>
* RespReason OK<br>
* RespHeader Date: Mon, 10 Jul 2017 15:10:00 GMT<br>
* RespHeader Server: gunicorn/19.7.1<br>
* RespHeader content-type: application/json; charset=UTF-8<br>
* RespHeader X-Varnish: 132712 98834<br>
* RespHeader Age: 1902<br>
* RespHeader Via: 1.1 varnish-v4<br>
* VCL_call DELIVER<br>
* RespHeader X-Cacheable: YES<br>
* RespUnset Server: gunicorn/19.7.1<br>
* RespUnset Via: 1.1 varnish-v4<br>
* RespUnset X-Varnish: 132712 98834<br>
* VCL_return deliver<br>
* Timestamp Process: 1499701302.309480 0.000067 0.000067<br>
* RespHeader Content-Length: 251799<br>
* Debug "RES_MODE 2"<br>
* RespHeader Connection: close<br>
* RespHeader Accept-Ranges: bytes<br>
* Timestamp Resp: 1499701302.309571 0.000159 0.000092<br>
* Debug "XXX REF 2"<br>
* ReqAcct 198 0 198 197 251799 251996<br>
* End<br>
<br>
I realize varnish believes that was treated quickly, but on curl's side<br>
it took 5 seconds. Curl is used directly on the varnish server, so it's<br>
not network latency. It's a bit hard to reproduce, I'm using a script<br>
that does queries in a loop and shows the curl time_total to finally get<br>
it to happen.<br>
<br>
Could it be something Linux side ? Maybe some kind of limit, or a socket<br>
cleanup job or something that would pause the request. It happens maybe<br>
once every 400 or 500 requests, sometimes more, sometimes less.<br>
<br>
Attached is the varnishstat -1 asked on the mailing list page.<br>
<br>
--<br>
Kevin<br>
<br>
<br>
<br>
<br>
<br>
<br>
<br>
<br>
<br>______________________________<wbr>_________________<br>
varnish-misc mailing list<br>
<a href="mailto:varnish-misc@varnish-cache.org">varnish-misc@varnish-cache.org</a><br>
<a href="https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc" rel="noreferrer" target="_blank">https://www.varnish-cache.org/<wbr>lists/mailman/listinfo/<wbr>varnish-misc</a><br></blockquote></div><br></div>