https://pinot.apache.org/ logo
#troubleshooting
Title
# troubleshooting
l

Luis Fernandez

05/12/2022, 2:12 PM
hello 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 PM
i 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 PM
the 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 PM
What is the crash error?
l

Luis Fernandez

05/12/2022, 2:36 PM
i’m trying to find that out 😄
message has been deleted
d

Daniel Lavoie

05/12/2022, 2:39 PM
kubectl logs pinot-zookeeper-1 --previous
l

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:56224
d

Daniel Lavoie

05/12/2022, 2:42 PM
I see no shutdown command.
kubectl describe pod pinot-zookeeper-1
Should give an exit status for previous container
l

Luis Fernandez

05/12/2022, 2:42 PM
Copy code
Last State:     Terminated
      Reason:       Error
      Exit Code:    143
d

Daniel Lavoie

05/12/2022, 2:43 PM
We 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 PM
For 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 PM
ops people did tell me that those pods seem to be using mostly of the memory available
d

Daniel Lavoie

05/12/2022, 2:48 PM
Do you have any trace of a OOMKilled in the pod describe output?
l

Luis Fernandez

05/12/2022, 2:49 PM
like w this one?
kubectl describe pod pinot-zookeeper-1
d

Daniel Lavoie

05/12/2022, 2:49 PM
yes
kubectl describe pod pinot-zookeeper-1 | grep OOM
l

Luis Fernandez

05/12/2022, 2:50 PM
nada
d

Daniel Lavoie

05/12/2022, 2:50 PM
Ok, 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 PM
this 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 PM
I would 2x or 4x all of these values
l

Luis Fernandez

05/12/2022, 3:00 PM
AHA
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 normally
in
pinot-zookeeper-2
d

Daniel Lavoie

05/12/2022, 3:01 PM
there you go 🙂 Smoking gun
l

Luis Fernandez

05/12/2022, 3:09 PM
cpu also you recommend 2x or 4x?
d

Daniel Lavoie

05/12/2022, 3:10 PM
2x 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 PM
and 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 PM
yea, 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 PM
Yeah current helm chart is broken
l

Luis Fernandez

05/12/2022, 7:27 PM
it 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 PM
latest 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