That's interesting/odd. Checkout the "jstack script jstackSeries.sh" detailed here: http://helpx.adobe.com/experience-manager/kb/TakeThreadDump.html
Perhaps you can run this against the server during the operation? It should give you insight into what code is running during those 2 seconds. (or you can just run the jstack manually...) Patrick On Thu, Oct 31, 2013 at 11:17 PM, Srikanth <[email protected]> wrote: > Enabled TRACE Logs and set fsync-warningthreshold to 50ms. > > 1. here's the trace when the pings from client are successful. As soon as > the request comes in, commit processor processes it immediately. > > 2013-10-31 19:07:24,073 [myid:1] - TRACE > [FollowerRequestProcessor:1:ZooTrace@90] - :Fsessionid:0x2420f7ae4ba0000 > type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffff > ffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:24,073 [myid:1] - DEBUG > [FollowerRequestProcessor:1:CommitProcessor@171] - Processing request:: > sessionid:0x2420f7ae4ba0000 type:ping cxid:0xffffffffff > fffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:24,073 [myid:1] - DEBUG > [CommitProcessor:1:FinalRequestProcessor@88] - Processing request:: > sessionid:0x2420f7ae4ba0000 type:ping cxid:0xffffffffffffff > fe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:24,073 [myid:1] - DEBUG > [CommitProcessor:1:FinalRequestProcessor@160] - sessionid:0x2420f7ae4ba0000 > type:ping cxid:0xfffffffffffffffe zxid:0xffffffffff > fffffe txntype:unknown reqpath:n/a > > 2. This is the trace when the client timesout. There are no fsync warnings > during this period. There is a 2 sec interval between the first trace > (FollowerRequestProcessor:1:ZooTrace@90) and when commit processor sees the > request (FollowerRequestProcessor:1:CommitProcessor@171]). Almost everytime > when zkclient timesout, the observation is similar. > > 2013-10-31 19:07:25,739 [myid:1] - TRACE > [FollowerRequestProcessor:1:ZooTrace@90] - :Fsessionid:0x2420f7ae4ba0000 > type:ping cxid:0xfffffffffffffffe zxid:0xfffffffffffff > ffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:27,518 [myid:1] - DEBUG > [FollowerRequestProcessor:1:CommitProcessor@171] - Processing request:: > sessionid:0x2420f7ae4ba0000 type:ping cxid:0xffffffffff > fffffe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:27,518 [myid:1] - DEBUG > [CommitProcessor:1:FinalRequestProcessor@88] - Processing request:: > sessionid:0x2420f7ae4ba0000 type:ping cxid:0xffffffffffffff > fe zxid:0xfffffffffffffffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:27,519 [myid:1] - DEBUG > [CommitProcessor:1:FinalRequestProcessor@160] - sessionid:0x2420f7ae4ba0000 > type:ping cxid:0xfffffffffffffffe zxid:0xffffffffff > fffffe txntype:unknown reqpath:n/a > 2013-10-31 19:07:27,498 [myid:1] - WARN > [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@349] - caught end > of stream exception > EndOfStreamException: Unable to read additional data from client sessionid > 0x2420f7ae4ba0000, likely client has closed socket > at > org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:220) > at > org.apache.zookeeper.server.NIOServerCnxnFactory.run(NIOServerCnxnFactory.java:208) > at java.lang.Thread.run(Thread.java:722) > 2013-10-31 19:07:27,519 [myid:1] - INFO > [NIOServerCxn.Factory:0.0.0.0/0.0.0.0:2181:NIOServerCnxn@1001] - Closed > socket connection for client /xx.yy.zz.aa:56844 whic > h had sessionid 0x2420f7ae4ba0000 > > > Any clues what would cause this 2 sec delay in processing ? > > thanks, > Srikanth > > > > -- > View this message in context: > http://zookeeper-user.578899.n2.nabble.com/Zookeeper-session-timeouts-during-RAID-Checks-tp7579160p7579223.html > Sent from the zookeeper-user mailing list archive at Nabble.com.
