Weird 5 seconds delay

Tue Jul 11 15:26:30 CEST 2017

And of course, I just figured it out after posting. Sorry for the noise !

The problem was DNS resolution, curl does a new DNS query each time and
it looks like the resolver for this server takes 5 seconds to answer,
sometimes. Nothing to do with varnish, my bad

On 07/11/2017 01:57 PM, Kevin Lemonnier 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

-- 

Cordialement,

<http://www.cognix-systems.com/> 	

Kevin LEMONNIER
Administrateur Systèmes, Cognix Systems

*Rennes* | Brest | Saint-Malo | Paris
kevin.lemonnier at cognix-systems.com
<mailto:kevin.lemonnier at cognix-systems.com>

Tél. : 02 99 27 75 92

Facebook Cognix Systems <https://www.facebook.com/cognix.systems/>
Twitter Cognix Systems <https://twitter.com/cognixsystems>
Logo Cognix Systems <http://www.cognix-systems.com/>

-------------- next part --------------
An HTML attachment was scrubbed...
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/22fb103e/attachment.html>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: hchidihi.jpe
Type: image/jpeg
Size: 4935 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/22fb103e/attachment.jpe>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: ihjiiedh.png
Type: image/png
Size: 1444 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/22fb103e/attachment.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: cfeegaaf.png
Type: image/png
Size: 1623 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/22fb103e/attachment-0001.png>
-------------- next part --------------
A non-text attachment was scrubbed...
Name: agdahgjc.png
Type: image/png
Size: 1474 bytes
Desc: not available
URL: <https://www.varnish-cache.org/lists/pipermail/varnish-misc/attachments/20170711/22fb103e/attachment-0002.png>