Re: local call latency

2017-10-26 Thread Abraham Fine
There is nothing ZooKeeper specific, it's all standard JVM stuff.

This is a pretty good article detailing how to do it:
https://dzone.com/articles/understanding-garbage-collection-log

Of course you can always attach visualvm (https://visualvm.github.io) or
a profiler of your choice.

Let me know what you find or, better yet, post the logs so the community
can take a look.

Thanks,
Abe

On Thu, Oct 26, 2017, at 15:27, rammohan ganapavarapu wrote:
> That is what i was suspecting, how do i get gc logs? right now in my logs
> i
> dont see any gc related logging.
> 
> On Thu, Oct 26, 2017 at 2:08 PM, Abraham Fine  wrote:
> 
> > Another possibility... have you ruled out garbage collection related
> > pauses?
> >
> > Abe
> >
> > On Thu, Oct 26, 2017, at 13:57, rammohan ganapavarapu wrote:
> > > I was running ls command with in zkCli console from the same box.
> > >
> > > zkCli.sh --server localhost ls /node1, so no network involved.
> > >
> > > On Oct 26, 2017 12:37 PM, "Abraham Fine"  wrote:
> > >
> > > > Thanks for the jstack. I am not seeing anything unusual there.
> > > >
> > > > In your first message you mentioned that the command you executed is a
> > > > "local zk 'ls' command". By "local" do you mean that the command is
> > > > being executed from the same machine where the instance of zookeeper
> > you
> > > > are querying is running? It would be great to determine if the latency
> > > > is network related or more tied to zookeeper internals.
> > > >
> > > > Abe
> > > >
> > > > On Thu, Oct 26, 2017, at 10:57, rammohan ganapavarapu wrote:
> > > > > Abe,
> > > > >
> > > > > It is just 20kb file, not sure why its not able to deliver. I am just
> > > > > copying the jstack here.
> > > > >
> > > > >
> > > > > ###
> > > > > > 2017-10-24 04:09:49
> > > > > > Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> > > > > > "Attach Listener" #758568 daemon prio=9 os_prio=0
> > > > tid=0x7efbfc001000
> > > > > > nid=0x10cfb waiting on condition [0x]
> > > > > >java.lang.Thread.State: RUNNABLE
> > > > > > "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000
> > > > nid=0x1a951
> > > > > > waiting on condition [0x7efbbaeef000]
> > > > > >java.lang.Thread.State: WAITING (parking)
> > > > > > at sun.misc.Unsafe.park(Native Method)
> > > > > > - parking to wait for  <0x0006c55eced0> (a
> > > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > ConditionObject)
> > > > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.
> > java:175)
> > > > > > at
> > > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > > > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > > > at
> > > > > > java.util.concurrent.LinkedBlockingQueue.take(
> > > > LinkedBlockingQueue.java:442)
> > > > > > at
> > > > > > org.apache.zookeeper.server.SyncRequestProcessor.run(
> > > > SyncRequestProcessor.java:97)
> > > > > > "ObserverRequestProcessor:210" #73 prio=5 os_prio=0
> > > > tid=0x7efba0035800
> > > > > > nid=0x1a950 waiting on condition [0x7efbbaff]
> > > > > >java.lang.Thread.State: WAITING (parking)
> > > > > > at sun.misc.Unsafe.park(Native Method)
> > > > > > - parking to wait for  <0x0006c55ec2e8> (a
> > > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > ConditionObject)
> > > > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.
> > java:175)
> > > > > > at
> > > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > > > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > > > at
> > > > > > java.util.concurrent.LinkedBlockingQueue.take(
> > > > LinkedBlockingQueue.java:442)
> > > > > > at
> > > > > > org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(
> > > > ObserverRequestProcessor.java:66)
> > > > > > "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> > > > > > nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
> > > > > >java.lang.Thread.State: WAITING (on object monitor)
> > > > > > at java.lang.Object.wait(Native Method)
> > > > > > at java.lang.Object.wait(Object.java:502)
> > > > > > at
> > > > > > org.apache.zookeeper.server.quorum.CommitProcessor.run(
> > > > CommitProcessor.java:80)
> > > > > > - locked <0x0006c55eb8e0> (a
> > > > > > org.apache.zookeeper.server.quorum.CommitProcessor)
> > > > > > "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> > > > > > nid=0x1a415 runnable [0x7efbbb1f2000]
> > > > > >java.lang.Thread.State: RUNNABLE
> > > > > > at java.net.SocketInputStream.socketRead0(Native Method)
> > > > > > at java.net.SocketInputStream.socketRead(SocketInputStream.
> > java:116)
> > > > > > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > > > > > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > > > > > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > > > > > at 

