hadoop-zookeeper-user mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stephen Green <eelstretch...@gmail.com>
Subject Re: Ping and client session timeouts
Date Fri, 21 May 2010 18:32:00 GMT
On Fri, May 21, 2010 at 2:15 PM, Patrick Hunt <phunt@apache.org> wrote:
> Hi Stephen, my comments inline below:

Thanks for the speedy response!

>> My understanding (having had a quick look at the code) is that the
>> client connection will send a ping every sessionTimeout * 2/3 ms or so
>> to keep the session alive, but I keep seeing sessions dying.  On the
>
> Actually the client sends a ping every 1/3 the timeout, and then looks for a
> response before another 1/3 elapses. This allows time to reconnect to a
> different server (and still maintain the session) if the current server were
> to become unavailable.

That makes sense.  I'm trying to get the system up to speed before I
introduce more complexity, but I expect that I'll be using a 3-ZK
setup before too long.

>> client side I'll see something like the following sequence of events:
>>
>> [05/21/10 15:59:40.753] INFO Initiating client connection,
>> connectString=zookeeper:2200 sessionTimeout=30000
>> watcher=com.echonest.cluster.ZooContainer@1eb3319f
>> [05/21/10 15:59:40.767] INFO Socket connection established to
>> zookeeper/10.255.9.187:2200, initiating session
>> [05/21/10 15:59:40.787] INFO Session establishment complete on server
>> zookeeper/10.255.9.187:2200, sessionid = 0x128bb7b828d004c, negotiated
>> timeout = 30000
>
> Ok, this (^^^) says that the timeout is set to 30sec.
>
>> [05/21/10 16:13:03.729] INFO Client session timed out, have not heard
>> from server in 33766ms for sessionid 0x128bb7b828d004c, closing socket
>> connection and attempting reconnect
>> [05/21/10 16:13:19.268] INFO Initiating client connection,
>> connectString=zookeeper:2200 sessionTimeout=30000
>> watcher=com.echonest.cluster.ZooContainer@1eb3319f
>> [05/21/10 16:14:12.326] INFO Client session timed out, have not heard
>> from server in 53058ms for sessionid 0x128bb7b828d004c, closing socket
>> connection and attempting reconnect
>
> This (^^^) is very suspicious, in particular "have not heard from server in
> 53058ms". This means that the client heartbeat code didn't notice that the
> heartbeat was exceeded for 53 seconds! This should never happen, the client
> does a "select" with a timeout of 1/3 the session timeout (10sec here).
>
> The fact that the select is taking 43 addl seconds (53-10sec select timeout)
> tells me that your client jvm is not allowing the heartbeat thread to run.
> The most common reason for this is GC. Is your client application very
> memory intensive? Heavy on GC? You should turn on your GC logging and review
> the output after reproducing this issue (turning on CMS/incremental GC mode
> usually resolves this issue, but you should verify first). What we typically
> see here is that the client JVM is running GC for very long periods of time,
> this blocks all the threads, and as a result the heartbeat is not sent by
> the client!

Right.  The system can be very memory-intensive, but at the time these
are occurring, it's not under a really heavy load, and there's plenty
of heap available. However, while looking at a thread dump from one of
the nodes, I realized that a very poor decision meant that I had more
than 1200 threads running.  I expect this is more of a problem than
the GC at this point.  I'm taking steps to correct this problem now.

Lately, I've had fewer and fewer problems with GC.  In a former life,
I sat down the hall from the folks who wrote Hotspot's GC and they're
pretty sharp folks :-)

> As you are running in a virtualized environment this could also be a factor
> (it's def an issue from a GC perspective). But I suspect that gc is the
> issue here, look at that first.

I'll do a run with verbose:gc (and maybe a few other triple-bucky JVM
options) and see what's going on.

> See this page for some common issues users have faced in the past:
> http://bit.ly/5WwS44

Thanks.

>> I started out with a session timeout of 10,000ms, but as you can see,
>> I have the same problem at 30,000ms.
>>
>
> You may not need to use this after you resolve the GC issue.

Right.  I'd like to have as small a timeout as possible so that I
notice quickly when things disappear.  What's a reasonable minimum?  I
notice recommendations in other messages on the list that 20000 is a
good value.

>> Do I have a fundamental misunderstanding? What else should I do to
>> figure out what's going on here?
>
> As I suggested above, give GC logging a try. I found 'gchisto' a very useful
> tool for reviewing the resulting log files.
> http://sysadminsjourney.com/content/2008/09/15/profile-your-java-gc-performance-gchisto

Tony will be chuffed to hear that folks are recommending his gc tools
:-)  I'll let you know how I get on.

Steve
-- 
Stephen Green
http://thesearchguy.wordpress.com

Mime
View raw message