Yes, 965 seconds is huge.

The times I've seen such huge latencies are (in order of frequency seen):

1) when the java process gc's, swaps, or both

and/or

2) disk utilization on the ZK server is high

and/or

3) under-provisioned virtual machines (ie vmware)

Re 2) in some cases we've seen users running multiple IO heavy processes on the same host as the zk server. hdfs data nodes and/or hbase region servers are two common examples. In those cases I've monitored "sudo iostat -x 3", specifically the "%util", and when this case is occurring I've seen heavy utilization concurrent with the max latency spiking up. ZK servers need to sync a file to disk on every write operation, maxed out disk utilization (esp on ext3 fs) will cause a spike in max latency as the server has to wait for the sync to complete.

I notice you have ~1mil writes and ~1mil reads according to the current server stats. It seems you are doing 1 read for every write (so relatively low read to write ratio... not extremely so but something to consider)

You might reset the latency using the "srst" 4 letter word
http://hadoop.apache.org/zookeeper/docs/current/zookeeperAdmin.html#sc_zkCommands
then monitor the max latency, the GC history, the "swappyness" of the java process, and esp the disk utilization. You can correlate a jump in latency against these (gc, swap, %util, etc...).

useful tool: http://github.com/phunt/zktop

Given that you've ruled out the gc (most common), disk utilization would be the next thing to check.

Patrick

On 06/15/2010 11:20 AM, Jordan Zimmerman wrote:
Yes - the session drop happened again. I did the stat. The max latency is huge 
(I assume that's in ms).

Zookeeper version: 3.3.0-925362, built on 03/19/2010 18:38 GMT
Clients:
  /10.243.14.179:57300[1](queued=0,recved=0,sent=0)
  /207.111.236.2:51493[1](queued=0,recved=1,sent=0)
  /10.243.13.191:44414[1](queued=0,recved=0,sent=0)
  /10.243.13.191:44415[1](queued=0,recved=0,sent=0)
  /10.244.135.100:58965[1](queued=0,recved=0,sent=0)
  /10.243.15.192:45057[1](queued=0,recved=0,sent=0)

Latency min/avg/max: 0/6/965759
Received: 2203048
Sent: 2202979
Outstanding: 0
Zxid: 0xef2b2
Mode: standalone
Node count: 347


On Jun 15, 2010, at 11:02 AM, Ted Dunning wrote:

Jordan,

Good step to get this info.

I have to ask, did you have your disconnect problem last night as well?
(just checking)

What does the stat command on ZK give you for each server?

On Tue, Jun 15, 2010 at 10:33 AM, Jordan Zimmerman<
jzimmer...@proofpoint.com>  wrote:

More on this...

I ran last night with verbose GC on our client. I analyzed the GC log in
gchisto and 99% of the GCs are 1 or 2 ms. The longest gc is 30 ms. On the
Zookeeper server side, the longest gc is 130 ms. So, I submit, GC is not the
problem. NOTE we're running on Amazon EC2.



Reply via email to