Re: local call latency

2017-10-26 Thread rammohan ganapavarapu
That is what i was suspecting, how do i get gc logs? right now in my logs i
dont see any gc related logging.

On Thu, Oct 26, 2017 at 2:08 PM, Abraham Fine  wrote:

> Another possibility... have you ruled out garbage collection related
> pauses?
>
> Abe
>
> On Thu, Oct 26, 2017, at 13:57, rammohan ganapavarapu wrote:
> > I was running ls command with in zkCli console from the same box.
> >
> > zkCli.sh --server localhost ls /node1, so no network involved.
> >
> > On Oct 26, 2017 12:37 PM, "Abraham Fine"  wrote:
> >
> > > Thanks for the jstack. I am not seeing anything unusual there.
> > >
> > > In your first message you mentioned that the command you executed is a
> > > "local zk 'ls' command". By "local" do you mean that the command is
> > > being executed from the same machine where the instance of zookeeper
> you
> > > are querying is running? It would be great to determine if the latency
> > > is network related or more tied to zookeeper internals.
> > >
> > > Abe
> > >
> > > On Thu, Oct 26, 2017, at 10:57, rammohan ganapavarapu wrote:
> > > > Abe,
> > > >
> > > > It is just 20kb file, not sure why its not able to deliver. I am just
> > > > copying the jstack here.
> > > >
> > > >
> > > > ###
> > > > > 2017-10-24 04:09:49
> > > > > Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> > > > > "Attach Listener" #758568 daemon prio=9 os_prio=0
> > > tid=0x7efbfc001000
> > > > > nid=0x10cfb waiting on condition [0x]
> > > > >java.lang.Thread.State: RUNNABLE
> > > > > "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000
> > > nid=0x1a951
> > > > > waiting on condition [0x7efbbaeef000]
> > > > >java.lang.Thread.State: WAITING (parking)
> > > > > at sun.misc.Unsafe.park(Native Method)
> > > > > - parking to wait for  <0x0006c55eced0> (a
> > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject)
> > > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.
> java:175)
> > > > > at
> > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > > at
> > > > > java.util.concurrent.LinkedBlockingQueue.take(
> > > LinkedBlockingQueue.java:442)
> > > > > at
> > > > > org.apache.zookeeper.server.SyncRequestProcessor.run(
> > > SyncRequestProcessor.java:97)
> > > > > "ObserverRequestProcessor:210" #73 prio=5 os_prio=0
> > > tid=0x7efba0035800
> > > > > nid=0x1a950 waiting on condition [0x7efbbaff]
> > > > >java.lang.Thread.State: WAITING (parking)
> > > > > at sun.misc.Unsafe.park(Native Method)
> > > > > - parking to wait for  <0x0006c55ec2e8> (a
> > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject)
> > > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.
> java:175)
> > > > > at
> > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > > at
> > > > > java.util.concurrent.LinkedBlockingQueue.take(
> > > LinkedBlockingQueue.java:442)
> > > > > at
> > > > > org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(
> > > ObserverRequestProcessor.java:66)
> > > > > "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> > > > > nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
> > > > >java.lang.Thread.State: WAITING (on object monitor)
> > > > > at java.lang.Object.wait(Native Method)
> > > > > at java.lang.Object.wait(Object.java:502)
> > > > > at
> > > > > org.apache.zookeeper.server.quorum.CommitProcessor.run(
> > > CommitProcessor.java:80)
> > > > > - locked <0x0006c55eb8e0> (a
> > > > > org.apache.zookeeper.server.quorum.CommitProcessor)
> > > > > "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> > > > > nid=0x1a415 runnable [0x7efbbb1f2000]
> > > > >java.lang.Thread.State: RUNNABLE
> > > > > at java.net.SocketInputStream.socketRead0(Native Method)
> > > > > at java.net.SocketInputStream.socketRead(SocketInputStream.
> java:116)
> > > > > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > > > > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > > > > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > > > > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > > > > at
> > > > > org.apache.zookeeper.server.quorum.QuorumCnxManager$
> RecvWorker.run(
> > > QuorumCnxManager.java:747)
> > > > > "SendWorker:204" #39 daemon prio=5 os_prio=0 tid=0x7efba8011000
> > > > > nid=0x1a414 waiting on condition [0x7efbbb2f3000]
> > > > >java.lang.Thread.State: TIMED_WAITING (parking)
> > > > > at sun.misc.Unsafe.park(Native Method)
> > > > > - parking to wait for  <0x0005c018c938> (a
> > > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject)
> > > > > at java.util.concurrent.locks.LockSupport.parkNanos(
> > > LockSupport.java:215)
> > > 

