https://pinot.apache.org/ logo
Join Slack
Powered by
Hey Team, We are facing an issue with ingestion i...
# troubleshooting
r
Hey Team, We are facing an issue with ingestion in pinot. Our prod cluster has stopped ingesting data. In server Helix logs I can see servers can't connect to zookeeper. I have tried restarting all the components. Disk usage on zookeeper = <5% CPU on zookeeper ~10% We have 24 servers, 36 kafka partitions, 50 GB memory each, peak ingestion rate 1MM rps, segment size - 300MB. Can anyone please help us understand this and mitigate this issue?
Copy code
2025/10/13 07:46:07.467 INFO [ZkClient] [Start a Pinot [SERVER]-EventThread] zkclient 3, zookeeper state changed ( Disconnected )
2025/10/13 07:46:07.472 WARN [ZKHelixManager] [ZkClient-EventThread-125-pinot-zookeeper:2181] KeeperState:Disconnected, SessionId: 10000184ff502de, instance: Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098, type: PARTICIPANT
2025/10/13 07:46:09.059 INFO [ZkClient] [Start a Pinot [SERVER]-EventThread] zkclient 3, zookeeper state changed ( SyncConnected )
2025/10/13 07:46:09.059 INFO [ZKHelixManager] [ZkClient-EventThread-125-pinot-zookeeper:2181] KeeperState: SyncConnected, instance: Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098, type: PARTICIPANT
2025/10/13 07:46:21.387 INFO [ZkClient] [Start a Pinot [SERVER]-EventThread] zkclient 3, zookeeper state changed ( Disconnected )
2025/10/13 07:46:21.387 WARN [ZKHelixManager] [ZkClient-EventThread-125-pinot-zookeeper:2181] KeeperState:Disconnected, SessionId: 10000184ff502de, instance: Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098, type: PARTICIPANT
2025/10/13 07:46:22.025 WARN [ZKHelixManager] [message-count-scheduler-0] zkClient to pinot-zookeeper:2181 is not connected, wait for 10000ms.
2025/10/13 07:46:32.028 ERROR [ZKHelixManager] [message-count-scheduler-0] zkClient is not connected after waiting 10000ms., clusterName: d3-pinot-cluster, zkAddress: pinot-zookeeper:2181
2025/10/13 07:46:34.790 INFO [ZkClient] [Start a Pinot [SERVER]-EventThread] zkclient 3, zookeeper state changed ( SyncConnected )
2025/10/13 07:46:34.790 INFO [ZKHelixManager] [ZkClient-EventThread-125-pinot-zookeeper:2181] KeeperState: SyncConnected, instance: Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098, type: PARTICIPANT
2025/10/13 12:34:34.225 INFO [CallbackHandler] [ZkClient-EventThread-125-pinot-zookeeper:2181] 125 START: CallbackHandler 0, INVOKE /d3-pinot-cluster/INSTANCES/Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098/MESSAGES listener: org.apache.helix.messaging.handling.HelixTaskExecutor@1b9d313c type: CALLBACK
2025/10/13 12:34:34.226 INFO [CallbackHandler] [ZkClient-EventThread-125-pinot-zookeeper:2181] CallbackHandler 0 subscribing changes listener to path: /d3-pinot-cluster/INSTANCES/Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098/MESSAGES, callback type: CALLBACK, event types: [NodeChildrenChanged], listener: org.apache.helix.messaging.handling.HelixTaskExecutor@1b9d313c, watchChild: false
2025/10/13 12:34:34.227 INFO [CallbackHandler] [ZkClient-EventThread-125-pinot-zookeeper:2181] CallbackHandler0, Subscribing to path: /d3-pinot-cluster/INSTANCES/Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098/MESSAGES took: 1
2025/10/13 12:34:34.231 INFO [MessageLatencyMonitor] [ZkClient-EventThread-125-pinot-zookeeper:2181] The latency of message 89f57203-2271-4d7a-abc3-1087222fc439 is 853 ms
2025/10/13 12:34:34.246 INFO [HelixTaskExecutor] [ZkClient-EventThread-125-pinot-zookeeper:2181] Scheduling message 89f57203-2271-4d7a-abc3-1087222fc439: metric_numerical_agg_1H_REALTIME:, null->null
m
The top reason for this is server Stop The World GC, because of which ZK doesn’t get heartbeat and disconnects
r
I have tried restarting servers but it didn't helped.
One more point: The ingestion has stopped on all servers. Few days ago ingestion was getting stopped on a few servers with this error: 2025/10/10 171754.775 ERROR [BlockingSegmentCompletionFSM_metric_numerical_agg_1H__21__182593__20251010T1717Z] [grizzly-http-server-7] Caught exception while committing segment metadata for segment: metric_numerical_agg_1H__21__182593__20251010T1717Z java.lang.IllegalStateException: Failed to persist segment ZK metadata for segment: metric_numerical_agg_1H__21__182593__20251010T1717Z of table: metric_numerical_agg_1H_REALTIME
There are also WARN messages like this in server helix.
Copy code
2025/10/13 15:46:30.470 WARN [ZkBaseDataAccessor] [ZkClient-EventThread-125-pinot-zookeeper:2181] Fail to read record for paths: {/d3-pinot-cluster/INSTANCES/Server_pinot-s
erver-20.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098/MESSAGES/f044490b-2ca9-4d64-9e78-42e3b0c41847=-101
m
You didn’t respond to the GC comment, do you see that? We need to understand if this is ZK side or server side issue. I’d look at server first - what is it doing around the time connection to ZK fails
r
When server is unable to connect to ZK. Around that time heap reaches close to ~100% capacity even when the ingestion is stopped. I see some spike in CPU util spiking to 250% (12 vCPUs). Let me check GC logs
The Garbage Collection (Allocation Rate) is this - 20828M(85%)->260M(1%) I do not see any long GC pause. Generally they are <500ms.
I also enabled safepoint logs there the safepoint pause is in a few ms. However there are no connection to ZK fails logs rn. I also tried to reduce heap size to see if it does anything, after reducing heap size CPU util jumped to 800%, ingestion started for a few secs and it stoppped again.
m
I think there are likley some issues in the way you have setup / sized the cluster as well as configs (eg jvm) that you are using. Hard to debug this over slack
r
I triggered force commit for consuming segments and checked logs. Below error logs are present in controller. It is unable to reach server.
Copy code
2025/10/14 05:41:42.360 ERROR [CompletionServiceHelper] [grizzly-http-server-31] Server: Server_pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098 returned error: 404, reason: Not Found for uri: <http://pinot-server-4.pinot-server-headless.d3-pinot-cluster.svc.cluster.local:8097/tables/metric_numerical_agg_1H_REALTIME/segments/metric_numerical_agg_1H__0__180910__20251010T1821Z/metadata?columns=*>
2025/10/14 05:41:42.364 ERROR [CompletionServiceHelper] [grizzly-http-server-31] Server: Server_pinot-server-3.pinot-server-headless.d3-pinot-cluster.svc.cluster.local_8098 returned error: 404, reason: Not Found for uri: <http://pinot-server-3.pinot-server-headless.d3-pinot-cluster.svc.cluster.local:8097/tables/metric_numerical_agg_1H_REALTIME/segments/metric_numerical_agg_1H__0__180910__20251010T1821Z/metadata?columns=*>
2025/10/14 05:41:42.364 WARN [CompletionServiceHelper] [grizzly-http-server-31] Finished reading information for table: metric_numerical_agg_1H_REALTIME with 0/2 server-request responses
m
Hmm, is the server healthy during that time? Are you able to connect to their server from controller pod
r
Yes, I issued forceCommit command which was able to reach servers from controller
Update: There was a mismatch in segment state between server and controller. The 404 error above meant that the server did not had the same segment in CONSUMING state. Server had the segment in COMPLETED state while controller had the segment in CONSUMING state. This mismatch blocked segment commit and resulted in no ingestion. At the same time we also observed maxBuffer limit reached in Zookeeper, not sure if issues are related. To resolve the issues we tried to reset and reload the segment but it was not successful. Ultimately we had to delete all consuming segments to resolve the issue.
m
What you described is not the root cause it is the effect of buffer limit due to which commit protocol could not complete
👍 4
Open in Slack
PreviousNext
Powered by