HSH_Lookup entered multiply - why could that happen?

2009-12-09 Thread Nils Goroll
Hi,

I am trying to understand under which circumstances in Varnish 2.0.3 HSH_Lookup 
could get entered entered multiply in succession in a restart-scenatio. The 
effect I am seeing is duplication of session objects on the waitinglist.

I was also considering duplication of output lines, but if I add a high 
resolution time stamp in HSH_Lookup's handling of busy objects,

if (busy_o != NULL) {
/* There are one or more busy objects, wait for them */
if (sp-esis == 0)
VTAILQ_INSERT_TAIL(oh-waitinglist, sp, list);
if (params-diag_bitmap  0x20)
WSP(sp, SLT_Debug,
%lld %p on waiting list %p %s, gethrtime(), sp, oh, 
oh-hash);
sp-objhead = oh;
Lck_Unlock(oh-mtx);
return (NULL);
}


what I get is this (URL removed to protect the innocent):

48 VCL_call c recv lookup
48 VCL_call c hash hash
48 Debugc 24115201202978841 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Debugc 24115203101868689 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Debugc 24115203106349919 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Debugc 24115205121308416 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Debugc 24115205122330112 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Debugc 24115207141435616 8d6278 on waiting list 8b72e0 ##URL##
48 VCL_call c hash hash
48 Hit  c 1506286692

the restart VCL code basically is this:

sub vcl_recv {
 if (req.restarts == 0) {
# set default backend and default grace
 } else if (req.restarts == 1) {
set req.grace = 24h;
# set other backend
 } else {
error 503 Retry count exceeded;
 }
}

Basically, what I am trying to achieve is to have restarts fall back to the 
cache.

I'd appreciate any pointers, at this point I really don't understand why the 
hash vcl should get invoked multiple times.

Thank you, Nils
___
varnish-dev mailing list
varnish-dev@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-dev


Re: HSH_Lookup entered multiply - why could that happen?

2009-12-09 Thread Nils Goroll
Maybe I should also mention that I am trying to test the restart behavior by 
simulating a a slow and unresponsive backend using this VCL code:

sub vcl_fetch {
 /* TEST CODE to test restarting REMOVE ME  */
 if ((req.url ~ MAGIC TESTING URL SUBSTRING) 
(req.restarts = 3)) {
C{
 sleep(2);
}C

 return (restart);
 }


Is there a better way to do this?

___
varnish-dev mailing list
varnish-dev@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-dev


Re: HSH_Lookup entered multiply - why could that happen?

2009-12-09 Thread Poul-Henning Kamp
In message 4b1ffa7d.3020...@schokola.de, Nils Goroll writes:
Hi,

what I get is this (URL removed to protect the innocent):

48 VCL_call c recv lookup
48 VCL_call c hash hash
48 Debugc 24115201202978841 8d6278 on waiting list 8b72e0 ##URL##

What happens here is that another client/thread holds this object
busy while it is being fetched from the backend.  Once the object
is marked unbusy, the waiting threads are relased, and calls hash
again.

I'm not quite sure you you keep hitting it so many times, it smells
like som weird situation where the object takes a long time to fetch,
has no cacheability, but does not get marked pass in vcl_fetch ?

Poul-Henning

-- 
Poul-Henning Kamp   | UNIX since Zilog Zeus 3.20
p...@freebsd.org | TCP/IP since RFC 956
FreeBSD committer   | BSD since 4.3-tahoe
Never attribute to malice what can adequately be explained by incompetence.
___
varnish-dev mailing list
varnish-dev@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-dev


Solved: HSH_Lookup entered multiply - why could that happen?

2009-12-09 Thread Nils Goroll
Sorry,

there's an easy answer to this:

I was using varnishlog -o.

Sorry, folks and thanks to all who have started thinking about this.

Nils
___
varnish-dev mailing list
varnish-dev@projects.linpro.no
http://projects.linpro.no/mailman/listinfo/varnish-dev