Re: local call latency

2017-10-26 Thread Abraham Fine
Another possibility... have you ruled out garbage collection related
pauses?

Abe

On Thu, Oct 26, 2017, at 13:57, rammohan ganapavarapu wrote:
> I was running ls command with in zkCli console from the same box.
> 
> zkCli.sh --server localhost ls /node1, so no network involved.
> 
> On Oct 26, 2017 12:37 PM, "Abraham Fine"  wrote:
> 
> > Thanks for the jstack. I am not seeing anything unusual there.
> >
> > In your first message you mentioned that the command you executed is a
> > "local zk 'ls' command". By "local" do you mean that the command is
> > being executed from the same machine where the instance of zookeeper you
> > are querying is running? It would be great to determine if the latency
> > is network related or more tied to zookeeper internals.
> >
> > Abe
> >
> > On Thu, Oct 26, 2017, at 10:57, rammohan ganapavarapu wrote:
> > > Abe,
> > >
> > > It is just 20kb file, not sure why its not able to deliver. I am just
> > > copying the jstack here.
> > >
> > >
> > > ###
> > > > 2017-10-24 04:09:49
> > > > Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> > > > "Attach Listener" #758568 daemon prio=9 os_prio=0
> > tid=0x7efbfc001000
> > > > nid=0x10cfb waiting on condition [0x]
> > > >java.lang.Thread.State: RUNNABLE
> > > > "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000
> > nid=0x1a951
> > > > waiting on condition [0x7efbbaeef000]
> > > >java.lang.Thread.State: WAITING (parking)
> > > > at sun.misc.Unsafe.park(Native Method)
> > > > - parking to wait for  <0x0006c55eced0> (a
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > > > at
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > at
> > > > java.util.concurrent.LinkedBlockingQueue.take(
> > LinkedBlockingQueue.java:442)
> > > > at
> > > > org.apache.zookeeper.server.SyncRequestProcessor.run(
> > SyncRequestProcessor.java:97)
> > > > "ObserverRequestProcessor:210" #73 prio=5 os_prio=0
> > tid=0x7efba0035800
> > > > nid=0x1a950 waiting on condition [0x7efbbaff]
> > > >java.lang.Thread.State: WAITING (parking)
> > > > at sun.misc.Unsafe.park(Native Method)
> > > > - parking to wait for  <0x0006c55ec2e8> (a
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > > > at
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > > at
> > > > java.util.concurrent.LinkedBlockingQueue.take(
> > LinkedBlockingQueue.java:442)
> > > > at
> > > > org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(
> > ObserverRequestProcessor.java:66)
> > > > "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> > > > nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
> > > >java.lang.Thread.State: WAITING (on object monitor)
> > > > at java.lang.Object.wait(Native Method)
> > > > at java.lang.Object.wait(Object.java:502)
> > > > at
> > > > org.apache.zookeeper.server.quorum.CommitProcessor.run(
> > CommitProcessor.java:80)
> > > > - locked <0x0006c55eb8e0> (a
> > > > org.apache.zookeeper.server.quorum.CommitProcessor)
> > > > "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> > > > nid=0x1a415 runnable [0x7efbbb1f2000]
> > > >java.lang.Thread.State: RUNNABLE
> > > > at java.net.SocketInputStream.socketRead0(Native Method)
> > > > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > > > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > > > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > > > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > > > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > > > at
> > > > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(
> > QuorumCnxManager.java:747)
> > > > "SendWorker:204" #39 daemon prio=5 os_prio=0 tid=0x7efba8011000
> > > > nid=0x1a414 waiting on condition [0x7efbbb2f3000]
> > > >java.lang.Thread.State: TIMED_WAITING (parking)
> > > > at sun.misc.Unsafe.park(Native Method)
> > > > - parking to wait for  <0x0005c018c938> (a
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > > at java.util.concurrent.locks.LockSupport.parkNanos(
> > LockSupport.java:215)
> > > > at
> > > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> > ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> > > > at
> > > > java.util.concurrent.ArrayBlockingQueue.poll(
> > ArrayBlockingQueue.java:418)
> > > > at
> > > > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(
> > QuorumCnxManager.java:831)
> > > > at
> > > > 

Re: local call latency

2017-10-26 Thread rammohan ganapavarapu
I was running ls command with in zkCli console from the same box.

zkCli.sh --server localhost ls /node1, so no network involved.

On Oct 26, 2017 12:37 PM, "Abraham Fine"  wrote:

> Thanks for the jstack. I am not seeing anything unusual there.
>
> In your first message you mentioned that the command you executed is a
> "local zk 'ls' command". By "local" do you mean that the command is
> being executed from the same machine where the instance of zookeeper you
> are querying is running? It would be great to determine if the latency
> is network related or more tied to zookeeper internals.
>
> Abe
>
> On Thu, Oct 26, 2017, at 10:57, rammohan ganapavarapu wrote:
> > Abe,
> >
> > It is just 20kb file, not sure why its not able to deliver. I am just
> > copying the jstack here.
> >
> >
> > ###
> > > 2017-10-24 04:09:49
> > > Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> > > "Attach Listener" #758568 daemon prio=9 os_prio=0
> tid=0x7efbfc001000
> > > nid=0x10cfb waiting on condition [0x]
> > >java.lang.Thread.State: RUNNABLE
> > > "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000
> nid=0x1a951
> > > waiting on condition [0x7efbbaeef000]
> > >java.lang.Thread.State: WAITING (parking)
> > > at sun.misc.Unsafe.park(Native Method)
> > > - parking to wait for  <0x0006c55eced0> (a
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > > at
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > at
> > > java.util.concurrent.LinkedBlockingQueue.take(
> LinkedBlockingQueue.java:442)
> > > at
> > > org.apache.zookeeper.server.SyncRequestProcessor.run(
> SyncRequestProcessor.java:97)
> > > "ObserverRequestProcessor:210" #73 prio=5 os_prio=0
> tid=0x7efba0035800
> > > nid=0x1a950 waiting on condition [0x7efbbaff]
> > >java.lang.Thread.State: WAITING (parking)
> > > at sun.misc.Unsafe.park(Native Method)
> > > - parking to wait for  <0x0006c55ec2e8> (a
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > > at
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > > at
> > > java.util.concurrent.LinkedBlockingQueue.take(
> LinkedBlockingQueue.java:442)
> > > at
> > > org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(
> ObserverRequestProcessor.java:66)
> > > "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> > > nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
> > >java.lang.Thread.State: WAITING (on object monitor)
> > > at java.lang.Object.wait(Native Method)
> > > at java.lang.Object.wait(Object.java:502)
> > > at
> > > org.apache.zookeeper.server.quorum.CommitProcessor.run(
> CommitProcessor.java:80)
> > > - locked <0x0006c55eb8e0> (a
> > > org.apache.zookeeper.server.quorum.CommitProcessor)
> > > "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> > > nid=0x1a415 runnable [0x7efbbb1f2000]
> > >java.lang.Thread.State: RUNNABLE
> > > at java.net.SocketInputStream.socketRead0(Native Method)
> > > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > > at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(
> QuorumCnxManager.java:747)
> > > "SendWorker:204" #39 daemon prio=5 os_prio=0 tid=0x7efba8011000
> > > nid=0x1a414 waiting on condition [0x7efbbb2f3000]
> > >java.lang.Thread.State: TIMED_WAITING (parking)
> > > at sun.misc.Unsafe.park(Native Method)
> > > - parking to wait for  <0x0005c018c938> (a
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > > at java.util.concurrent.locks.LockSupport.parkNanos(
> LockSupport.java:215)
> > > at
> > > java.util.concurrent.locks.AbstractQueuedSynchronizer$
> ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> > > at
> > > java.util.concurrent.ArrayBlockingQueue.poll(
> ArrayBlockingQueue.java:418)
> > > at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(
> QuorumCnxManager.java:831)
> > > at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager.
> access$500(QuorumCnxManager.java:62)
> > > at
> > > org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(
> QuorumCnxManager.java:667)
> > > "RecvWorker:203" #38 daemon prio=5 os_prio=0 tid=0x7efba800f800
> > > nid=0x1a413 runnable [0x7efbbb3f4000]
> > >java.lang.Thread.State: RUNNABLE
> > > at 

Re: local call latency

2017-10-26 Thread Abraham Fine
Thanks for the jstack. I am not seeing anything unusual there.

In your first message you mentioned that the command you executed is a
"local zk 'ls' command". By "local" do you mean that the command is
being executed from the same machine where the instance of zookeeper you
are querying is running? It would be great to determine if the latency
is network related or more tied to zookeeper internals. 

Abe

On Thu, Oct 26, 2017, at 10:57, rammohan ganapavarapu wrote:
> Abe,
> 
> It is just 20kb file, not sure why its not able to deliver. I am just
> copying the jstack here.
> 
> 
> ###
> > 2017-10-24 04:09:49
> > Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> > "Attach Listener" #758568 daemon prio=9 os_prio=0 tid=0x7efbfc001000
> > nid=0x10cfb waiting on condition [0x]
> >java.lang.Thread.State: RUNNABLE
> > "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000 nid=0x1a951
> > waiting on condition [0x7efbbaeef000]
> >java.lang.Thread.State: WAITING (parking)
> > at sun.misc.Unsafe.park(Native Method)
> > - parking to wait for  <0x0006c55eced0> (a
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > at
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > at
> > java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
> > at
> > org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:97)
> > "ObserverRequestProcessor:210" #73 prio=5 os_prio=0 tid=0x7efba0035800
> > nid=0x1a950 waiting on condition [0x7efbbaff]
> >java.lang.Thread.State: WAITING (parking)
> > at sun.misc.Unsafe.park(Native Method)
> > - parking to wait for  <0x0006c55ec2e8> (a
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> > at
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> > at
> > java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
> > at
> > org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(ObserverRequestProcessor.java:66)
> > "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> > nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
> >java.lang.Thread.State: WAITING (on object monitor)
> > at java.lang.Object.wait(Native Method)
> > at java.lang.Object.wait(Object.java:502)
> > at
> > org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:80)
> > - locked <0x0006c55eb8e0> (a
> > org.apache.zookeeper.server.quorum.CommitProcessor)
> > "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> > nid=0x1a415 runnable [0x7efbbb1f2000]
> >java.lang.Thread.State: RUNNABLE
> > at java.net.SocketInputStream.socketRead0(Native Method)
> > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:747)
> > "SendWorker:204" #39 daemon prio=5 os_prio=0 tid=0x7efba8011000
> > nid=0x1a414 waiting on condition [0x7efbbb2f3000]
> >java.lang.Thread.State: TIMED_WAITING (parking)
> > at sun.misc.Unsafe.park(Native Method)
> > - parking to wait for  <0x0005c018c938> (a
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> > at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> > at
> > java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> > at
> > java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> > at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:831)
> > at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:62)
> > at
> > org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:667)
> > "RecvWorker:203" #38 daemon prio=5 os_prio=0 tid=0x7efba800f800
> > nid=0x1a413 runnable [0x7efbbb3f4000]
> >java.lang.Thread.State: RUNNABLE
> > at java.net.SocketInputStream.socketRead0(Native Method)
> > at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> > at java.net.SocketInputStream.read(SocketInputStream.java:170)
> > at java.net.SocketInputStream.read(SocketInputStream.java:141)
> > at java.net.SocketInputStream.read(SocketInputStream.java:223)
> > at java.io.DataInputStream.readInt(DataInputStream.java:387)
> > at
> > 

Re: local call latency

2017-10-26 Thread rammohan ganapavarapu
Abe,

It is just 20kb file, not sure why its not able to deliver. I am just
copying the jstack here.


###
> 2017-10-24 04:09:49
> Full thread dump OpenJDK 64-Bit Server VM (25.101-b13 mixed mode):
> "Attach Listener" #758568 daemon prio=9 os_prio=0 tid=0x7efbfc001000
> nid=0x10cfb waiting on condition [0x]
>java.lang.Thread.State: RUNNABLE
> "SyncThread:210" #74 prio=5 os_prio=0 tid=0x7efba0036000 nid=0x1a951
> waiting on condition [0x7efbbaeef000]
>java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for  <0x0006c55eced0> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> at
> java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
> at
> org.apache.zookeeper.server.SyncRequestProcessor.run(SyncRequestProcessor.java:97)
> "ObserverRequestProcessor:210" #73 prio=5 os_prio=0 tid=0x7efba0035800
> nid=0x1a950 waiting on condition [0x7efbbaff]
>java.lang.Thread.State: WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for  <0x0006c55ec2e8> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)
> at
> java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:442)
> at
> org.apache.zookeeper.server.quorum.ObserverRequestProcessor.run(ObserverRequestProcessor.java:66)
> "CommitProcessor:210" #72 prio=5 os_prio=0 tid=0x7efba004d800
> nid=0x1a94f in Object.wait() [0x7efbbb0f1000]
>java.lang.Thread.State: WAITING (on object monitor)
> at java.lang.Object.wait(Native Method)
> at java.lang.Object.wait(Object.java:502)
> at
> org.apache.zookeeper.server.quorum.CommitProcessor.run(CommitProcessor.java:80)
> - locked <0x0006c55eb8e0> (a
> org.apache.zookeeper.server.quorum.CommitProcessor)
> "RecvWorker:204" #40 daemon prio=5 os_prio=0 tid=0x7efba8013000
> nid=0x1a415 runnable [0x7efbbb1f2000]
>java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> at java.net.SocketInputStream.read(SocketInputStream.java:170)
> at java.net.SocketInputStream.read(SocketInputStream.java:141)
> at java.net.SocketInputStream.read(SocketInputStream.java:223)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:747)
> "SendWorker:204" #39 daemon prio=5 os_prio=0 tid=0x7efba8011000
> nid=0x1a414 waiting on condition [0x7efbbb2f3000]
>java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for  <0x0005c018c938> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> at
> java.util.concurrent.ArrayBlockingQueue.poll(ArrayBlockingQueue.java:418)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.pollSendQueue(QuorumCnxManager.java:831)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager.access$500(QuorumCnxManager.java:62)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$SendWorker.run(QuorumCnxManager.java:667)
> "RecvWorker:203" #38 daemon prio=5 os_prio=0 tid=0x7efba800f800
> nid=0x1a413 runnable [0x7efbbb3f4000]
>java.lang.Thread.State: RUNNABLE
> at java.net.SocketInputStream.socketRead0(Native Method)
> at java.net.SocketInputStream.socketRead(SocketInputStream.java:116)
> at java.net.SocketInputStream.read(SocketInputStream.java:170)
> at java.net.SocketInputStream.read(SocketInputStream.java:141)
> at java.net.SocketInputStream.read(SocketInputStream.java:223)
> at java.io.DataInputStream.readInt(DataInputStream.java:387)
> at
> org.apache.zookeeper.server.quorum.QuorumCnxManager$RecvWorker.run(QuorumCnxManager.java:747)
> "SendWorker:203" #37 daemon prio=5 os_prio=0 tid=0x7efba800d800
> nid=0x1a412 waiting on condition [0x7efbbb4f5000]
>java.lang.Thread.State: TIMED_WAITING (parking)
> at sun.misc.Unsafe.park(Native Method)
> - parking to wait for  <0x0005c018bf00> (a
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
> at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
> at
> java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
> at
> 

Re: local call latency

2017-10-26 Thread Abraham Fine
Maybe it is a limitation of the mailing list infrastructure, but I'm not
getting them.
Would it be possible to put the jstack output in a gist and link
to it here?
Abe


On Thu, Oct 26, 2017, at 09:00, rammohan ganapavarapu wrote:
> Hmm, it is attached in my sent mail but any way i am attaching again.> 
> On Thu, Oct 26, 2017 at 8:58 AM, Abraham Fine
>  wrote:>> Hi Ram-
>> 
>>  I don't see any jstack output attached to the email.
>> 
>>  Thanks,
>>  Abe
>> 
>> 
>> 
>> On Wed, Oct 25, 2017, at 18:17, rammohan ganapavarapu wrote:
>>  > Abe,
>>  >
>>  > Under /node1 i have 30 child nodes but each child node doesn't
>>  > have>>  > any more nodes. I did took jstack at the time of latency, please
>>  > find>>  > the attached. It is happening with most of the servers i didn't
>>  > check>>  > all of them.>
>>  > Thanks,
>>  > Ram
>>  >
>>  > On Wed, Oct 25, 2017 at 4:06 PM, Abraham Fine
>>  >  wrote:>> That's strange. ZooKeeper's reads
>>  > happen locally usually quickly.>>  >>
>>  >>  Can you tell us anything else about the issue? Could you
>>  >>  possibly>>  >>  provide a jstack output from a server that is slow to 
>> respond?
>>  >>  Does>>  this happen with all of the servers? Does it matter if
>>  >>  the node>>  >>  you are>>  reading from has many children?
>>  >>
>>  >>  Thanks,
>>  >>  Abe
>>  >>
>>  >>
>>  >> On Wed, Oct 25, 2017, at 09:18, rammohan ganapavarapu wrote:
>>  >>  > Hi,
>>  >>  >
>>  >>  > We have a multi region zk cluster, we are observing latency
>>  >>  > for>>  >>  > just>>  > local
>>  >>  > zk 'ls' command intermittently nothing in logs dont know how
>>  >>  > to>>  >>  > find>>  >  reason for latency, any one have any thoughts?
>>  >>  >
>>  >>  > zkCli.sh ls /node1
>>  >>  >
>>  >>  > real 0m13.089s --When latency
>>  >>  > real 0m0.689s -- No latency
>>  >>  >
>>  >>  > Thanks,
>>  >>  > Ram
>> 



Re: local call latency

2017-10-26 Thread rammohan ganapavarapu
Hmm, it is attached in my sent mail but any way i am attaching again.

On Thu, Oct 26, 2017 at 8:58 AM, Abraham Fine  wrote:

> Hi Ram-
>
> I don't see any jstack output attached to the email.
>
> Thanks,
> Abe
>
>
> On Wed, Oct 25, 2017, at 18:17, rammohan ganapavarapu wrote:
> > Abe,
> >
> > Under /node1 i have 30 child nodes but each child node doesn't have
> > any more nodes. I did took jstack at the time of latency, please find
> > the attached. It is happening with most of the servers i didn't check
> > all of them.>
> > Thanks,
> > Ram
> >
> > On Wed, Oct 25, 2017 at 4:06 PM, Abraham Fine
> >  wrote:>> That's strange. ZooKeeper's reads happen
> locally usually quickly.
> >>
> >>  Can you tell us anything else about the issue? Could you possibly
> >>  provide a jstack output from a server that is slow to respond?
> Does>>  this happen with all of the servers? Does it matter if the node
> >>  you are>>  reading from has many children?
> >>
> >>  Thanks,
> >>  Abe
> >>
> >>
> >> On Wed, Oct 25, 2017, at 09:18, rammohan ganapavarapu wrote:
> >>  > Hi,
> >>  >
> >>  > We have a multi region zk cluster, we are observing latency for
> >>  > just>>  > local
> >>  > zk 'ls' command intermittently nothing in logs dont know how to
> >>  > find>>  >  reason for latency, any one have any thoughts?
> >>  >
> >>  > zkCli.sh ls /node1
> >>  >
> >>  > real 0m13.089s --When latency
> >>  > real 0m0.689s -- No latency
> >>  >
> >>  > Thanks,
> >>  > Ram
>
>


Re: local call latency

2017-10-26 Thread Abraham Fine
Hi Ram-

I don't see any jstack output attached to the email.

Thanks,
Abe


On Wed, Oct 25, 2017, at 18:17, rammohan ganapavarapu wrote:
> Abe,
> 
> Under /node1 i have 30 child nodes but each child node doesn't have
> any more nodes. I did took jstack at the time of latency, please find
> the attached. It is happening with most of the servers i didn't check
> all of them.> 
> Thanks,
> Ram
> 
> On Wed, Oct 25, 2017 at 4:06 PM, Abraham Fine
>  wrote:>> That's strange. ZooKeeper's reads happen locally 
> usually quickly.
>> 
>>  Can you tell us anything else about the issue? Could you possibly
>>  provide a jstack output from a server that is slow to respond?  Does>>  
>> this happen with all of the servers? Does it matter if the node
>>  you are>>  reading from has many children?
>> 
>>  Thanks,
>>  Abe
>> 
>> 
>> On Wed, Oct 25, 2017, at 09:18, rammohan ganapavarapu wrote:
>>  > Hi,
>>  >
>>  > We have a multi region zk cluster, we are observing latency for
>>  > just>>  > local
>>  > zk 'ls' command intermittently nothing in logs dont know how to
>>  > find>>  >  reason for latency, any one have any thoughts?
>>  >
>>  > zkCli.sh ls /node1
>>  >
>>  > real 0m13.089s --When latency
>>  > real 0m0.689s -- No latency
>>  >
>>  > Thanks,
>>  > Ram



Re: local call latency

2017-10-25 Thread rammohan ganapavarapu
Abe,

Under /node1 i have 30 child nodes but each child node doesn't have any
more nodes. I did took jstack at the time of latency, please find the
attached. It is happening with most of the servers i didn't check all of
them.

Thanks,
Ram

On Wed, Oct 25, 2017 at 4:06 PM, Abraham Fine  wrote:

> That's strange. ZooKeeper's reads happen locally usually quickly.
>
> Can you tell us anything else about the issue? Could you possibly
> provide a jstack output from a server that is slow to respond?  Does
> this happen with all of the servers? Does it matter if the node you are
> reading from has many children?
>
> Thanks,
> Abe
>
> On Wed, Oct 25, 2017, at 09:18, rammohan ganapavarapu wrote:
> > Hi,
> >
> > We have a multi region zk cluster, we are observing latency for just
> > local
> > zk 'ls' command intermittently nothing in logs dont know how to find
> >  reason for latency, any one have any thoughts?
> >
> > zkCli.sh ls /node1
> >
> > real 0m13.089s --When latency
> > real 0m0.689s -- No latency
> >
> > Thanks,
> > Ram
>


Re: local call latency

2017-10-25 Thread Abraham Fine
That's strange. ZooKeeper's reads happen locally usually quickly.

Can you tell us anything else about the issue? Could you possibly
provide a jstack output from a server that is slow to respond?  Does
this happen with all of the servers? Does it matter if the node you are
reading from has many children?

Thanks,
Abe

On Wed, Oct 25, 2017, at 09:18, rammohan ganapavarapu wrote:
> Hi,
> 
> We have a multi region zk cluster, we are observing latency for just
> local
> zk 'ls' command intermittently nothing in logs dont know how to find
>  reason for latency, any one have any thoughts?
> 
> zkCli.sh ls /node1
> 
> real 0m13.089s --When latency
> real 0m0.689s -- No latency
> 
> Thanks,
> Ram