Hi Ken, David, Enrico, Li Wang,
Ken wrote: >>> We run a load test (just a few connections) that generates about >>> 300,000 ephemeral nodes. We drop these connections simultaneously so >>> those ephemeral nodes expire around the same time. At this point we >>> see a crash in LearnerHandler: >> >> After running a few more tests, it also happens with 75K >> simultaneously expiring ephemeral nodes. I believe this is the ZOOKEEPER-4306 issue, "CloseSessionTxn contains too many ephemal nodes cause cluster crash": https://issues.apache.org/jira/browse/ZOOKEEPER-4306 It is due to the Jute-limited size of "CloseSession" transactions. The crash can be worked around by setting: closeSessionTxn.enabled = false but that disables the fix for another potential issue: https://issues.apache.org/jira/browse/ZOOKEEPER-3145 HTH, -D P.-S. — Enrico, I still don't have a better solution than the one in this PR: https://github.com/apache/zookeeper/pull/1716 Li Wang also looked into it and seems to have reached the same conclusion: https://issues.apache.org/jira/browse/ZOOKEEPER-4306?focusedCommentId=17685644&page=com.atlassian.jira.plugin.system.issuetabpanels%3Acomment-tabpanel#comment-17685644 Thoughts? ----- Original Message ----- David Smiley <[email protected]> writes: > I'm interested in the same... we're thinking of using ephemeral nodes > to indicate the presence of data that this node can be searched for. > The numbers will reach hundreds of thousands on the high end. > > On Mon, Jun 17, 2024 at 9:08 PM Ken Mamitsuka <[email protected]> wrote: >> >> After running a few more tests, it also happens with 75K simultaneously >> expiring ephemeral nodes. >> >> I guess a more fundamental question is whether Zookeeper is meant to handle >> something like this or is this huge simultaneous expiration something >> unsupported. >> >> Thank you! >> >> On Wed, Jun 12, 2024 at 10:24 AM Ken Mamitsuka <[email protected]> wrote: >> >> > We are running a 5 node Zookeeper cluster on version 3.8.4 (it had the >> > same issue with 3.7.1). We run a load test (just a few connections) that >> > generates about 300,000 ephemeral nodes. We drop these connections >> > simultaneously so those ephemeral nodes expire around the same time. At >> > this point we see a crash in LearnerHandler: >> > >> > Jun 10 17:39:12 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:12,764 [myid:] - INFO >> > [Snapshot Thread:o.a.z.s.p.FileTxnSnapLog@479] - Snapshotting: >> > 0x100093f83 to /var/lib/zookeeper/version-2/ >> > snapshot.100093f83 >> > Jun 10 17:39:12 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:12,765 [myid:] - INFO >> > [SyncThread:5:o.a.z.s.p.FileTxnLog@285] - Creating new log file: >> > log.100093f85 >> > Jun 10 17:39:13 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:13,520 [myid:] - INFO >> > [Snapshot Thread:o.a.z.s.ZooKeeperServer@558] - Snapshot taken in >> > 756 ms >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - ERROR >> > [LearnerHandler-/10.1.67.28:51888:o.a.z.s.q.LearnerHandler@719] - >> > Unexpected exception in LearnerHandler: >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: java.io.EOFException: null >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.io.DataInputStream.readInt(DataInputStream.java:392) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:96) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:134) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:656) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - ERROR >> > [Sender-/10.1.67.28:51888:o.a.z.s.q.LearnerHandler@372] - >> > Exception while sending packets in LearnerHandler >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: java.net.SocketException: Connection >> > reset >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:115) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.net.SocketOutputStream.write(SocketOutputStream.java:155) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.io.DataOutputStream.write(DataOutputStream.java:107) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > java.io.FilterOutputStream.write(FilterOutputStream.java:97) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryOutputArchive.writeBuffer(BinaryOutputArchive.java:122) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.QuorumPacket.serialize(QuorumPacket.java:71) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryOutputArchive.writeRecord(BinaryOutputArchive.java:126) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.sendPackets(LearnerHandler.java:368) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.access$200(LearnerHandler.java:65) >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler$1.run(LearnerHandler.java:751) >> > >> > Then connections to learners drop: >> > >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - INFO >> > [LearnerHandler-/10.1.79.102:35670:o.a.z.s.q.LearnerHandler@1159] >> > - Synchronously closing socket to learner 2. >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - INFO >> > [LearnerHandler-/10.1.72.1:54384:o.a.z.s.q.LearnerHandler@1159] - >> > Synchronously closing socket to learner 3. >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - INFO >> > [LearnerHandler-/10.1.71.8:40626:o.a.z.s.q.LearnerHandler@1159] - >> > Synchronously closing socket to learner 4. >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,903 [myid:] - WARN >> > [LearnerHandler-/10.1.67.28:51888:o.a.z.s.q.LearnerHandler@735] - >> > ******* GOODBYE /10.1.67.28:51888 ******** >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,904 [myid:] - WARN >> > [LearnerHandler-/10.1.71.8:40626:o.a.z.s.q.LearnerHandler@735] - >> > ******* GOODBYE /10.1.71.8:40626 ******** >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,904 [myid:] - WARN >> > [LearnerHandler-/10.1.79.102:35670:o.a.z.s.q.LearnerHandler@735] - >> > ******* GOODBYE /10.1.79.102:35670 ******** >> > Jun 10 17:39:16 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:16,904 [myid:] - WARN >> > [LearnerHandler-/10.1.72.1:54384:o.a.z.s.q.LearnerHandler@735] - >> > ******* GOODBYE /10.1.72.1:54384 ******** >> > >> > Then it seems like it can't load (or update) the database? >> > >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: 2024-06-10 17:39:18,146 [myid:] - ERROR >> > [QuorumPeer[myid=5](plain=[0:0:0:0:0:0:0:0]:2181)(secure=[0:0:0:0:0:0:0:0]:3181):o.a.z.s.ZooKeeperServer@892] >> > - Error updating DB >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: java.io.IOException: Unreasonable length >> > = 8010890 >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryInputArchive.checkLength(BinaryInputArchive.java:166) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.jute.BinaryInputArchive.readBuffer(BinaryInputArchive.java:127) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.Util.readTxnBytes(Util.java:159) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.next(FileTxnLog.java:750) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.FileTxnLog$FileTxnIterator.<init>(FileTxnLog.java:632) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:448) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.FileTxnLog.read(FileTxnLog.java:435) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.persistence.FileTxnSnapLog.fastForwardFromEdits(FileTxnSnapLog.java:330) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.ZKDatabase.fastForwardDataBase(ZKDatabase.java:300) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.ZooKeeperServer.shutdown(ZooKeeperServer.java:890) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.ZooKeeperServer.shutdown(ZooKeeperServer.java:838) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.LeaderZooKeeperServer.shutdown(LeaderZooKeeperServer.java:162) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.Leader.shutdown(Leader.java:837) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.Leader.lead(Leader.java:803) >> > Jun 10 17:39:18 zookeeper-5-automation99999 >> > zookeeper-server[19472]: at >> > org.apache.zookeeper.server.quorum.QuorumPeer.run(QuorumPeer.java:1552) >> > >> > After this, zookeeper-4 appears to be elected leader and then hits the >> > same LearnerHandler crash: >> > >> > Jun 10 17:39:17 zookeeper-4-automation99999 >> > zookeeper-server[19461]: 2024-06-10 17:39:17,208 [myid:] - INFO >> > [QuorumPeer[myid=4](plain=[0:0:0:0:0:0:0:0]:2181)(secure=[0:0:0:0:0:0:0:0]:3181):o.a.z.s.q.QuorumPeer@1549] >> > - LEADING >> > >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: 2024-06-10 17:39:24,125 [myid:] - ERROR >> > [LearnerHandler-/10.1.67.28:35566:o.a.z.s.q.LearnerHandler@719] - >> > Unexpected exception in LearnerHandler: >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: java.io.EOFException: null >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.io.DataInputStream.readInt(DataInputStream.java:392) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.jute.BinaryInputArchive.readInt(BinaryInputArchive.java:96) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.QuorumPacket.deserialize(QuorumPacket.java:86) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.jute.BinaryInputArchive.readRecord(BinaryInputArchive.java:134) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:656) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: 2024-06-10 17:39:24,125 [myid:] - ERROR >> > [Sender-/10.1.67.28:35566:o.a.z.s.q.LearnerHandler@372] - >> > Exception while sending packets in LearnerHandler >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: java.net.SocketException: Connection >> > reset >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.net.SocketOutputStream.socketWrite(SocketOutputStream.java:115) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.net.SocketOutputStream.write(SocketOutputStream.java:155) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.io.BufferedOutputStream.write(BufferedOutputStream.java:122) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.io.DataOutputStream.write(DataOutputStream.java:107) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > java.io.FilterOutputStream.write(FilterOutputStream.java:97) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.jute.BinaryOutputArchive.writeBuffer(BinaryOutputArchive.java:122) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.QuorumPacket.serialize(QuorumPacket.java:71) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.jute.BinaryOutputArchive.writeRecord(BinaryOutputArchive.java:126) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.sendPackets(LearnerHandler.java:368) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler.access$200(LearnerHandler.java:65) >> > Jun 10 17:39:24 zookeeper-4-automation99999 >> > zookeeper-server[19461]: at >> > org.apache.zookeeper.server.quorum.LearnerHandler$1.run(LearnerHandler.java:751) >> > >> > The same thing happens to zookeeper-3, at which point there is no quorum >> > so no new leader is elected. I apologize if anything I posted is wrong and >> > I'm not intimately familiar with Zookeeper config. Our java process args >> > look like >> > >> > java -Dzookeeper.log.dir=/var/log/zookeeper >> > -Dzookeeper.log.file=zookeeper-zookeeper-server-zookeeper-1-automation99999.log >> > -XX:+HeapDumpOnOutOfMemoryError -XX:OnOutOfMemoryError=kill -9 %p -cp >> > /opt/zookeeper-3.8.4/bin/../zookeeper-server/target/classes:/opt/zookeeper-3.8.4/bin/../build/classes:/opt/zookeeper-3.8.4/bin/../zookeeper-server/target/lib/*.jar:/opt/zookeeper-3.8.4/bin/../build/lib/*.jar:/opt/zookeeper-3.8.4/bin/../lib/zookeeper-prometheus-metrics-3.8.4.jar:/opt/zookeeper-3.8.4/bin/../lib/zookeeper-jute-3.8.4.jar:/opt/zookeeper-3.8.4/bin/../lib/zookeeper-3.8.4.jar:/opt/zookeeper-3.8.4/bin/../lib/snappy-java-1.1.10.5.jar:/opt/zookeeper-3.8.4/bin/../lib/slf4j-api-1.7.30.jar:/opt/zookeeper-3.8.4/bin/../lib/simpleclient_servlet-0.9.0.jar:/opt/zookeeper-3.8.4/bin/../lib/simpleclient_hotspot-0.9.0.jar:/opt/zookeeper-3.8.4/bin/../lib/simpleclient_common-0.9.0.jar:/opt/zookeeper-3.8.4/bin/../lib/simpleclient-0.9.0.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-transport-native-unix-common-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-transport-native-epoll-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-transport-classes-epoll-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-transport-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-resolver-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-handler-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-common-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-codec-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/netty-buffer-4.1.105.Final.jar:/opt/zookeeper-3.8.4/bin/../lib/metrics-core-4.1.12.1.jar:/opt/zookeeper-3.8.4/bin/../lib/logback-core-1.2.13.jar:/opt/zookeeper-3.8.4/bin/../lib/logback-classic-1.2.13.jar:/opt/zookeeper-3.8.4/bin/../lib/jline-2.14.6.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-util-ajax-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-util-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-servlet-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-server-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-security-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-io-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/jetty-http-9.4.53.v20231009.jar:/opt/zookeeper-3.8.4/bin/../lib/javax.servlet-api-3.1.0.jar:/opt/zookeeper-3.8.4/bin/../lib/jackson-databind-2.15.2.jar:/opt/zookeeper-3.8.4/bin/../lib/jackson-core-2.15.2.jar:/opt/zookeeper-3.8.4/bin/../lib/jackson-annotations-2.15.2.jar:/opt/zookeeper-3.8.4/bin/../lib/commons-io-2.11.0.jar:/opt/zookeeper-3.8.4/bin/../lib/commons-cli-1.5.0.jar:/opt/zookeeper-3.8.4/bin/../lib/audience-annotations-0.12.0.jar:/opt/zookeeper-3.8.4/bin/../zookeeper-*.jar:/opt/zookeeper-3.8.4/bin/../zookeeper-server/src/main/resources/lib/*.jar:/opt/zookeeper-3.8.4/conf::/opt/zookeeper-3.8.4/conf:/opt/zookeeper-3.8.4/*:/opt/zookeeper-3.8.4/lib/* >> > -Xmx1000m >> > -Dzookeeper.serverCnxnFactory=org.apache.zookeeper.server.NettyServerCnxnFactory >> > -Dzookeeper.ssl.keyStore.location=<XXXX> >> > -Dzookeeper.ssl.keyStore.password=<XXXX> >> > -Dzookeeper.ssl.trustStore.location=<XXXX> >> > -Dzookeeper.ssl.trustStore.password=<XXXX> -Xms12g -Xmx12g -Xmn8g >> > -Dfsync.warningthresholdms=200 -Dzookeeper.log.threshold=INFO >> > -XX:+UseParNewGC -XX:+CMSClassUnloadingEnabled -XX:+UseConcMarkSweepGC >> > -XX:+CMSIncrementalMode -XX:CMSIncrementalDutyCycle=100 >> > -XX:-CMSIncrementalPacing -XX:PermSize=160m -XX:MaxPermSize=160m >> > -XX:SurvivorRatio=4 -Dcom.sun.management.jmxremote >> > -Dcom.sun.management.jmxremote.local.only=false >> > org.apache.zookeeper.server.quorum.QuorumPeerMain >> > /opt/zookeeper-3.8.4/conf/zoo.cfg >> > >> > Our zoo.cfg (not including server config looks like: >> > >> > tickTime=2000 >> > peerType=participant >> > dataDir=/var/lib/zookeeper >> > dataLogDir=/zookeeper/data >> > clientPort=2181 >> > secureClientPort=3181 >> > maxClientCnxns=20000 >> > initLimit=5 >> > syncLimit=2 >> > >> >> >> -- >> Ken Mamitsuka >> Staff Software Engineer, Cantina >> [email protected] | cantina.com
