You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@pinot.apache.org by GitBox <gi...@apache.org> on 2020/08/14 09:24:56 UTC
[GitHub] [incubator-pinot] fx19880617 opened a new pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
fx19880617 opened a new pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864
## Description
Current Pinot server start ServerInstance before ControllerLeaderLocator creation.
This is typically ok but in one extreme case that during realtime server bootstrap, one segment is consumed to threshold and trying to persist, it will use `ControllerLeaderLocator` in `ServerSegmentCompletionProtocolHandler.createSegmentCompletionUrl(...)` which may not be created yet.
Below is a sample logs:
```
2020/08/14 00:20:05.855 INFO [PluginManager] [main] Plugins root dir is [/opt/pinot/plugins]
2020/08/14 00:20:05.869 INFO [PluginManager] [main] Loading all plugins. Please use env variable 'plugins.include' to customize.
2020/08/14 00:20:05.869 INFO [PluginManager] [main] Trying to load plugin [pinot-batch-ingestion-hadoop] from location [/opt/pinot/plugins/pinot-batch-ingestion/pinot-batch-ingestion-hadoop]
2020/08/14 00:20:05.870 INFO [PluginManager] [main] Successfully loaded plugin [pinot-batch-ingestion-hadoop] from jar file [/opt/pinot/plugins/pinot-batch-ingestion/pinot-batch-ingestion-hadoop/pinot-batch-ingestion-hadoop-0.5.0-SNAPSHOT-shaded.jar]
...
...
2020/08/14 00:20:06.199 INFO [ServerInstance] [main] Initializing server instance
2020/08/14 00:20:06.199 INFO [ServerInstance] [main] Initializing server metrics
2020/08/14 00:20:06.220 INFO [ServerInstance] [main] Initializing instance data manager of class: org.apache.pinot.server.starter.helix.HelixInstanceDataManager
2020/08/14 00:20:06.223 INFO [HelixInstanceDataManager] [main] Initializing Helix instance data manager
2020/08/14 00:20:06.224 INFO [HelixInstanceDataManagerConfig] [main] InstanceDataManagerConfig, key: datadir , value: /var/pinot/server/data/index
2020/08/14 00:20:06.225 INFO [HelixInstanceDataManagerConfig] [main] InstanceDataManagerConfig, key: segmenttardir , value: /var/pinot/server/data/segment
2020/08/14 00:20:06.225 INFO [HelixInstanceDataManagerConfig] [main] InstanceDataManagerConfig, key: data.manager.class , value: org.apache.pinot.server.starter.helix.HelixInstanceDataManager
...
2020/08/14 00:20:08.114 INFO [HelixTaskExecutor] [main] Scheduling message 553a8091-14b7-48a9-91b6-61c9c722112d: testTable_REALTIME:testTable__0__4__20200813T2127Z, OFFLINE->CONSUMING
2020/08/14 00:20:08.115 INFO [HelixTaskExecutor] [main] Submit task: 553a8091-14b7-48a9-91b6-61c9c722112d to pool: java.util.concurrent.ThreadPoolExecutor@48b0e701[Running, pool size = 1, active threads = 1, queued tasks = 0, completed tasks = 0]
2020/08/14 00:20:08.203 INFO [HelixStateTransitionHandler] [HelixTaskExecutor-message_handle_thread] Instance Server_my-host-server-0.my-host-server-headless.my-host.svc.cluster.local_8098, partition testTable__0__4__20200813T2127Z received state transition from OFFLINE to CONSUMING on session 100e1f0f4d00022, message id: 553a8091-14b7-48a9-91b6-61c9c722112d
2020/08/14 00:20:08.203 INFO [SegmentOnlineOfflineStateModelFactory$SegmentOnlineOfflineStateModel] [HelixTaskExecutor-message_handle_thread] SegmentOnlineOfflineStateModel.onBecomeConsumingFromOffline() : ZnRecord=553a8091-14b7-48a9-91b6-61c9c722112d, {CREATE_TIMESTAMP=1597364407619, ClusterEventName=CurrentStateChange, EXECUTE_START_TIMESTAMP=1597364408128, EXE_SESSION_ID=100e1f0f4d00022, FROM_STATE=OFFLINE, MSG_ID=553a8091-14b7-48a9-91b6-61c9c722112d, MSG_STATE=read, MSG_TYPE=STATE_TRANSITION, PARTITION_NAME=testTable__0__4__20200813T2127Z, READ_TIMESTAMP=1597364407995, RESOURCE_NAME=testTable_REALTIME, RESOURCE_TAG=testTable_REALTIME, SRC_NAME=my-host-controller-0.my-host-controller-headless.my-host.svc.cluster.local_9000, SRC_SESSION_ID=100e1f0f4d0001e, STATE_MODEL_DEF=SegmentOnlineOfflineStateModel, STATE_MODEL_FACTORY_NAME=DEFAULT, TGT_NAME=Server_my-host-server-0.my-host-server-headless.my-host.svc.cluster.local_8098, TGT_SESSION_ID=100e1f0f4d00022, TO_STATE=CONSUMING}{}{}
, Stat=Stat {_version=0, _creationTime=1597364407632, _modifiedTime=1597364407632, _ephemeralOwner=0}
2020/08/14 00:20:08.203 INFO [SegmentOnlineOfflineStateModelFactory$SegmentOnlineOfflineStateModel] [HelixTaskExecutor-message_handle_thread] SegmentOnlineOfflineStateModel.onBecomeOnlineFromOffline() : ZnRecord=553a8091-14b7-48a9-91b6-61c9c722112d, {CREATE_TIMESTAMP=1597364407619, ClusterEventName=CurrentStateChange, EXECUTE_START_TIMESTAMP=1597364408128, EXE_SESSION_ID=100e1f0f4d00022, FROM_STATE=OFFLINE, MSG_ID=553a8091-14b7-48a9-91b6-61c9c722112d, MSG_STATE=read, MSG_TYPE=STATE_TRANSITION, PARTITION_NAME=testTable__0__4__20200813T2127Z, READ_TIMESTAMP=1597364407995, RESOURCE_NAME=testTable_REALTIME, RESOURCE_TAG=testTable_REALTIME, SRC_NAME=my-host-controller-0.my-host-controller-headless.my-host.svc.cluster.local_9000, SRC_SESSION_ID=100e1f0f4d0001e, STATE_MODEL_DEF=SegmentOnlineOfflineStateModel, STATE_MODEL_FACTORY_NAME=DEFAULT, TGT_NAME=Server_my-host-server-0.my-host-server-headless.my-host.svc.cluster.local_8098, TGT_SESSION_ID=100e1f0f4d00022, TO_STATE=CONSUMING}{}{}, S
tat=Stat {_version=0, _creationTime=1597364407632, _modifiedTime=1597364407632, _ephemeralOwner=0}
2020/08/14 00:20:08.203 INFO [HelixInstanceDataManager] [HelixTaskExecutor-message_handle_thread] Adding segment: testTable__0__4__20200813T2127Z to table: testTable_REALTIME
2020/08/14 00:20:09.093 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [HelixTaskExecutor-message_handle_thread] RealtimeDataResourceZKMetadata contains no information about sorted column for segment testTable__0__4__20200813T2127Z
2020/08/14 00:20:09.099 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [HelixTaskExecutor-message_handle_thread] Creating new stream consumer, reason: Starting
2020/08/14 00:20:09.129 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [HelixTaskExecutor-message_handle_thread] Creating new stream metadata provider, reason: Starting
...
2020/08/14 00:20:09.173 INFO [FixedByteSVMutableForwardIndex] [HelixTaskExecutor-message_handle_thread] Allocating 200000 bytes for: testTable__0__4__20200813T2127Z:ItemStatus.sv.unsorted.fwd
...
2020/08/14 00:20:09.228 INFO [MutableSegmentImpl_testTable__0__4__20200813T2127Z_testTables] [HelixTaskExecutor-message_handle_thread] Metrics aggregation is disabled.
2020/08/14 00:20:09.272 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [HelixTaskExecutor-message_handle_thread] Starting consumption on realtime consuming segment testTable__0__4__20200813T2127Z maxRowCount 50000 maxEndTime 2020-08-14T00:30:09.229Z
2020/08/14 00:20:09.292 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [HelixTaskExecutor-message_handle_thread] Created new consumer thread Thread[testTable__0__4__20200813T2127Z,5,main] for org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager@a12cbb0
2020/08/14 00:20:09.299 INFO [testTable_REALTIME-RealtimeTableDataManager] [HelixTaskExecutor-message_handle_thread] Initialize RealtimeSegmentDataManager - testTable__0__4__20200813T2127Z
2020/08/14 00:20:09.299 INFO [HelixInstanceDataManager] [HelixTaskExecutor-message_handle_thread] Added segment: testTable__0__4__20200813T2127Z to table: testTable_REALTIME
2020/08/14 00:20:09.300 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [testTable__0__4__20200813T2127Z] Starting consumption loop start offset 200000, finalOffset null
2020/08/14 00:20:09.383 INFO [HelixTask] [HelixTaskExecutor-message_handle_thread] Message: 553a8091-14b7-48a9-91b6-61c9c722112d (parent: null) handling task for testTable_REALTIME:testTable__0__4__20200813T2127Z completed at: 1597364409383, results: true. FrameworkTime: 53 ms; HandlerTime: 1211 ms.
2020/08/14 00:20:09.717 INFO [Metadata] [testTable__0__4__20200813T2127Z] Cluster ID: 21TWeeruS9eTKd-gAXF1qQ
2020/08/14 00:20:14.127 INFO [AbstractCoordinator] [testTable__0__4__20200813T2127Z] [Consumer clientId=consumer-2, groupId=] Discovered group coordinator b-3.gc-pinot-kafka.hgsrac.c3.kafka.us-west-2.amazonaws.com:9092 (id: 2147483644 rack: null)
2020/08/14 00:20:18.489 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [testTable__0__4__20200813T2127Z] Stopping consumption due to row limit nRows=50000 numRowsIndexed=50000, numRowsConsumed=50000
2020/08/14 00:20:18.489 INFO [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [testTable__0__4__20200813T2127Z] Stopping consumption due to row limit nRows=50000 numRowsIndexed=50000, numRowsConsumed=50000
2020/08/14 00:20:18.489 ERROR [LLRealtimeSegmentDataManager_testTable__0__4__20200813T2127Z] [testTable__0__4__20200813T2127Z] Exception while in work
java.lang.RuntimeException: Not yet created
at org.apache.pinot.server.realtime.ControllerLeaderLocator.getInstance(ControllerLeaderLocator.java:79) ~[pinot-all-0.5.0-SNAPSHOT-jar-with-dependencies.jar:0.5.0-SNAPSHOT-8ab032fa05b514ab6614396d632b9c9e52b9100d]
at org.apache.pinot.server.realtime.ServerSegmentCompletionProtocolHandler.createSegmentCompletionUrl(ServerSegmentCompletionProtocolHandler.java:188) ~[pinot-all-0.5.0-SNAPSHOT-jar-with-dependencies.jar:0.5.0-SNAPSHOT-8ab032fa05b514ab6614396d632b9c9e52b9100d]
at org.apache.pinot.server.realtime.ServerSegmentCompletionProtocolHandler.segmentConsumed(ServerSegmentCompletionProtocolHandler.java:170) ~[pinot-all-0.5.0-SNAPSHOT-jar-with-dependencies.jar:0.5.0-SNAPSHOT-8ab032fa05b514ab6614396d632b9c9e52b9100d]
at org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager.postSegmentConsumedMsg(LLRealtimeSegmentDataManager.java:926) ~[pinot-all-0.5.0-SNAPSHOT-jar-with-dependencies.jar:0.5.0-SNAPSHOT-8ab032fa05b514ab6614396d632b9c9e52b9100d]
at org.apache.pinot.core.data.manager.realtime.LLRealtimeSegmentDataManager$PartitionConsumer.run(LLRealtimeSegmentDataManager.java:553) [pinot-all-0.5.0-SNAPSHOT-jar-with-dependencies.jar:0.5.0-SNAPSHOT-8ab032fa05b514ab6614396d632b9c9e52b9100d]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_265]
```
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] fx19880617 merged pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
fx19880617 merged pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] mcvsubbu commented on pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
mcvsubbu commented on pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#issuecomment-674146813
I think the right fix is to not field any state transitions until the start() method has completed.
We can have the state transition call wait on a semaphore?
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] npawar commented on pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
npawar commented on pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#issuecomment-674172740
This doesn't explain why we saw the first 4 segments complete successfully. Afaik, there was no restart between testTable__0__3 and testTable__0__4
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] fx19880617 commented on pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
fx19880617 commented on pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#issuecomment-675124357
> I think the right fix is to not field any state transitions until the start() method has completed.
>
> We can have the state transition call wait on a semaphore?
We set ServerInstance::start as a addPreConnectCallback, then the ServerInstance will always start after helixManager connected.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] mcvsubbu commented on a change in pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
mcvsubbu commented on a change in pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#discussion_r470715315
##########
File path: pinot-server/src/main/java/org/apache/pinot/server/starter/helix/HelixServerStarter.java
##########
@@ -363,6 +363,7 @@ public void start()
LOGGER.info("Initializing server instance and registering state model factory");
Utils.logVersions();
+ ControllerLeaderLocator.create(_helixManager);
Review comment:
ControllerLeaderLocator uses helixManager to get the controller resource status, so you need to have the helix manager connected before any leader locator functionality is invoked. So your use case will not work if the same race condition happens again.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] fx19880617 commented on pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
fx19880617 commented on pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#issuecomment-675123916
> This doesn't explain why we saw the first 4 segments complete successfully. Afaik, there was no restart between testTable__0__3 and testTable__0__4
I think the user had a restart for this.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org
[GitHub] [incubator-pinot] fx19880617 commented on a change in pull request #5864: Fixing the race condition that segment finished before ControllerLeaderLocator created.
Posted by GitBox <gi...@apache.org>.
fx19880617 commented on a change in pull request #5864:
URL: https://github.com/apache/incubator-pinot/pull/5864#discussion_r470792533
##########
File path: pinot-server/src/main/java/org/apache/pinot/server/starter/helix/HelixServerStarter.java
##########
@@ -363,6 +363,7 @@ public void start()
LOGGER.info("Initializing server instance and registering state model factory");
Utils.logVersions();
+ ControllerLeaderLocator.create(_helixManager);
Review comment:
Here we only hold a reference to helixManager
since we set ServerInstance::start as a addPreConnectCallback, then the server will always start after helixManager connected.
----------------------------------------------------------------
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
---------------------------------------------------------------------
To unsubscribe, e-mail: commits-unsubscribe@pinot.apache.org
For additional commands, e-mail: commits-help@pinot.apache.org