Uploaded image for project: 'ZooKeeper'
  1. ZooKeeper
  2. ZOOKEEPER-1661

Random (?) 5s delay when establishing connection

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Open
    • Major
    • Resolution: Unresolved
    • 3.4.5
    • None
    • server
    • None

    Description

      I have a client connecting to ZooKeeper and I am sometimes seeing a 5s delay before the opening of the socket connection:

      Here is the output on the client side:

      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:zookeeper.version=3.4.5-1392090, built on 09/30/2012 17:52 GMT
      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:host.name=xeon
      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.version=1.6.0_41
      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.vendor=Apple Inc.
      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.home=/System/Library/Java/JavaVirtualMachines/1.6.0.jdk/Contents/Home
      2013/03/07 10:53:48.729 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.class.path=/local/java/lib/tools.jar:lib/ant-1.8.4.jar:lib/ant-antlr-1.8.4.jar:lib/ant-junit-1.8.4.jar:lib/ant-launcher-1.8.4.jar:lib/antlr-2.7.7.jar:lib/asm-4.0.jar:lib/asm-analysis-4.0.jar:lib/asm-commons-4.0.jar:lib/asm-tree-4.0.jar:lib/asm-util-4.0.jar:lib/commons-cli-1.2.jar:lib/groovy-2.0.7.jar:lib/groovy-ant-2.0.7.jar:lib/groovy-groovydoc-2.0.7.jar:lib/groovy-templates-2.0.7.jar:lib/groovy-xml-2.0.7.jar:lib/jackson-annotations-2.1.4.jar:lib/jackson-core-2.1.4.jar:lib/jackson-databind-2.1.4.jar:lib/jline-0.9.94.jar:lib/json-20090211.jar:lib/jul-to-slf4j-1.6.2.jar:lib/junit-3.8.1.jar:lib/log4j-1.2.16.jar:lib/netty-3.2.2.Final.jar:lib/org.linkedin.util-core-1.8.glu47.0.jar:lib/org.linkedin.util-groovy-1.8.glu47.0.jar:lib/org.linkedin.zookeeper-cli-impl-1.5.glu47.0-SNAPSHOT.jar:lib/org.linkedin.zookeeper-impl-1.5.glu47.0-SNAPSHOT.jar:lib/slf4j-api-1.6.2.jar:lib/slf4j-log4j12-1.6.2.jar:lib/zookeeper-3.4.5.jar
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.library.path=/local/instantclient10:.:/Users/ypujante/Library/Java/Extensions:/Library/Java/Extensions:/System/Library/Java/Extensions:/usr/lib/java
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.io.tmpdir=/var/folders/dj/qmkmx5648xjf2n006s7hc1v80000gq/T/
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:java.compiler=<NA>
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.name=Mac OS X
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.arch=x86_64
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:os.version=10.8.2
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.name=ypujante
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.home=/Users/ypujante
      2013/03/07 10:53:48.730 INFO [org.apache.zookeeper.ZooKeeper] Client environment:user.dir=/export/content/linkedin-zookeeper/org.linkedin.zookeeper-cli-1.5.glu47.0-SNAPSHOT
      2013/03/07 10:53:48.731 INFO [org.apache.zookeeper.ZooKeeper] Initiating client connection, connectString=localhost:2181 sessionTimeout=100 watcher=org.linkedin.zookeeper.client.ZKClient@3823bdd1
      2013/03/07 10:53:48.737 DEBUG [org.apache.zookeeper.ClientCnxn] zookeeper.disableAutoWatchReset is false
      2013/03/07 10:53:48.756 DEBUG [org.linkedin.zookeeper.cli.ClientMain] Talking to zookeeper on localhost:2181
      2013/03/07 10:53:53.763 INFO [org.apache.zookeeper.ClientCnxn] Opening socket connection to server fe80:0:0:0:0:0:0:1%1/fe80:0:0:0:0:0:0:1%1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration)
      

      From this output you can see the line at 10:53:48 => Initiating client connection
      And then 5s later, at 10:53:53 => opening socket connection

      Note that I did not see this delay/problem prior to upgrading to 3.4.5 (from 3.3.3)

      Also note that sometimes there is no delay as in the following output!

      2013/03/07 11:04:06.084 INFO [org.apache.zookeeper.ZooKeeper] Initiating client connection, connectString=localhost:2181 sessionTimeout=100 watcher=org.linkedin.zookeeper.client.ZKClient@1e670479
      2013/03/07 11:04:06.089 DEBUG [org.apache.zookeeper.ClientCnxn] zookeeper.disableAutoWatchReset is false
      2013/03/07 11:04:06.109 DEBUG [org.linkedin.zookeeper.cli.ClientMain] Talking to zookeeper on localhost:2181
      2013/03/07 11:04:06.116 INFO [org.apache.zookeeper.ClientCnxn] Opening socket connection to server localhost/0:0:0:0:0:0:0:1:2181. Will not attempt to authenticate using SASL (Unable to locate a login configuration)
      

      I will be more than happy to provide more details if necessary. The client code is open source and hosted on github @ https://github.com/linkedin/linkedin-zookeeper/blob/master/org.linkedin.zookeeper-cli-impl/src/main/groovy/org/linkedin/zookeeper/cli/ClientMain.groovy#L65

      and is not doing mech but (under the cover)

      new ZooKeeper("localhost:2181", 100, watcher)

      and then wait until the SyncConnected even is received...

      Thanks
      Yan

      Attachments

        Issue Links

          Activity

            People

              Unassigned Unassigned
              ypujante Yan Pujante
              Votes:
              1 Vote for this issue
              Watchers:
              6 Start watching this issue

              Dates

                Created:
                Updated: