Channels
#troubleshooting
Title
# troubleshooting
l
Luis Fernandez
05/12/2022, 2:12 PMhello my friends it’s me again, does anyone know what would be the reason of zookeeper crashing while we are ingesting data with the job yaml? we are running some migrations and it seems like zookeeper is just keeping on being sad crashing a lot, also what’s your recommended sizing for zookeeper, we are just using the default in the helm chart we may be hitting some roof
m
Mayank
05/12/2022, 2:19 PM
Too many segments (tens of thousands or more)?
l
Luis Fernandez
05/12/2022, 2:20 PMi see 2k segments after the migration was done but at the end is def more than that
how can i tell?
m
Mayank
05/12/2022, 2:23 PM
Pinot UI should show
2k is small
l
Luis Fernandez
05/12/2022, 2:24 PMthe thing is that i don’t know if all the segments that were supposed to be migrated were migrated
we have a 512mb with 256 heap zk
3 replicas
m
Mayank
05/12/2022, 2:24 PM
@Daniel Lavoie any comments
d
Daniel Lavoie
05/12/2022, 2:31 PMWhat is the crash error?
l
Luis Fernandez
05/12/2022, 2:36 PMi’m trying to find that out 😄
message has been deleted
d
Daniel Lavoie
05/12/2022, 2:39 PMkubectl logs pinot-zookeeper-1 --previousl
Luis Fernandez
05/12/2022, 2:41 PM Copy code
2022-05-12 10:15:32,603 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:32,604 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:32,614 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:32,615 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:32,816 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 400
2022-05-12 10:15:32,816 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:32,817 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:32,817 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:33,217 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 800
2022-05-12 10:15:33,221 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:33,221 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:33,221 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:34,022 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 1600
2022-05-12 10:15:34,023 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:34,023 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:34,023 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:35,624 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 3200
2022-05-12 10:15:35,624 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:35,624 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:35,625 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:38,825 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 6400
2022-05-12 10:15:38,826 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:38,826 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:38,826 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:45,227 [myid:2] - INFO [QuorumPeer[myid=2](plain=/0.0.0.0:2181)(secure=disabled):FastLeaderElection@919] - Notification time out: 12800
2022-05-12 10:15:45,228 [myid:2] - INFO [WorkerSender[myid=2]:QuorumCnxManager@430] - Have smaller server identifier, so dropping the connection: (3, 2)
2022-05-12 10:15:45,228 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 2 (n.leader), 0x0 (n.zxid), 0x1 (n.round), LOOKING (n.state), 2 (n.sid), 0x0 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:45,233 [myid:2] - INFO [WorkerReceiver[myid=2]:FastLeaderElection@679] - Notification: 2 (message format version), 3 (n.leader), 0x110001d0cf (n.zxid), 0x6 (n.round), FOLLOWING (n.state), 1 (n.sid), 0x12 (n.peerEPoch), LOOKING (my state)0 (n.config version)
2022-05-12 10:15:56,491 [myid:2] - INFO [NIOWorkerThread-1:FourLetterCommands@234] - The list of known four letter word commands is : [{1936881266=srvr, 1937006964=stat, 2003003491=wchc, 1685417328=dump, 1668445044=crst, 1936880500=srst, 1701738089=envi, 1668247142=conf, -720899=telnet close, 2003003507=wchs, 2003003504=wchp, 1684632179=dirs, 1668247155=cons, 1835955314=mntr, 1769173615=isro, 1920298859=ruok, 1735683435=gtmk, 1937010027=stmk}]
2022-05-12 10:15:56,491 [myid:2] - INFO [NIOWorkerThread-1:FourLetterCommands@235] - The list of enabled four letter word commands is : [[wchs, stat, wchp, dirs, stmk, conf, ruok, mntr, srvr, wchc, envi, srst, isro, dump, gtmk, telnet close, crst, cons]]
2022-05-12 10:15:56,491 [myid:2] - INFO [NIOWorkerThread-1:NIOServerCnxn@518] - Processing ruok command from /127.0.0.1:56218
2022-05-12 10:15:57,298 [myid:2] - INFO [NIOWorkerThread-2:NIOServerCnxn@518] - Processing srvr command from /127.0.0.1:56224d
Daniel Lavoie
05/12/2022, 2:42 PMI see no shutdown command.
kubectl describe pod pinot-zookeeper-1l
Luis Fernandez
05/12/2022, 2:42 PM Copy code
Last State: Terminated
Reason: Error
Exit Code: 143d
Daniel Lavoie
05/12/2022, 2:43 PMWe get this error when the liveness probe stops returning exit code 0
m
Mayank
05/12/2022, 2:44 PM
Perhaps too low heap is a potential issue here?
d
Daniel Lavoie
05/12/2022, 2:45 PMFor 2K segments, that’s a a reasonable assumption
But I would expect some OOM Killed or JVM OOM stacktrace
l
Luis Fernandez
05/12/2022, 2:47 PMops people did tell me that those pods seem to be using mostly of the memory available
d
Daniel Lavoie
05/12/2022, 2:48 PMDo you have any trace of a OOMKilled in the pod describe output?
l
Luis Fernandez
05/12/2022, 2:49 PMlike w this one?
kubectl describe pod pinot-zookeeper-1d
Daniel Lavoie
05/12/2022, 2:49 PMyes
kubectl describe pod pinot-zookeeper-1 | grep OOMl
Luis Fernandez
05/12/2022, 2:50 PMnada
d
Daniel Lavoie
05/12/2022, 2:50 PMOk, then maybe ZK gracefully reports error status on mntr command when memory is running out. So, I would recommend bumping memory
l
Luis Fernandez
05/12/2022, 2:54 PMthis is our config
Copy code
resources: {
requests: {
cpu: '500m',
memory: '1Gi',
},
limits: {
cpu: '500m',
memory: '1Gi',
},
}, Copy code
ZK_HEAP_SIZE: '256M',d
Daniel Lavoie
05/12/2022, 2:55 PMI would 2x or 4x all of these values
l
Luis Fernandez
05/12/2022, 3:00 PMAHA
Copy code
2022-05-06 15:55:56,927 [myid:3] - WARN [LearnerHandler-/10.24.10.144:59094:LearnerHandler@928] - Ignoring unexpected exception
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
at org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:926)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
2022-05-06 15:55:56,927 [myid:3] - WARN [QuorumPeer[myid=3](plain=/0.0.0.0:2181)(secure=disabled):ZooKeeperThread@55] - Exception occurred from thread QuorumPeer[myid=3](plain=/0.0.0.0:2181)(secure=disabled)
java.lang.OutOfMemoryError: Java heap space
2022-05-06 15:55:56,927 [myid:3] - WARN [LearnerHandler-/10.24.7.181:38132:LearnerHandler@928] - Ignoring unexpected exception
java.lang.InterruptedException
at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireInterruptibly(AbstractQueuedSynchronizer.java:1220)
at java.util.concurrent.locks.ReentrantLock.lockInterruptibly(ReentrantLock.java:335)
at java.util.concurrent.LinkedBlockingQueue.put(LinkedBlockingQueue.java:339)
at org.apache.zookeeper.server.quorum.LearnerHandler.shutdown(LearnerHandler.java:926)
at org.apache.zookeeper.server.quorum.LearnerHandler.run(LearnerHandler.java:647)
2022-05-06 15:55:56,928 [myid:3] - INFO [main:QuorumPeerMain@104] - Exiting normallyin
pinot-zookeeper-2d
Daniel Lavoie
05/12/2022, 3:01 PMthere you go 🙂 Smoking gun
l
Luis Fernandez
05/12/2022, 3:09 PMcpu also you recommend 2x or 4x?
d
Daniel Lavoie
05/12/2022, 3:10 PM2x is going to be fine, but my recommendation would be to instrument and measure resource usage
and adjust
l
Luis Fernandez
05/12/2022, 3:23 PM🙏 will do so
now, in terms of the job spec yaml, if zookeeper dies what are the implications for the job
i do see a lot of exceptions in the controller where we ran the job
d
Daniel Lavoie
05/12/2022, 3:24 PM@Mayank ^^
l
Luis Fernandez
05/12/2022, 3:24 PMand i imagine that zookeeper dying would just take all the controllers to a sad state and then mess up with the import
m
Mayank
05/12/2022, 3:41 PM
Yes, exceptions are probably effect rather than cause
l
Luis Fernandez
05/12/2022, 7:04 PMyea, so we have beefed up those machines
also another question, is there anything we have to do to the helm config in order for us to get grafana metrics for zk?
d
Daniel Lavoie
05/12/2022, 7:20 PMYeah current helm chart is broken
l
Luis Fernandez
05/12/2022, 7:27 PMit seems like that future is also recent https://zookeeper.apache.org/doc/r3.6.3/zookeeperMonitor.html
d
Daniel Lavoie
05/12/2022, 7:45 PMlatest ZK embedds a prometheus
We implemented it in our Cloud operator. You only meed to add a ZK properties. Chart needs that default properties and the removal of the side car containers
If you are interested in contributing to the project, that’s a nice one to look at.
f
Fizza Abid
06/28/2022, 11:27 AM@Yasir Khatri