[jira] [Commented] (ZOOKEEPER-2770) ZooKeeper slow operation log
[
https://issues.apache.org/jira/browse/ZOOKEEPER-2770?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=16088755#comment-16088755
]
ASF GitHub Bot commented on ZOOKEEPER-2770:
---
Github user karanmehta93 commented on the issue:
https://github.com/apache/zookeeper/pull/307
@hanm @eribeiro
Thank you for your comments. I have added a rebased patch with a test in
`ZooKeeperServerMainTest` class. Please review whenever convenient.
> It's odd to have two (or in future even more) types of latency checks
scattered around which creates fragmentation w.r.t. the definition of what a
request latency means.
We can decide based on opinion from other people and I can update the patch
accordingly. I will create new JIRA's based on @tdunning suggestions, after
this one gets approved. I am eager to take them up.
Documentation is still pending. Will add a patch for it soon. I am not sure
if I have to modify the `ZooKeeperAdmin.xml` file or `ZooKeeperAdmin.html`
file. Can you point me to any relevant stuff?
> ZooKeeper slow operation log
>
>
> Key: ZOOKEEPER-2770
> URL: https://issues.apache.org/jira/browse/ZOOKEEPER-2770
> Project: ZooKeeper
> Issue Type: Improvement
>Reporter: Karan Mehta
>Assignee: Karan Mehta
> Attachments: ZOOKEEPER-2770.001.patch, ZOOKEEPER-2770.002.patch,
> ZOOKEEPER-2770.003.patch
>
>
> ZooKeeper is a complex distributed application. There are many reasons why
> any given read or write operation may become slow: a software bug, a protocol
> problem, a hardware issue with the commit log(s), a network issue. If the
> problem is constant it is trivial to come to an understanding of the cause.
> However in order to diagnose intermittent problems we often don't know where,
> or when, to begin looking. We need some sort of timestamped indication of the
> problem. Although ZooKeeper is not a datastore, it does persist data, and can
> suffer intermittent performance degradation, and should consider implementing
> a 'slow query' log, a feature very common to services which persist
> information on behalf of clients which may be sensitive to latency while
> waiting for confirmation of successful persistence.
> Log the client and request details if the server discovers, when finally
> processing the request, that the current time minus arrival time of the
> request is beyond a configured threshold.
> Look at the HBase {{responseTooSlow}} feature for inspiration.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)
[GitHub] zookeeper issue #307: ZOOKEEPER-2770 ZooKeeper slow operation log
Github user karanmehta93 commented on the issue: https://github.com/apache/zookeeper/pull/307 @hanm @eribeiro Thank you for your comments. I have added a rebased patch with a test in `ZooKeeperServerMainTest` class. Please review whenever convenient. > It's odd to have two (or in future even more) types of latency checks scattered around which creates fragmentation w.r.t. the definition of what a request latency means. We can decide based on opinion from other people and I can update the patch accordingly. I will create new JIRA's based on @tdunning suggestions, after this one gets approved. I am eager to take them up. Documentation is still pending. Will add a patch for it soon. I am not sure if I have to modify the `ZooKeeperAdmin.xml` file or `ZooKeeperAdmin.html` file. Can you point me to any relevant stuff? --- If your project is set up for it, you can reply to this email and have your reply appear on GitHub as well. If your project does not have this feature enabled and wishes so, or if the feature is enabled but not working, please contact infrastructure at infrastruct...@apache.org or file a JIRA ticket with INFRA. ---
ZooKeeper-trunk-openjdk7 - Build # 1546 - Failure
See https://builds.apache.org/job/ZooKeeper-trunk-openjdk7/1546/ ### ## LAST 60 LINES OF THE CONSOLE ### [...truncated 58.42 MB...] [junit] 2017-07-15 20:01:33,511 [myid:127.0.0.1:22058] - INFO [main-SendThread(127.0.0.1:22058):ClientCnxn$SendThread@1113] - Opening socket connection to server 127.0.0.1/127.0.0.1:22058. Will not attempt to authenticate using SASL (unknown error) [junit] 2017-07-15 20:01:33,511 [myid:127.0.0.1:22058] - WARN [main-SendThread(127.0.0.1:22058):ClientCnxn$SendThread@1235] - Session 0x10572c5aa98 for server 127.0.0.1/127.0.0.1:22058, unexpected error, closing socket connection and attempting reconnect [junit] java.net.ConnectException: Connection refused [junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) [junit] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:739) [junit] at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:357) [junit] at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1214) [junit] 2017-07-15 20:01:33,716 [myid:127.0.0.1:22117] - INFO [main-SendThread(127.0.0.1:22117):ClientCnxn$SendThread@1113] - Opening socket connection to server 127.0.0.1/127.0.0.1:22117. Will not attempt to authenticate using SASL (unknown error) [junit] 2017-07-15 20:01:33,717 [myid:127.0.0.1:22117] - WARN [main-SendThread(127.0.0.1:22117):ClientCnxn$SendThread@1235] - Session 0x10572c7d6f3 for server 127.0.0.1/127.0.0.1:22117, unexpected error, closing socket connection and attempting reconnect [junit] java.net.ConnectException: Connection refused [junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) [junit] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:739) [junit] at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:357) [junit] at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1214) [junit] 2017-07-15 20:01:33,760 [myid:127.0.0.1:22043] - INFO [main-SendThread(127.0.0.1:22043):ClientCnxn$SendThread@1113] - Opening socket connection to server 127.0.0.1/127.0.0.1:22043. Will not attempt to authenticate using SASL (unknown error) [junit] 2017-07-15 20:01:33,761 [myid:127.0.0.1:22043] - WARN [main-SendThread(127.0.0.1:22043):ClientCnxn$SendThread@1235] - Session 0x10572c5185c0001 for server 127.0.0.1/127.0.0.1:22043, unexpected error, closing socket connection and attempting reconnect [junit] java.net.ConnectException: Connection refused [junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method) [junit] at sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:739) [junit] at org.apache.zookeeper.ClientCnxnSocketNIO.doTransport(ClientCnxnSocketNIO.java:357) [junit] at org.apache.zookeeper.ClientCnxn$SendThread.run(ClientCnxn.java:1214) [junit] 2017-07-15 20:01:33,967 [myid:] - INFO [ProcessThread(sid:0 cport:22240)::PrepRequestProcessor@614] - Processed session termination for sessionid: 0x10572cb29fa [junit] 2017-07-15 20:01:33,968 [myid:] - INFO [SyncThread:0:MBeanRegistry@128] - Unregister MBean [org.apache.ZooKeeperService:name0=StandaloneServer_port22240,name1=Connections,name2=127.0.0.1,name3=0x10572cb29fa] [junit] 2017-07-15 20:01:33,968 [myid:] - INFO [main:ZooKeeper@1329] - Session: 0x10572cb29fa closed [junit] 2017-07-15 20:01:33,968 [myid:] - INFO [main-EventThread:ClientCnxn$EventThread@513] - EventThread shut down for session: 0x10572cb29fa [junit] 2017-07-15 20:01:33,968 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@82] - Memory used 213778 [junit] 2017-07-15 20:01:33,969 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@87] - Number of threads 2431 [junit] 2017-07-15 20:01:33,969 [myid:] - INFO [main:JUnit4ZKTestRunner$LoggedInvokeMethod@102] - FINISHED TEST METHOD testWatcherAutoResetWithLocal [junit] 2017-07-15 20:01:33,969 [myid:] - INFO [main:ClientBase@601] - tearDown starting [junit] 2017-07-15 20:01:33,969 [myid:] - INFO [main:ClientBase@571] - STOPPING server [junit] 2017-07-15 20:01:33,969 [myid:] - INFO [main:NettyServerCnxnFactory@464] - shutdown called 0.0.0.0/0.0.0.0:22240 [junit] 2017-07-15 20:01:33,979 [myid:] - INFO [main:ZooKeeperServer@541] - shutting down [junit] 2017-07-15 20:01:33,979 [myid:] - ERROR [main:ZooKeeperServer@505] - ZKShutdownHandler is not registered, so ZooKeeper server won't take any action on ERROR or SHUTDOWN server state changes [junit] 2017-07-15 20:01:33,980 [myid:] - INFO [main:SessionTrackerImpl@232] - Shutting down [junit] 2017-07-15 20:01:33,980 [myid:] - INFO [main:PrepRequestProcessor@1008] - Shutting down [junit] 2017-07-1
ZooKeeper_branch35_jdk8 - Build # 601 - Still Failing
See https://builds.apache.org/job/ZooKeeper_branch35_jdk8/601/
###
## LAST 60 LINES OF THE CONSOLE
###
[...truncated 64.78 MB...]
[junit] java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:24810
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:14:19,523 [myid:] - INFO [New I/O boss
#2763:ClientCnxnSocketNetty@208] - channel is told closing
[junit] 2017-07-15 12:14:19,524 [myid:127.0.0.1:24810] - INFO
[main-SendThread(127.0.0.1:24810):ClientCnxn$SendThread@1231] - channel for
sessionid 0x1068bf7fc21 is lost, closing socket connection and attempting
reconnect
[junit] 2017-07-15 12:14:19,670 [myid:127.0.0.1:24813] - INFO
[main-SendThread(127.0.0.1:24813):ClientCnxn$SendThread@1113] - Opening socket
connection to server 127.0.0.1/127.0.0.1:24813. Will not attempt to
authenticate using SASL (unknown error)
[junit] 2017-07-15 12:14:19,672 [myid:] - INFO [New I/O boss
#2772:ClientCnxnSocketNetty$1@127] - future isn't success, cause: {}
[junit] java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:24813
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:14:19,672 [myid:] - WARN [New I/O boss
#2772:ClientCnxnSocketNetty$ZKClientHandler@439] - Exception caught: [id:
0x2eb7b6d9] EXCEPTION: java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:24813
[junit] java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:24813
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:14:19,672 [myid:
ZooKeeper-trunk-jdk8 - Build # 1129 - Still Failing
See https://builds.apache.org/job/ZooKeeper-trunk-jdk8/1129/
###
## LAST 60 LINES OF THE CONSOLE
###
[...truncated 58.63 MB...]
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:03:32,303 [myid:] - INFO [New I/O boss
#5253:ClientCnxnSocketNetty@208] - channel is told closing
[junit] 2017-07-15 12:03:32,303 [myid:127.0.0.1:19430] - INFO
[main-SendThread(127.0.0.1:19430):ClientCnxn$SendThread@1231] - channel for
sessionid 0x304bf901174 is lost, closing socket connection and attempting
reconnect
[junit] 2017-07-15 12:03:32,350 [myid:127.0.0.1:19424] - INFO
[main-SendThread(127.0.0.1:19424):ClientCnxn$SendThread@1113] - Opening socket
connection to server 127.0.0.1/127.0.0.1:19424. Will not attempt to
authenticate using SASL (unknown error)
[junit] 2017-07-15 12:03:32,351 [myid:] - INFO [New I/O boss
#5219:ClientCnxnSocketNetty$1@127] - future isn't success, cause: {}
[junit] java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:19424
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:03:32,351 [myid:] - WARN [New I/O boss
#5219:ClientCnxnSocketNetty$ZKClientHandler@439] - Exception caught: [id:
0xe633d371] EXCEPTION: java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:19424
[junit] java.net.ConnectException: Connection refused:
127.0.0.1/127.0.0.1:19424
[junit] at sun.nio.ch.SocketChannelImpl.checkConnect(Native Method)
[junit] at
sun.nio.ch.SocketChannelImpl.finishConnect(SocketChannelImpl.java:717)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.connect(NioClientBoss.java:152)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.processSelectedKeys(NioClientBoss.java:105)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.process(NioClientBoss.java:79)
[junit] at
org.jboss.netty.channel.socket.nio.AbstractNioSelector.run(AbstractNioSelector.java:337)
[junit] at
org.jboss.netty.channel.socket.nio.NioClientBoss.run(NioClientBoss.java:42)
[junit] at
org.jboss.netty.util.ThreadRenamingRunnable.run(ThreadRenamingRunnable.java:108)
[junit] at
org.jboss.netty.util.internal.DeadLockProofWorker$1.run(DeadLockProofWorker.java:42)
[junit] at
java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
[junit] at
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
[junit] at java.lang.Thread.run(Thread.java:748)
[junit] 2017-07-15 12:03:32,351 [myid:] - INFO [New I/O boss
#5219:ClientCnxnSocketNetty@208] - channel is told closing
