Kristian, please let me know whether I should file a ticket for this. - Stig
On Mon, Dec 20, 2010 at 4:14 PM, Stig Bakken <[email protected]> wrote: > On Mon, Dec 20, 2010 at 9:25 AM, Kristian Lyngstol < > [email protected]> wrote: > >> On Fri, Dec 17, 2010 at 03:40:35PM +0100, Stig Bakken wrote: >> > I have a script processing varnishlog output to give me the serving >> > latency based on the ReqEnd tag, and frequently see objects served from >> > cache, size around 25kB, that take 5+ seconds to serve. >> >> If there are two requests for an object, request A and request B, the >> following will happen: >> >> Time | Action >> 0s | A asks for /foo >> | Cache-miss - fetch from backend >> 0.5s | B asks for /foo >> | Cache hit on busy object - wait for it >> 5s | Web server is finished delivering /foo >> 5.1s | A gets /foo - cache miss >> 5.1s | B gets /foo - cache hit >> >> It's a bit difficult to spot this as it happens, it's been a matter of >> discussion recently (Arthur being the one who first became aware of the >> issue). >> >> It sounds like this might be what you are seeing. >> > > Here are some more details. The attached file is an edited varnishlog > dump, with elapsed time appended after each ReqEnd. Notice that one of the > requests takes 137 seconds, during which time all of the others in the dump > complete much faster. The Age: header is high, which rules out the cache > injection race condition, right? > > This is with 2.1.4 installed from the official rpm on RHEL, btw. > > - Stig > > > -- > Stig Bakken > CTO, Zedge.net - free your phone! > -- Stig Bakken CTO, Zedge.net - free your phone!
_______________________________________________ varnish-misc mailing list [email protected] http://www.varnish-cache.org/lists/mailman/listinfo/varnish-misc
