On Friday 09 May 2003 2:20 am, Wankyu Choi wrote:
Hi Toby,
I'm terribly sorry to bother you like this. I tried mailling lists but no one seems to have the answer :-)
CC zope@zope.org, in case anyone else is interested.
Squid works great with one glitch: if you pack your ZODB, Squid gives up every parent cache peer as **dead**.
Zope seems to get lazy answering the calls from Squid when packing is in progress. Raising timeout values as high as 20 seconds didn't fix the problem.
Only restarting squid fixes the problem. I even came up with a little script to grep cache.log and restart Squid accordingly. But that's too kludgy.
Now I have three ZEO clients defined as parent cache peers. They work seemlessly barring this problem.
Have you had any trouble like this?
Yes I have seen that, but I am suprised it applies to you. You are using ICP. right? A dead peer means that the ICP replies are getting lost. Lost, not just delayed. Is squid really saying "dead peer" in cache.log? Do you have network packet loss? Or, maybe squid isnt actually declaring the peers as dead... you would get a similar effect if you neglected to put the "round-robin" directive on your cache_peer lines, which controls how it resonds to delayed ICP responses (if this is the case then you may want to tweak icp_query_timeout for performance, but thats a different question) I am still suprised that this applies to you at all, because you ZEO server is on it own machine. right? Is there anything of interest in cache.log? What about if you turn on full debugging in squid.conf? Can you post a before and after of "Peer Cache Statistics" page in squid cachemanager CGI -- Toby Dickenson http://www.geminidataloggers.com/people/tdickenson
Hi Toby,
I'm terribly sorry to bother you like this. I tried mailling lists but no one seems to have the answer :-)
CC zope@zope.org, in case anyone else is interested.
I already posted this days ago on zope@zope.org, but no answer yet ;-)
Have you had any trouble like this?
Yes I have seen that, but I am suprised it applies to you.
You are using ICP. right?
Yes.
A dead peer means that the ICP replies are getting lost. Lost, not just delayed. Is squid really saying "dead peer" in cache.log?
Yes, 'Detected Dead Parent.' All three clients are pronounced dead ( immediatley, I guess, after packing starts. ). Every 10 minutes, a little script runs to check cache.log to prevent this state from going on, and when Squid gets restarted, everthing goes back to normal.
Do you have network packet loss?
No. All machines are hooked up in a dedicated 10M lan using a 100M switch. The ZEO server comes with dual 1000bit ethernets. No packet loss at all.
Or, maybe squid isnt actually declaring the peers as dead... you would get a similar effect if you neglected to put the "round-robin" directive on your cache_peer lines, which controls how it resonds to delayed ICP responses (if this is the case then you may want to tweak icp_query_timeout for performance, but thats a different question)
cache_peer 192.168.250.3 parent 8080 3130 no-digest no-netdb-exchange round-robin cache_peer 192.168.250.4 parent 8080 3130 no-digest no-netdb-exchange round-robin cache_peer 127.0.0.1 parent 8080 3130 no-digest no-netdb-exchange round-robin 'round-robin' is right there :-) I tried 1 to 20 seconds for icp_query_timeout; none makes any difference.
I am still suprised that this applies to you at all, because you ZEO server is on it own machine. right?
Sure. No bandwidth or horsepower problem. It's the baddest machine in the whole setup: 2way P4 Xeon with 4G RAM and stuff.
Is there anything of interest in cache.log?
Nothing unusual. It pronounces all three clients dead and keeps complaining that it failed to select source for objects. 2003/05/09 01:02:32| Detected DEAD Parent: 192.168.250.4/8080/3130 2003/05/09 01:02:32| Detected DEAD Parent: 192.168.250.3/8080/3130 2003/05/09 01:02:32| Detected DEAD Parent: 127.0.0.1/8080/3130 2003/05/09 01:02:32| Failed to select source for XXXX 2003/05/09 01:02:32| always_direct = 0 2003/05/09 01:02:32| never_direct = 1 2003/05/09 01:02:32| timedout = 0 2003/05/09 01:02:32| Failed to select source for XXXX The ZODB packer script runs exactly at 1 AM. Clients are deemed dead at 1:02. This is from last night's cache.log From what I understood... I thought Squid would keep polling the clients and redeclare they're alive and kicking, but it never happens. Before I installed that little cron script, service came to a full stop all night until I realized something went wrong.
What about if you turn on full debugging in squid.conf?
Haven't tried it yet. I'll give it a try.
Can you post a before and after of "Peer Cache Statistics" page in squid cachemanager CGI
Haven't tried it either. Thought it was a **simple** misconfiguration or something. It might not be the case after all. I'll look into this more thoroughly then. Thanks again for your input. Cheers, Wankyu Choi --------------------------------------------------------------- Wankyu Choi CEO/President NeoQuest Communications, Inc. http://www.zoper.net http://www.neoboard.net ---------------------------------------------------------------
On Friday 09 May 2003 9:22 am, Wankyu Choi wrote:
From what I understood... I thought Squid would keep polling the clients and redeclare they're alive and kicking, but it never happens. Before I installed that little cron script, service came to a full stop all night until I realized something went wrong.
Yes, thats what happens. Squid sends ICP one request one every 10 seconds to dead peers to detect when they come back up. In practice, it takes perhaps 20 or 30 seconds before squid starts using a resurrected peer. -- Toby Dickenson http://www.geminidataloggers.com/people/tdickenson
Can you post a before and after of "Peer Cache Statistics" page in squid cachemanager CGI
About 10 minutes ago, I caught Squid getting restarted. Every night at 1 AM, the same thing happens: the packing script starts running; Squid declares peers dead; my cron job restarts Squid; the packing script keeps running; everything's back to normal, just a couple of minutes of a service blackout (the squid watch script runs every 10 minutes). Here goes 'Peer Cache Statistics' before and after the fact. Any ideas? ( Squid runs on 127.0.0.1 which also works as the first parent. ) Before Squid delcares peers dead: ----------------------------- Parent : 127.0.0.1/8080/3130 Flags : no-digest default round-robin no-netdb-exchange Address[0] : 127.0.0.1 Status : Up AVG RTT : 19 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 104 PINGS ACKED: 104 100% FETCHES : 5 5% IGNORED : 2 2% Histogram of PINGS ACKED: ICP_HIT : 3 3% ICP_MISS : 101 97% keep-alive ratio: 100% Parent : 192.168.250.4/8080/3130 Flags : no-digest round-robin no-netdb-exchange Address[0] : 192.168.250.4 Status : Up AVG RTT : 1 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 104 PINGS ACKED: 104 100% FETCHES : 87 84% IGNORED : 10 10% Histogram of PINGS ACKED: ICP_MISS : 104 100% keep-alive ratio: 100% Parent : 192.168.250.3/8080/3130 Flags : no-digest round-robin no-netdb-exchange Address[0] : 192.168.250.3 Status : Up AVG RTT : 13 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 104 PINGS ACKED: 104 100% FETCHES : 12 12% IGNORED : 5 5% Histogram of PINGS ACKED: ICP_MISS : 104 100% keep-alive ratio: 100% ------------------------------------------------------ After a restart: ----------------------------------- Parent : 127.0.0.1/8080/3130 Flags : no-digest default round-robin no-netdb-exchange Address[0] : 127.0.0.1 Status : Up AVG RTT : 20 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 68 PINGS ACKED: 68 100% FETCHES : 3 4% IGNORED : 2 3% Histogram of PINGS ACKED: ICP_HIT : 1 1% ICP_MISS : 67 99% keep-alive ratio: 100% Parent : 192.168.250.4/8080/3130 Flags : no-digest round-robin no-netdb-exchange Address[0] : 192.168.250.4 Status : Up AVG RTT : 6 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 68 PINGS ACKED: 68 100% FETCHES : 57 84% IGNORED : 5 7% Histogram of PINGS ACKED: ICP_MISS : 68 100% keep-alive ratio: 100% Parent : 192.168.250.3/8080/3130 Flags : no-digest round-robin no-netdb-exchange Address[0] : 192.168.250.3 Status : Up AVG RTT : 16 msec LAST QUERY : 5 seconds ago LAST REPLY : 5 seconds ago PINGS SENT : 68 PINGS ACKED: 68 100% FETCHES : 8 12% IGNORED : 3 4% Histogram of PINGS ACKED: ICP_MISS : 68 100% keep-alive ratio: 100% ---------------------------------
ATT: cross post to ZODB-DEV. Wankyu Choi wrote at 2003-5-31 01:20 +0900:
Can you post a before and after of "Peer Cache Statistics" page in squid cachemanager CGI
About 10 minutes ago, I caught Squid getting restarted. Every night at 1 AM, the same thing happens: the packing script starts running; Squid declares peers dead; my cron job restarts Squid; the packing script keeps running; everything's back to normal, just a couple of minutes of a service blackout (the squid watch script runs every 10 minutes).
Zope becomes very slow during packing. I do not yet fully understand why, but the complete host seems to be affected by the high disc bandwidth required during packing. In the second packing phase (the so called copying phase), the packing thread helds the storage lock most of the time. This can make accessing the ZODB impossible by normal operations, especially because the "lock_release", "lock_acquire" probably does not succeed in giving the lock to a waiting thread. I have a patch that restricts this locking to only a minor fraction of time. However, I know that this is not responsible alone for the sluggish responses during packing. Dieter
On Sat, 2003-05-31 at 13:42, Dieter Maurer wrote:
I do not yet fully understand why, but the complete host seems to be affected by the high disc bandwidth required during packing.
Note that with Berkeley storages, one of the biggest boosts to performance you can get is by separating the BerkeleyDB database and log files to different disks. This is a low-level BerkeleyDB configuration option that's exposed in the storage configuration parameters. FileStorage doesn't have this "luxury".
In the second packing phase (the so called copying phase), the packing thread helds the storage lock most of the time. This can make accessing the ZODB impossible by normal operations, especially because the "lock_release", "lock_acquire" probably does not succeed in giving the lock to a waiting thread. I have a patch that restricts this locking to only a minor fraction of time.
Berkeley storages release the storage lock during the various phases of packing. It's not terribly granular, but it would give opportunities for other work to happen during packing. That, and regular autopacking might make things acceptably responsive. -Barry
[Dieter Maurer]
... In the second packing phase (the so called copying phase), the packing thread helds the storage lock most of the time. This can make accessing the ZODB impossible by normal operations, especially because the "lock_release", "lock_acquire" probably does not succeed in giving the lock to a waiting thread.
That decision is made by the platform thread facilities: the strongest that can be said in general is that lock_release *offers* to yield to another thread. The conditions under which the platform accepts the offer vary a lot across platforms. Assuming you're using Linux, there are many reports (in the Python world, independent of Zope) that most Linux flavors are reluctant to switch threads given the pthread condition variable + mutex pair Python uses to implement locks prior to Python 2.3. When possible, Python 2.3 uses POSIX semaphores instead to implement locks on pthreads boxes. Because POSIX semaphores derived from the real-time world, platforms supporting them are generally much more willing to switch, often treating the offer to yield more as a demand to yield. So an interesting experiment would be to try the same thing but using Python 2.3b1 instead. A caution that this can have bad effects too: always switching is as irritating to some apps as rarely switching is to others. The pragmatics of thread use are a cross-platform, cross-thread-library, and cross-thread-gimmick mess.
Tim Peters wrote at 2003-5-31 14:58 -0400:
[Dieter Maurer]
... In the second packing phase (the so called copying phase), the packing thread helds the storage lock most of the time. This can make accessing the ZODB impossible by normal operations, especially because the "lock_release", "lock_acquire" probably does not succeed in giving the lock to a waiting thread.
That decision is made by the platform thread facilities: the strongest that can be said in general is that lock_release *offers* to yield to another thread. The conditions under which the platform accepts the offer vary a lot across platforms.
In other (i.e. non-Zope) code, I saw code like: lock.release() sleep(0) # indicate, threads should switch, if necessary lock.acquire() Of course, "sleep(0)" may not force a thread switch on all platforms. My lock time optimization holds the lock only while it decides whether it has finished. It looks like: # Read the transaction record seek(pos) h=read(TRANS_HDR_LEN) if len(h) < TRANS_HDR_LEN: # DM: lock and try again _commit_lock_acquire(); _lock_acquire(); locked= 1 h+= read(TRANS_HDR_LEN - len(h)) if len(h) < TRANS_HDR_LEN: break .... # DM: ensure the complete transaction can be read if not (packing or locked or _largeEnough(file,tend + 8)): # it was not - lock # when we get the lock, the transaction will be written completely # this would not work with a concurrent pack; # but hopefully, this cannot happen _commit_lock_acquire(); _lock_acquire(); locked= 1 assert _largeEnough(file,tend+8) # DM: we can release the locks now, as the currently # copied transaction is complete if locked: locked= 0; _lock_release(); _commit_lock_release() "_largeEnough(file,size)" checks that *file* has at least length *size*. Because the locks are held only during a very short time, locking out of other requests should be drastically reduced. Dieter
[Dieter Maurer]
In other (i.e. non-Zope) code, I saw code like:
lock.release() sleep(0) # indicate, threads should switch, if necessary lock.acquire()
Of course, "sleep(0)" may not force a thread switch on all platforms.
sleep(0) definitely forces a thread to yield its timeslice on Windows, definitely does not on Solaris, and "beats me" for everything else. Windows is happy to switch threads frequently without this kind of trickery, though.
My lock time optimization holds the lock only while it decides whether it has finished. It looks like: ...
Sorry, I don't know the packing code well enough to comment.
On Friday 30 May 2003 17:20, Wankyu Choi wrote:
Can you post a before and after of "Peer Cache Statistics" page in squid cachemanager CGI
About 10 minutes ago, I caught Squid getting restarted. Every night at 1 AM, the same thing happens: the packing script starts running; Squid declares peers dead; my cron job restarts Squid; the packing script keeps running; everything's back to normal, just a couple of minutes of a service blackout (the squid watch script runs every 10 minutes).
Here goes 'Peer Cache Statistics' before and after the fact. Any ideas?
Could you tweak your script that restarts squid to grab a copy of that page before the restart? Something is causing all ICP responses to be dropped for at least 10 seconds, or whatever you have squids dead_peer_timeout set to. You could try setting dead_peer_timeout longer, perhaps 30 seconds, but not too long because this also affects how long squid will wait before noticing that a peer has shut down. I'm still sure its not relevent, but have you tried this squid patch? http://www.squid-cache.org/bugs/show_bug.cgi?id=293 -- Toby Dickenson http://www.geminidataloggers.com/people/tdickenson
participants (5)
-
Barry Warsaw -
Dieter Maurer -
Tim Peters -
Toby Dickenson -
Wankyu Choi