Hello Everyone, We are also using zookeeper 3.6.2 with ssl turned on both sides. We observed the same behaviour where under high write load the ZK server starts expiring the session. There are no jvm related issues. During high load the max latency increases significantly.
Also the session expiration message is not accurate. We do have session expiration set to 40 sec but ZK server disconnects the client within 10 sec. Also the logs prints throttling the request but ZK documentation says throttling is disabled by default. Can someone check the code once to see if it is enabled or disabled. I am not a developer and hence not familiar with java code. Thanks Srikant Kalani On Wed, 21 Apr 2021 at 11:03 AM, Michael Han <h...@apache.org> wrote: > What is the workload looking like? Is it pure write, or mixed read write? > > A couple of ideas to move this forward: > * Publish the performance benchmark so the community can help. > * Bisect git commit and find the bad commit that caused the regression. > * Use the fine grained metrics introduced in 3.6 (e.g per processor stage > metrics) to measure where time spends during writes. We might have to add > these metrics on 3.4 to get a fair comparison. > > For the throttling - the RequestThrottler introduced in 3.6 does introduce > latency, but should not impact throughput this much. > > On Thu, Mar 11, 2021 at 11:46 AM Li Wang <li4w...@gmail.com> wrote: > > > The CPU usage of both server and client are normal (< 50%) during the > test. > > > > Based on the investigation, the server is too busy with the load. > > > > The issue doesn't exist in 3.4.14. I wonder why there is a significant > > write performance degradation from 3.4.14 to 3.6.2 and how we can address > > the issue. > > > > Best, > > > > Li > > > > > > > > > > > > > > > > > > > > > > > > On Thu, Mar 11, 2021 at 11:25 AM Andor Molnar <an...@apache.org> wrote: > > > > > What is the CPU usage of both server and client during the test? > > > > > > Looks like server is dropping the clients because either the server or > > > both are too busy to deal with the load. > > > This log line is also concerning: "Too busy to snap, skipping” > > > > > > If that’s the case I believe you'll have to profile the server process > to > > > figure out where the perf bottleneck is. > > > > > > Andor > > > > > > > > > > > > > > > > On 2021. Feb 22., at 5:31, Li Wang <li4w...@gmail.com> wrote: > > > > > > > > Thanks, Patrick. > > > > > > > > Yes, we are using the same JVM version and GC configurations when > > > > running the two tests. I have checked the GC metrics and also the > heap > > > dump > > > > of the 3.6, the GC pause and the memory usage look okay. > > > > > > > > Best, > > > > > > > > Li > > > > > > > > On Sun, Feb 21, 2021 at 3:34 PM Patrick Hunt <ph...@apache.org> > wrote: > > > > > > > >> On Sun, Feb 21, 2021 at 3:28 PM Li Wang <li4w...@gmail.com> wrote: > > > >> > > > >>> Hi Enrico, Sushant, > > > >>> > > > >>> I re-run the perf test with the data consistency check feature > > disabled > > > >>> (i.e. -Dzookeeper.digest.enabled=false), the write performance > issue > > of > > > >> 3.6 > > > >>> is still there. > > > >>> > > > >>> With everything exactly the same, the throughput of 3.6 was only > 1/2 > > of > > > >> 3.4 > > > >>> and the max latency was more than 8 times. > > > >>> > > > >>> Any other points or thoughts? > > > >>> > > > >>> > > > >> In the past I've noticed a big impact of GC when doing certain > > > performance > > > >> measurements. I assume you are using the same JVM version and GC > when > > > >> running the two tests? Perhaps our memory footprint has expanded > over > > > time. > > > >> You should rule out GC by running with gc logging turned on with > both > > > >> versions and compare the impact. > > > >> > > > >> Regards, > > > >> > > > >> Patrick > > > >> > > > >> > > > >>> Cheers, > > > >>> > > > >>> Li > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> > > > >>> On Sat, Feb 20, 2021 at 9:04 PM Li Wang <li4w...@gmail.com> wrote: > > > >>> > > > >>>> Thanks Sushant and Enrico! > > > >>>> > > > >>>> This is a really good point. According to the 3.6 documentation, > > the > > > >>>> feature is disabled by default. > > > >>>> > > > >>> > > > >> > > > > > > https://zookeeper.apache.org/doc/r3.6.2/zookeeperAdmin.html#ch_administration > > > >>> . > > > >>>> However, checking the code, the default is enabled. > > > >>>> > > > >>>> Let me set the zookeeper.digest.enabled to false and see how the > > write > > > >>>> operation performs. > > > >>>> > > > >>>> Best, > > > >>>> > > > >>>> Li > > > >>>> > > > >>>> > > > >>>> > > > >>>> > > > >>>> On Fri, Feb 19, 2021 at 1:32 PM Sushant Mane < > > sushantma...@gmail.com> > > > >>>> wrote: > > > >>>> > > > >>>>> Hi Li, > > > >>>>> > > > >>>>> On 3.6.2 consistency checker (adhash based) is enabled by > default: > > > >>>>> > > > >>>>> > > > >>> > > > >> > > > > > > https://github.com/apache/zookeeper/blob/803c7f1a12f85978cb049af5e4ef23bd8b688715/zookeeper-server/src/main/java/org/apache/zookeeper/server/ZooKeeperServer.java#L136 > > > >>>>> . > > > >>>>> It is not present in ZK 3.4.14. > > > >>>>> > > > >>>>> This feature does have some impact on write performance. > > > >>>>> > > > >>>>> Thanks, > > > >>>>> Sushant > > > >>>>> > > > >>>>> > > > >>>>> On Fri, Feb 19, 2021 at 12:50 PM Enrico Olivelli < > > > eolive...@gmail.com > > > >>> > > > >>>>> wrote: > > > >>>>> > > > >>>>>> Li, > > > >>>>>> I wonder of we have some new throttling/back pressure mechanisms > > > >> that > > > >>> is > > > >>>>>> enabled by default. > > > >>>>>> > > > >>>>>> Does anyone has some pointer to relevant implementations? > > > >>>>>> > > > >>>>>> > > > >>>>>> Enrico > > > >>>>>> > > > >>>>>> Il Ven 19 Feb 2021, 19:46 Li Wang <li4w...@gmail.com> ha > scritto: > > > >>>>>> > > > >>>>>>> Hi, > > > >>>>>>> > > > >>>>>>> We switched to Netty on both client side and server side and > the > > > >>>>>>> performance issue is still there. Anyone has any insights on > > what > > > >>>>> could > > > >>>>>> be > > > >>>>>>> the cause of higher latency? > > > >>>>>>> > > > >>>>>>> Thanks, > > > >>>>>>> > > > >>>>>>> Li > > > >>>>>>> > > > >>>>>>> > > > >>>>>>> > > > >>>>>>> On Mon, Feb 15, 2021 at 2:17 PM Li Wang <li4w...@gmail.com> > > > >> wrote: > > > >>>>>>> > > > >>>>>>>> Hi Enrico, > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> Thanks for the reply. > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 1. We are using NIO based stack, not Netty based yet. > > > >>>>>>>> > > > >>>>>>>> 2. Yes, here are some metrics on the client side. > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 3.6: throughput: 7K, failure: 81215228, Avg Latency: 57ms, > Max > > > >>>>> Latency > > > >>>>>>> 31s > > > >>>>>>>> > > > >>>>>>>> 3.4: throughput: 15k, failure: 0, Avg Latency: 30ms, Max > > > >>> Latency: > > > >>>>>> 1.6s > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 3. Yes, the JVM and zoo.cfg config are the exact same > > > >>>>>>>> > > > >>>>>>>> 10G of Heap > > > >>>>>>>> > > > >>>>>>>> 13G of Memory > > > >>>>>>>> > > > >>>>>>>> 5 Participante > > > >>>>>>>> > > > >>>>>>>> 5 Observere > > > >>>>>>>> > > > >>>>>>>> Client session timeout: 3000ms > > > >>>>>>>> > > > >>>>>>>> Server min session time: 4000ms > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 4. Yes, there are two types of WARN logs and many “Expiring > > > >>>>> session” > > > >>>>>>>> INFO log > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 2021-02-15 22:04:36,506 [myid:4] - WARN > > > >>>>>>>> [NIOWorkerThread-7:NIOServerCnxn@365] - Unexpected exception > > > >>>>>>>> > > > >>>>>>>> EndOfStreamException: Unable to read additional data from > > > >> client, > > > >>> it > > > >>>>>>>> probably closed the socket: address = /100.108.63.116:43366, > > > >>>>> session = > > > >>>>>>>> 0x400189fee9a000b > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>> > > > >> > > > > > > org.apache.zookeeper.server.NIOServerCnxn.handleFailedRead(NIOServerCnxn.java:164) > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>> > > > >> > org.apache.zookeeper.server.NIOServerCnxn.doIO(NIOServerCnxn.java:327) > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>> > > > >> > > > > > > org.apache.zookeeper.server.NIOServerCnxnFactory$IOWorkRequest.doWork(NIOServerCnxnFactory.java:522) > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>> > > > >> > > > > > > org.apache.zookeeper.server.WorkerService$ScheduledWorkRequest.run(WorkerService.java:154) > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>> > > > >> > > > > > > java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1128) > > > >>>>>>>> > > > >>>>>>>> at > > > >>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>> > > > >> > > > > > > java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:628) > > > >>>>>>>> > > > >>>>>>>> at java.base/java.lang.Thread.run(Thread.java:834) > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 2021-02-15 22:05:14,428 [myid:4] - WARN > > > >>>>>>>> [SyncThread:4:SyncRequestProcessor@188] - Too busy to snap, > > > >>>>> skipping > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 2021-02-15 22:01:51,427 [myid:4] - INFO > > > >>>>>>>> [SessionTracker:ZooKeeperServer@610] - Expiring session > > > >>>>>>>> 0x400189fee9a001e, timeout of 4000ms exceeded > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 5. Yes we upgrade both the client and the server to 3.6. > > > >> Actually, > > > >>>>> the > > > >>>>>>>> issue happened with the combinations of > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> 3.4 client and 3.6 server > > > >>>>>>>> > > > >>>>>>>> 3.6 client and 3.6 server > > > >>>>>>>> > > > >>>>>>>> Please let me know if you need any additional info. > > > >>>>>>>> > > > >>>>>>>> Thanks, > > > >>>>>>>> > > > >>>>>>>> Li > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> > > > >>>>>>>> On Mon, Feb 15, 2021 at 1:44 PM Li Wang <li4w...@gmail.com> > > > >>> wrote: > > > >>>>>>>> > > > >>>>>>>>> Hi Enrico, > > > >>>>>>>>> > > > >>>>>>>>> Thanks for the reply. > > > >>>>>>>>> > > > >>>>>>>>> 1. We are using direct NIO based stack, not Netty based yet. > > > >>>>>>>>> 2. Yes, on the client side, here are the metrics > > > >>>>>>>>> > > > >>>>>>>>> 3.6: > > > >>>>>>>>> > > > >>>>>>>>> > > > >>>>>>>>> > > > >>>>>>>>> > > > >>>>>>>>> On Mon, Feb 15, 2021 at 10:44 AM Enrico Olivelli < > > > >>>>> eolive...@gmail.com > > > >>>>>>> > > > >>>>>>>>> wrote: > > > >>>>>>>>> > > > >>>>>>>>>> IIRC The main difference is about the switch to Netty 4 and > > > >>> about > > > >>>>>> using > > > >>>>>>>>>> more DirectMemory. Are you using the Netty based stack? > > > >>>>>>>>>> > > > >>>>>>>>>> Apart from that macro difference there have been many many > > > >>> changes > > > >>>>>>> since > > > >>>>>>>>>> 3.4. > > > >>>>>>>>>> > > > >>>>>>>>>> Do you have some metrics to share? > > > >>>>>>>>>> Are the JVM configurations and zoo.cfg configuration equals > > > >> to > > > >>>>> each > > > >>>>>>>>>> other? > > > >>>>>>>>>> > > > >>>>>>>>>> Do you see warnings on the server logs? > > > >>>>>>>>>> > > > >>>>>>>>>> Did you upgrade both the client and the server or only the > > > >>> server? > > > >>>>>>>>>> > > > >>>>>>>>>> Enrico > > > >>>>>>>>>> > > > >>>>>>>>>> > > > >>>>>>>>>> Il Lun 15 Feb 2021, 18:30 Li Wang <li4w...@gmail.com> ha > > > >>> scritto: > > > >>>>>>>>>> > > > >>>>>>>>>>> Hi, > > > >>>>>>>>>>> > > > >>>>>>>>>>> We want to upgrade from 3.4.14 to 3.6.2. During the > > > >>>>> perform/load > > > >>>>>>>>>>> comparison test, it was found that the performance of 3.6 > > > >> has > > > >>>>> been > > > >>>>>>>>>>> significantly degraded compared to 3.4 for the write > > > >>> operation. > > > >>>>>> Under > > > >>>>>>>>>> the > > > >>>>>>>>>>> same load, there was a huge number of SessionExpired and > > > >>>>>>> ConnectionLoss > > > >>>>>>>>>>> errors in 3.6 while no such errors in 3.4. > > > >>>>>>>>>>> > > > >>>>>>>>>>> The load testing is 500 concurrent users with a cluster of > 5 > > > >>>>>>>>>> participants > > > >>>>>>>>>>> and 5 observers. The min session timeout on the server side > > > >> is > > > >>>>>>> 4000ms. > > > >>>>>>>>>>> > > > >>>>>>>>>>> I wonder if anyone has seen the same issue and has any > > > >>> insights > > > >>>>> on > > > >>>>>>> what > > > >>>>>>>>>>> could be the cause of the performance degradation. > > > >>>>>>>>>>> > > > >>>>>>>>>>> Thanks > > > >>>>>>>>>>> > > > >>>>>>>>>>> Li > > > >>>>>>>>>>> > > > >>>>>>>>>> > > > >>>>>>>>> > > > >>>>>>> > > > >>>>>> > > > >>>>> > > > >>>> > > > >>> > > > >> > > > > > > > > >
