https://pinot.apache.org/ logo
Join Slack
Powered by
Hi guys, we faced a sudden ingestion rate drop to ...
# troubleshooting
p
Hi guys, we faced a sudden ingestion rate drop to 0 some time back. These are our observations (have attached the log files). Realtime-server logs:
Copy code
java.lang.InternalError: a fault occurred in a recent unsafe memory access operation in compiled Java code
 15         at org.apache.pinot.core.realtime.impl.dictionary.BaseOffHeapMutableDictionary.indexValue(BaseOffHeapMutableDictionary.java:361)
 14         at org.apache.pinot.core.realtime.impl.dictionary.StringOffHeapMutableDictionary.index(StringOffHeapMutableDictionary.java:61)
 13         at org.apache.pinot.core.indexsegment.mutable.MutableSegmentImpl.updateDictionary(MutableSegmentImpl.java:521)
 12         at org.apache.pinot.core.indexsegment.mutable.MutableSegmentImpl.index(MutableSegmentImpl.java:466)
 11         at org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager.processStreamEvents(LLRealtimeSegmentDataManager.java:497)
 10         at org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager.consumeLoop(LLRealtimeSegmentDataManager.java:402)
  9         at org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager$PartitionConsumer.run(LLRealtimeSegmentDataManager.java:538)
  8         at java.lang.Thread.run(Thread.java:748)
  7 2021/09/23 15:00:16.067 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=rawServiceView__0__3342__20210922T1809Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068648, modifiedTime=163240921557    7, version=11, waitingFor=CurrentStateMatch, resource=rawServiceView_REALTIME, numResourcesLeft=2, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init;;
  6 2021/09/23 15:00:26.077 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=backendEntityView__2__23025__20210922T1909Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068635, modifiedTime=16324091    07080, version=19, waitingFor=CurrentStateMatch, resource=backendEntityView_REALTIME, numResourcesLeft=2, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init    ;;
  5 2021/09/23 15:00:36.093 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=backendEntityView__2__23025__20210922T1909Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068635, modifiedTime=16324091    07080, version=19, waitingFor=CurrentStateMatch, resource=backendEntityView_REALTIME, numResourcesLeft=1, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init    ;;
  4 2021/09/23 15:00:46.103 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=backendEntityView__2__23025__20210922T1909Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068635, modifiedTime=16324091    07080, version=19, waitingFor=CurrentStateMatch, resource=backendEntityView_REALTIME, numResourcesLeft=1, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init    ;;
  3 2021/09/23 15:00:56.113 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=backendEntityView__2__23025__20210922T1909Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068635, modifiedTime=16324092    55125, version=22, waitingFor=CurrentStateMatch, resource=backendEntityView_REALTIME, numResourcesLeft=1, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init    ;;
  2 2021/09/23 15:01:06.122 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Sleep for 10000ms as service status has not turned GOOD: PinotServiceManagerStatusCallback:Started;MultipleCallbackServiceSta    tusCallback:IdealStateAndCurrentStateMatchServiceStatusCallback:partition=backendEntityView__2__23040__20210923T0619Z, expected=ONLINE, found=OFFLINE, creationTime=1632409068635, modifiedTime=16324092    66062, version=48, waitingFor=CurrentStateMatch, resource=backendEntityView_REALTIME, numResourcesLeft=1, numTotalResources=5, minStartCount=5,;IdealStateAndExternalViewMatchServiceStatusCallback:Init    ;;
  1 2021/09/23 15:01:16.215 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Service status is GOOD after 190391ms
  0 2021/09/23 15:01:16.222 INFO [HelixServerStarter] [Start a Pinot [SERVER]] Pinot server ready
  1 2021/09/23 15:30:06.057 WARN [ZkBaseDataAccessor] [ZkClient-EventThread-23-apache-pinot-zookeeper-bitnami-headless.pinot.svc.cluster.local:2181] Fail to read record for paths: {/pinot-prod/INSTANCES/S    erver_server-realtime-0.server-realtime-headless.pinot.svc.cluster.local_8098/MESSAGES/74dc1531-5db0-47a4-b97c-95cabc4067dc=-101}
controller-logs
These are the GC and other metrics. The ingestion suddenly dropped to 0. You can also see the CPU going to 0 on all real-time servers in that time window.
message has been deleted
The ingestion rate went back to normal once we restarted the realtime server pods.
Two of the real-time server pods had restarted 14 and 16 times respectively. We verified that there was no resource crunch for the servers. There was also no ingestion rate spike at the time of the issue, although the rate had increased a bit before the incident.
k
thanks for sharing the logs
can you please create an issue and attach the logs
m
Is there an hs_error.log, or do you see OOM anywhere?
p
There was no OOM definitely. Let me look for hs_error.log though.
I’ll create an issue with all of this info.
m
s
This is happening again on our system Attaching latest logs here.
realtime-server_logs
s
we have been getting similar error. Wonder what's going on here
p
Open in Slack
PreviousNext
Powered by