Weird 5 seconds delay

[Guillaume Quintard]

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?

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.

If varnish is still outputting the data super fast, try wireshark, and
maybe look at open sockets.

-- 
Guillaume Quintard

On Tue, Jul 11, 2017 at 2:57 PM, Kevin Lemonnier <
kevin.lemonnier at cognix-systems.com> wrote:

> Hi,
>
> I've posted on serverfault and on IRC, but since this is a bit (or very)
> urgent, I'll try it here too.
>
> I have a strange problem with varnish, it's in front of an API and it's
> caching the whole responses. It mostly works fine, but from time to time
> a request will take 5 seconds (or rarely 10 seconds, or 15 seconds ..
> always an increment of 5) more than usual to return.
>
> I've tried bypassing the HAProxy in front, same, and I checked, it does
> that whether the URL is already cached or not (I've checked the Age
> header). So it can't be the backend since the page is in cache, it's not
> what's in front of varnish, that leaves only varnish itself as the cause
> of that problem.
>
> Any idea as to what could cause that 5 seconds delay ? I've checked
> varnishlog, during that delay varnish isn't doing anything. I've also
> tried manually making another request during that delay, and varnish
> answered fine so it's not frozen or anything, it works fine. And at the
> end of that 5 seconds, it's outputting the log for the request as usual,
> nothing weird in it. Example :
>
>   * << Request >> 132712
>   * Begin req 132711 rxreq
>   * Timestamp Start: 1499701302.309413 0.000000 0.000000
>   * Timestamp Req: 1499701302.309413 0.000000 0.000000
>   * ReqStart 127.0.0.1 43955
>   * ReqMethod GET
>   * ReqURL /url
>   * ReqProtocol HTTP/1.1
>   * ReqHeader User-Agent: curl/7.38.0
>   * ReqHeader Host: host
>   * ReqHeader Accept: ///
>   * ReqHeader X-Forwarded-Proto: https
>   * ReqHeader X-Forwarded-For: ip
>   * ReqHeader Connection: close
>   * ReqUnset X-Forwarded-For: ip
>   * ReqHeader X-Forwarded-For: ip, 127.0.0.1
>   * VCL_call RECV
>   * ReqUnset X-Forwarded-For: ip, 127.0.0.1
>   * ReqHeader X-Forwarded-For: ip, 127.0.0.1, 127.0.0.1
>   * VCL_return hash
>   * VCL_call HASH
>   * VCL_return lookup
>   * Hit 2147582482
>   * VCL_call HIT
>   * VCL_return deliver
>   * RespProtocol HTTP/1.1
>   * RespStatus 200
>   * RespReason OK
>   * RespHeader Date: Mon, 10 Jul 2017 15:10:00 GMT
>   * RespHeader Server: gunicorn/19.7.1
>   * RespHeader content-type: application/json; charset=UTF-8
>   * RespHeader X-Varnish: 132712 98834
>   * RespHeader Age: 1902
>   * RespHeader Via: 1.1 varnish-v4
>   * VCL_call DELIVER
>   * RespHeader X-Cacheable: YES
>   * RespUnset Server: gunicorn/19.7.1
>   * RespUnset Via: 1.1 varnish-v4
>   * RespUnset X-Varnish: 132712 98834
>   * VCL_return deliver
>   * Timestamp Process: 1499701302.309480 0.000067 0.000067
>   * RespHeader Content-Length: 251799
>   * Debug "RES_MODE 2"
>   * RespHeader Connection: close
>   * RespHeader Accept-Ranges: bytes
>   * Timestamp Resp: 1499701302.309571 0.000159 0.000092
>   * Debug "XXX REF 2"
>   * ReqAcct 198 0 198 197 251799 251996
>   * End
>
> I realize varnish believes that was treated quickly, but on curl's side
> it took 5 seconds. Curl is used directly on the varnish server, so it's
> not network latency. It's a bit hard to reproduce, I'm using a script
> that does queries in a loop and shows the curl time_total to finally get
> it to happen.
>
> Could it be something Linux side ? Maybe some kind of limit, or a socket
> cleanup job or something that would pause the request. It happens maybe
> once every 400 or 500 requests, sometimes more, sometimes less.
>
> Attached is the varnishstat -1 asked on the mailing list page.
>
> --
> Kevin
>
>
>
>
>
>
>
>
>
> _______________________________________________
> varnish-misc mailing list
> varnish-misc at varnish-cache.org
> https://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
>
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/c23e7fad/attachment-0001.html>