ZooKeeper
  1. ZooKeeper
  2. ZOOKEEPER-1146

significant regression in client (c/python) performance

    Details

    • Type: Bug Bug
    • Status: Closed
    • Priority: Blocker Blocker
    • Resolution: Fixed
    • Affects Version/s: 3.4.0
    • Fix Version/s: 3.4.0
    • Component/s: c client
    • Labels:
      None
    • Hadoop Flags:
      Reviewed

      Description

      I tried running my latency tester against trunk, in so doing I noticed that the C/Python (not sure which yet) client performance has seriously degraded since 3.3.3.

      The first run (below) is with released 3.3.3 client against a 3 server ensemble running released 3.3.3 server code. The second run is the exact same environment (same ensemble), however using trunk c/zkpython client.

      Notice:

      1) in the first run operations are approx 10ms/write, 0.25ms/read - which is pretty much what's expected.

      2) however in the second run we are seeing 50ms/operation regardless of read or write.

      [phunt@c0309 zk-smoketest-3.3.3]$ PYTHONPATH=lib.linux-x86_64-2.6/ LD_LIBRARY_PATH=lib.linux-x86_64-2.6/ python26 ./zk-latencies.py --servers "c0309:2181,c0310:2181,c0311:2181" --znode_size=100 --znode_count=100 --timeout=5000 --synchronous
      Connecting to c0309:2181
      Connected in 16 ms, handle is 0
      Connecting to c0310:2181
      Connected in 16 ms, handle is 1
      Connecting to c0311:2181
      Connected in 15 ms, handle is 2
      Testing latencies on server c0309:2181 using syncronous calls
      created     100 permanent znodes  in    959 ms (9.599378 ms/op 104.173415/sec)
      set         100           znodes  in    933 ms (9.332101 ms/op 107.157002/sec)
      get         100           znodes  in     27 ms (0.270889 ms/op 3691.551589/sec)
      deleted     100 permanent znodes  in    881 ms (8.812950 ms/op 113.469388/sec)
      created     100 ephemeral znodes  in    956 ms (9.564152 ms/op 104.557103/sec)
      watched     100           znodes  in     26 ms (0.264361 ms/op 3782.707587/sec)
      deleted     100 ephemeral znodes  in    881 ms (8.819292 ms/op 113.387792/sec)
      notif       100           watches in    999 ms (9.994299 ms/op 100.057038/sec)
      Testing latencies on server c0310:2181 using syncronous calls
      created     100 permanent znodes  in    964 ms (9.640460 ms/op 103.729490/sec)
      set         100           znodes  in    933 ms (9.332800 ms/op 107.148981/sec)
      get         100           znodes  in     29 ms (0.299308 ms/op 3341.036650/sec)
      deleted     100 permanent znodes  in    886 ms (8.864651 ms/op 112.807603/sec)
      created     100 ephemeral znodes  in    958 ms (9.585140 ms/op 104.328161/sec)
      watched     100           znodes  in     30 ms (0.300801 ms/op 3324.459240/sec)
      deleted     100 ephemeral znodes  in    886 ms (8.865030 ms/op 112.802779/sec)
      notif       100           watches in   1000 ms (10.000212 ms/op 99.997878/sec)
      Testing latencies on server c0311:2181 using syncronous calls
      created     100 permanent znodes  in    958 ms (9.582071 ms/op 104.361569/sec)
      set         100           znodes  in    935 ms (9.359350 ms/op 106.845024/sec)
      get         100           znodes  in     25 ms (0.252700 ms/op 3957.263893/sec)
      deleted     100 permanent znodes  in    891 ms (8.913291 ms/op 112.192013/sec)
      created     100 ephemeral znodes  in    958 ms (9.584489 ms/op 104.335246/sec)
      watched     100           znodes  in     25 ms (0.251091 ms/op 3982.627356/sec)
      deleted     100 ephemeral znodes  in    891 ms (8.915379 ms/op 112.165730/sec)
      notif       100           watches in   1000 ms (10.000508 ms/op 99.994922/sec)
      Latency test complete
      [phunt@c0309 zk-smoketest-3.3.3]$ cd ../zk-smoketest-trunk/
      [phunt@c0309 zk-smoketest-trunk]$ PYTHONPATH=lib.linux-x86_64-2.6/ LD_LIBRARY_PATH=lib.linux-x86_64-2.6/ python26 ./zk-latencies.py --servers "c0309:2181,c0310:2181,c0311:2181" --znode_size=100 --znode_count=100 --timeout=5000 --synchronous
      Connecting to c0309:2181
      Connected in 31 ms, handle is 0
      Connecting to c0310:2181
      Connected in 16 ms, handle is 1
      Connecting to c0311:2181
      Connected in 16 ms, handle is 2
      Testing latencies on server c0309:2181 using syncronous calls
      created     100 permanent znodes  in   5099 ms (50.999281 ms/op 19.608119/sec)
      set         100           znodes  in   5066 ms (50.665429 ms/op 19.737324/sec)
      get         100           znodes  in   4009 ms (40.093150 ms/op 24.941916/sec)
      deleted     100 permanent znodes  in   5040 ms (50.404449 ms/op 19.839519/sec)
      created     100 ephemeral znodes  in   5124 ms (51.249170 ms/op 19.512511/sec)
      watched     100           znodes  in   4051 ms (40.514441 ms/op 24.682557/sec)
      deleted     100 ephemeral znodes  in   5048 ms (50.484939 ms/op 19.807888/sec)
      notif       100           watches in   1000 ms (10.004182 ms/op 99.958199/sec)
      Testing latencies on server c0310:2181 using syncronous calls
      created     100 permanent znodes  in   5115 ms (51.157510 ms/op 19.547472/sec)
      set         100           znodes  in   5056 ms (50.568910 ms/op 19.774996/sec)
      get         100           znodes  in   4099 ms (40.999382 ms/op 24.390612/sec)
      deleted     100 permanent znodes  in   5041 ms (50.418010 ms/op 19.834182/sec)
      created     100 ephemeral znodes  in   5083 ms (50.835850 ms/op 19.671157/sec)
      watched     100           znodes  in   4100 ms (41.003261 ms/op 24.388304/sec)
      deleted     100 ephemeral znodes  in   5058 ms (50.581930 ms/op 19.769906/sec)
      notif       100           watches in   1000 ms (10.005081 ms/op 99.949219/sec)
      Testing latencies on server c0311:2181 using syncronous calls
      created     100 permanent znodes  in   5099 ms (50.992720 ms/op 19.610642/sec)
      set         100           znodes  in   5091 ms (50.916569 ms/op 19.639972/sec)
      get         100           znodes  in   4099 ms (40.996401 ms/op 24.392385/sec)
      deleted     100 permanent znodes  in   5066 ms (50.669601 ms/op 19.735699/sec)
      created     100 ephemeral znodes  in   5124 ms (51.249208 ms/op 19.512496/sec)
      watched     100           znodes  in   4099 ms (40.999141 ms/op 24.390755/sec)
      deleted     100 ephemeral znodes  in   5049 ms (50.498819 ms/op 19.802443/sec)
      notif       100           watches in    999 ms (9.997852 ms/op 100.021486/sec)
      Latency test complete
      

        Activity

        Hide
        Patrick Hunt added a comment -

        Please create a new jira and attach the patch to that - thanks!

        Show
        Patrick Hunt added a comment - Please create a new jira and attach the patch to that - thanks!
        Hide
        Dheeraj Agrawal added a comment -

        Yes, we can use it as int. Although while testing on windows, it didn't return an error code, which i would have expected, if there were any issues.

        If we change this to int for both unix/windows, we will need to change the setsockopt and have ifdef around it to avoid warnings. Optval is char* for windows, so we will need a cast to (char*) around the optval.

        int setsockopt(int s, int level, int optname, const void *optval, socklen_t optlen);
        int setsockopt(
        __in SOCKET s,
        __in int level,
        __in int optname,
        __in const char *optval,
        __in int optlen
        );

        setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, (char*) &on, sizeof(int));

        Can you submit a patch for this?

        Show
        Dheeraj Agrawal added a comment - Yes, we can use it as int. Although while testing on windows, it didn't return an error code, which i would have expected, if there were any issues. If we change this to int for both unix/windows, we will need to change the setsockopt and have ifdef around it to avoid warnings. Optval is char* for windows, so we will need a cast to (char*) around the optval. int setsockopt(int s, int level, int optname, const void *optval, socklen_t optlen); int setsockopt( __in SOCKET s, __in int level, __in int optname, __in const char *optval, __in int optlen ); setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, (char*) &on, sizeof(int)); Can you submit a patch for this?
        Hide
        Brodie Thiesfield added a comment -

        This fix is incorrect, Windows uses an int not a char for this socket option, just like the rest of the world.

        Ref: http://msdn.microsoft.com/en-us/library/ms740476%28v=vs.85%29.aspx
        level = IPPROTO_TCP
        Value Type Description
        TCP_NODELAY BOOL Disables the Nagle algorithm for send coalescing.

        So what is a "BOOL"?
        http://msdn.microsoft.com/en-us/library/aa383751%28v=vs.85%29.aspx
        BOOL
        A Boolean variable (should be TRUE or FALSE).
        This type is declared in WinDef.h as follows:
        typedef int BOOL;

        The fix should be changed from an ifdef on WIN32 to just the int...

        int enable_tcp_nodelay = 1;

        Show
        Brodie Thiesfield added a comment - This fix is incorrect, Windows uses an int not a char for this socket option, just like the rest of the world. Ref: http://msdn.microsoft.com/en-us/library/ms740476%28v=vs.85%29.aspx level = IPPROTO_TCP Value Type Description TCP_NODELAY BOOL Disables the Nagle algorithm for send coalescing. So what is a "BOOL"? http://msdn.microsoft.com/en-us/library/aa383751%28v=vs.85%29.aspx BOOL A Boolean variable (should be TRUE or FALSE). This type is declared in WinDef.h as follows: typedef int BOOL; The fix should be changed from an ifdef on WIN32 to just the int... int enable_tcp_nodelay = 1;
        Hide
        Hudson added a comment -

        Integrated in ZooKeeper-trunk #1266 (See https://builds.apache.org/job/ZooKeeper-trunk/1266/)
        ZOOKEEPER-1146. significant regression in client (c/python) performance. (phunt via mahadev)

        mahadev : http://svn.apache.org/viewcvs.cgi/?root=Apache-SVN&view=rev&rev=1157574
        Files :

        • /zookeeper/trunk/src/c/src/zookeeper.c
        • /zookeeper/trunk/CHANGES.txt
        Show
        Hudson added a comment - Integrated in ZooKeeper-trunk #1266 (See https://builds.apache.org/job/ZooKeeper-trunk/1266/ ) ZOOKEEPER-1146 . significant regression in client (c/python) performance. (phunt via mahadev) mahadev : http://svn.apache.org/viewcvs.cgi/?root=Apache-SVN&view=rev&rev=1157574 Files : /zookeeper/trunk/src/c/src/zookeeper.c /zookeeper/trunk/CHANGES.txt
        Hide
        Mahadev konar added a comment -

        I just pushed this. thanks pat!

        Show
        Mahadev konar added a comment - I just pushed this. thanks pat!
        Hide
        Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12489411/ZOOKEEPER-1146.patch
        against trunk revision 1152141.

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no new tests are needed for this patch.
        Also please list what manual steps were performed to verify this patch.

        +1 javadoc. The javadoc tool did not generate any warning messages.

        +1 javac. The applied patch does not increase the total number of javac compiler warnings.

        +1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings.

        +1 release audit. The applied patch does not increase the total number of release audit warnings.

        +1 core tests. The patch passed core unit tests.

        +1 contrib tests. The patch passed contrib unit tests.

        Test results: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//testReport/
        Findbugs warnings: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
        Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//console

        This message is automatically generated.

        Show
        Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12489411/ZOOKEEPER-1146.patch against trunk revision 1152141. +1 @author. The patch does not contain any @author tags. -1 tests included. The patch doesn't appear to include any new or modified tests. Please justify why no new tests are needed for this patch. Also please list what manual steps were performed to verify this patch. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. +1 core tests. The patch passed core unit tests. +1 contrib tests. The patch passed contrib unit tests. Test results: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//testReport/ Findbugs warnings: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/439//console This message is automatically generated.
        Hide
        Hadoop QA added a comment -

        -1 overall. Here are the results of testing the latest attachment
        http://issues.apache.org/jira/secure/attachment/12489411/ZOOKEEPER-1146.patch
        against trunk revision 1152141.

        +1 @author. The patch does not contain any @author tags.

        -1 tests included. The patch doesn't appear to include any new or modified tests.
        Please justify why no new tests are needed for this patch.
        Also please list what manual steps were performed to verify this patch.

        +1 javadoc. The javadoc tool did not generate any warning messages.

        +1 javac. The applied patch does not increase the total number of javac compiler warnings.

        +1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings.

        +1 release audit. The applied patch does not increase the total number of release audit warnings.

        +1 core tests. The patch passed core unit tests.

        +1 contrib tests. The patch passed contrib unit tests.

        Test results: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//testReport/
        Findbugs warnings: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html
        Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//console

        This message is automatically generated.

        Show
        Hadoop QA added a comment - -1 overall. Here are the results of testing the latest attachment http://issues.apache.org/jira/secure/attachment/12489411/ZOOKEEPER-1146.patch against trunk revision 1152141. +1 @author. The patch does not contain any @author tags. -1 tests included. The patch doesn't appear to include any new or modified tests. Please justify why no new tests are needed for this patch. Also please list what manual steps were performed to verify this patch. +1 javadoc. The javadoc tool did not generate any warning messages. +1 javac. The applied patch does not increase the total number of javac compiler warnings. +1 findbugs. The patch does not introduce any new Findbugs (version 1.3.9) warnings. +1 release audit. The applied patch does not increase the total number of release audit warnings. +1 core tests. The patch passed core unit tests. +1 contrib tests. The patch passed contrib unit tests. Test results: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//testReport/ Findbugs warnings: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//artifact/trunk/build/test/findbugs/newPatchFindbugsWarnings.html Console output: https://builds.apache.org/job/PreCommit-ZOOKEEPER-Build/433//console This message is automatically generated.
        Hide
        Dheeraj Agrawal added a comment -

        tested this on windows and dont see any issues. Thanks Patrick ...

        Show
        Dheeraj Agrawal added a comment - tested this on windows and dont see any issues. Thanks Patrick ...
        Hide
        Camille Fournier added a comment -

        I'll have Dheeraj take a look at this in win32 next week and make sure it all checks out.

        Show
        Camille Fournier added a comment - I'll have Dheeraj take a look at this in win32 next week and make sure it all checks out.
        Hide
        Benjamin Reed added a comment -

        +1 looks good. great job tracking it down pat!

        Show
        Benjamin Reed added a comment - +1 looks good. great job tracking it down pat!
        Hide
        Patrick Hunt added a comment -

        This patch fixes the issue on Linux and also logs a WARNING if it fails.

        I believe this will compile/test successfully on win32 but I'm not sure as I don't have a setup to test it (although I did look at the docs and afaict it should work). Would be good for someone on the win32 side to verify.

        Show
        Patrick Hunt added a comment - This patch fixes the issue on Linux and also logs a WARNING if it fails. I believe this will compile/test successfully on win32 but I'm not sure as I don't have a setup to test it (although I did look at the docs and afaict it should work). Would be good for someone on the win32 side to verify.
        Hide
        Patrick Hunt added a comment -

        turns out this change is responsible:

        -            setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, &on, sizeof(int));
        +            setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, &on, sizeof(char));
        

        setsockopt is returning -1 after this change (failed to set). Without this change the performance is as expected.

        I'll craft a patch or this.

        Show
        Patrick Hunt added a comment - turns out this change is responsible: - setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, &on, sizeof(int)); + setsockopt(zh->fd, IPPROTO_TCP, TCP_NODELAY, &on, sizeof(char)); setsockopt is returning -1 after this change (failed to set). Without this change the performance is as expected. I'll craft a patch or this.
        Hide
        Patrick Hunt added a comment -

        I've narrowed this down to the following commit:

        ZOOKEEPER-992. MT Native Version of Windows C Client (Dheeraj Agrawal via michim)

        prior to this 10ms/op, subsequent to this patch 50ms/op.

        Show
        Patrick Hunt added a comment - I've narrowed this down to the following commit: ZOOKEEPER-992 . MT Native Version of Windows C Client (Dheeraj Agrawal via michim) prior to this 10ms/op, subsequent to this patch 50ms/op.
        Hide
        Patrick Hunt added a comment -

        I reviewed all the changes that went into zkpython btw 3.3.3 and current trunk, I don't see anything that would account for this. Fairly certain this must be a c client change.

        Show
        Patrick Hunt added a comment - I reviewed all the changes that went into zkpython btw 3.3.3 and current trunk, I don't see anything that would account for this. Fairly certain this must be a c client change.

          People

          • Assignee:
            Patrick Hunt
            Reporter:
            Patrick Hunt
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development