You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@zookeeper.apache.org by Srikanth <rs...@gmail.com> on 2013/11/01 07:17:50 UTC
Re: Zookeeper session timeouts during RAID Checks
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.
Re: Zookeeper session timeouts during RAID Checks
Posted by Patrick Hunt <ph...@apache.org>.
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 <rs...@gmail.com> 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.