[Pinot 1.2.0] Realtime table segment reload fails with error "Snapshot of validDocIds is required to preload segment"

[ajeydudhe]

Steps to reproduce

• Define REALTIME table schema and table config using Pinot 1.2.0
• In the table config, make sure the upsertConfig has enableSnapshot = true and enablePreload = true as below:

"upsertConfig": {
        "mode": "FULL",
        "comparisonColumns": ["someField"],
        "partialUpsertStrategies": {},
        "deleteRecordColumn": "isDeleted",
        "deletedKeysTTL": 86400000,
        "enableSnapshot": true,
        "enablePreload": true
}

• Load some records using Kafka and check that data is visible and all segments are GOOD.
• Now, pause the Kafka consumption using following command:

curl --location --request POST 'http://localhost:9000/tables/myTable/pauseConsumption'

• Make sure consumption is paused using following command:

curl --location 'http://localhost:9000/tables/myTable/pauseStatus'

• Resume the consumption using following command:

curl --location --request POST 'http://localhost:9000/tables/myTable/resumeConsumption'

• Now, check the segment status.
• All the older segments are marked BAD and new consuming ones as GOOD.
• The server logs has following error for segments failing to load:

2024-09-24 13:21:19 Caused by: java.lang.IllegalStateException: Snapshot of validDocIds is required to preload segment: myTable__0__0__20240924T0750Z, table: myTable_REALTIME

Note

• Same POC runs properly without any errors on Pinot 1.1.0
• Issue occurs only when using upsertConfig.enableSnapshot = true and upsertConfig.enablePreload = true

Exception

2024-09-24 13:21:19 2024/09/24 07:51:19.021 ERROR [HelixStateTransitionHandler] [HelixTaskExecutor-message_handle_thread_10] Exception while executing a state transition task myTable__0__0__20240924T0750Z
2024-09-24 13:21:19 java.lang.reflect.InvocationTargetException: null
2024-09-24 13:21:19     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(Native Method) ~[?:?]
2024-09-24 13:21:19     at java.base/jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:77) ~[?:?]
2024-09-24 13:21:19     at java.base/jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) ~[?:?]
2024-09-24 13:21:19     at java.base/java.lang.reflect.Method.invoke(Method.java:568) ~[?:?]
2024-09-24 13:21:19     at org.apache.helix.messaging.handling.HelixStateTransitionHandler.invoke(HelixStateTransitionHandler.java:350) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.helix.messaging.handling.HelixStateTransitionHandler.handleMessage(HelixStateTransitionHandler.java:278) [pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.helix.messaging.handling.HelixTask.call(HelixTask.java:97) [pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.helix.messaging.handling.HelixTask.call(HelixTask.java:49) [pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at java.base/java.util.concurrent.FutureTask.run(FutureTask.java:264) [?:?]
2024-09-24 13:21:19     at java.base/java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1136) [?:?]
2024-09-24 13:21:19     at java.base/java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:635) [?:?]
2024-09-24 13:21:19     at java.base/java.lang.Thread.run(Thread.java:840) [?:?]
2024-09-24 13:21:19 Caused by: java.lang.IllegalStateException: Snapshot of validDocIds is required to preload segment: myTable__0__0__20240924T0750Z, table: myTable_REALTIME
2024-09-24 13:21:19     at org.apache.pinot.shaded.com.google.common.base.Preconditions.checkState(Preconditions.java:838) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.segment.local.upsert.BasePartitionUpsertMetadataManager.doPreloadSegment(BasePartitionUpsertMetadataManager.java:513) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.segment.local.upsert.BasePartitionUpsertMetadataManager.preloadSegment(BasePartitionUpsertMetadataManager.java:498) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeTableDataManager.handleUpsert(RealtimeTableDataManager.java:585) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeTableDataManager.addSegment(RealtimeTableDataManager.java:541) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeTableDataManager.downloadAndReplaceConsumingSegment(RealtimeTableDataManager.java:628) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeSegmentDataManager.downloadSegmentAndReplace(RealtimeSegmentDataManager.java:1351) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeSegmentDataManager.goOnlineFromConsuming(RealtimeSegmentDataManager.java:1290) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.realtime.RealtimeTableDataManager.doAddOnlineSegment(RealtimeTableDataManager.java:421) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.core.data.manager.BaseTableDataManager.addOnlineSegment(BaseTableDataManager.java:313) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.server.starter.helix.HelixInstanceDataManager.addOnlineSegment(HelixInstanceDataManager.java:275) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     at org.apache.pinot.server.starter.helix.SegmentOnlineOfflineStateModelFactory$SegmentOnlineOfflineStateModel.onBecomeOnlineFromConsuming(SegmentOnlineOfflineStateModelFactory.java:88) ~[pinot-all-1.2.0-jar-with-dependencies.jar:1.2.0-cc33ac502a02e2fe830fe21e556234ee99351a7a]
2024-09-24 13:21:19     ... 12 more

[Jackie-Jiang]

@klsince @tibrewalpratik17 Can you help take a look? We probably need to loose the check

[tibrewalpratik17]

@klsince any idea why is this specifically occuring in 1.2 and not 1.1. It should have ideally happened in 1.1 as well as this check has been there since beginning: https://github.com/apache/pinot/pull/11020/files#diff-0a831c7605c3a8b7058200545bd732eb614526a4b03e4a972af66058874b507bR206-R207

All the older segments are marked BAD and new consuming ones as GOOD.

@ajeydudhe can you also share if the segments are in ERROR state or marked as OFFLINE in External view?

[klsince]

I'm wondering why resuming the consumption caused old segments to be added again. It seems like adding old segments had entered the preloading logic flow unexpectedly.

I'll see if I can repro this on my local.

[dang-stripe]

We've managed to hit this exception in our test clusters on 1.2 as well w/ snapshot + preload. I haven't been able to reproduce it yet though. The segments were in ERROR state.

The only relevant logs seem to be these snapshot failures, but I do not see any Caught exception while taking snapshot logs from https://github.com/apache/pinot/blob/master/pinot-segment-local/src/main/java/org/apache/pinot/segment/local/upsert/BasePartitionUpsertMetadataManager.java

[2024-09-23 15:15:23.682414] INFO [setup_attempts_REALTIME-327710-ConcurrentMapPartitionUpsertMetadataManager] [setup_attempts__327710__147__20240923T1515Z:138928] Taking snapshot for 147 segments
[2024-09-23 15:15:23.682430] INFO [ImmutableSegmentImpl] [setup_attempts__327710__147__20240923T1515Z:25] Persisted validDocIds for segment: setup_attempts__327710__146__20240923T1115Z with: 3 valid docs
[2024-09-23 15:15:23.682447] WARN [setup_attempts_REALTIME-327710-ConcurrentMapPartitionUpsertMetadataManager] [setup_attempts__327710__147__20240923T1515Z:138928] Missed taking snapshot for 146 immutable segments
[2024-09-23 15:15:23.682466] INFO [setup_attempts_REALTIME-327710-ConcurrentMapPartitionUpsertMetadataManager] [setup_attempts__327710__147__20240923T1515Z:138928] Finished taking snapshot for 1 immutable segments with 3 primary keys (out of 147 total segments, 0 are consuming segments) in 1 ms

[klsince]

HelixTaskExecutor-message_handle_thread_10 thread was preloading the segment, and this is already unexpected.

segment preloading should be done by a separate preloading thread pool whose thread name should be like 'segment-preload-thread-xx'

so somehow server entered the preloading logic unexpected, and did it on helix thread unexpectedly too.

this reminded me of a fix I did weeks ago (but after 1.2.0): #13747 to refine the check of enabling segment preloading.

[klsince]

hi @dang-stripe @ajeydudhe

could you try to set this server config max.segment.preload.threads a positive value (like 8 or 2x the cpu cores). When set enablePreload to true, this preloading thread pool should be set too.

[dang-stripe]

actually i wouldn't be surprised if that's the issue. we had that turned on for one of our servers and not the others. we clearly see the error on a server that didn't have this on, while preload was enabled on the table. we've since rolled out the threads setting to all the servers and haven't been able to repro the behavior.

let me try to re-test w/ it off. is it possible to set a sane default for preload threads in code or skip preloading in this case?

[klsince]

the default 0 should have disabled the preloading, but in 1.2.0 or earlier, it's not disabled cleanly, because an internal flag _isPreloading flag didn't consider the pool size. The fix #13747 should have corrected this, so that if pool size is 0, the preloading mechanism is disabled cleanly.

[dang-stripe]

thanks we'll pull in that fix. i was able to repro the issue by rebalancing the table so segments moved to servers that didn't have max.segment.preload.threads set and those segments came up in ERROR state.

[ajeydudhe]

@klsince any idea why is this specifically occuring in 1.2 and not 1.1. It should have ideally happened in 1.1 as well as this check has been there since beginning: https://github.com/apache/pinot/pull/11020/files#diff-0a831c7605c3a8b7058200545bd732eb614526a4b03e4a972af66058874b507bR206-R207

All the older segments are marked BAD and new consuming ones as GOOD.

@ajeydudhe can you also share if the segments are in ERROR state or marked as OFFLINE in External view?

All the segments are in ERROR state.

Additional info

• I am using the attached docker compose for Pinot using following command:

docker-compose up --scale server=2 -d

• For Kafka, I am creating topic with 10 partitions and hence the table creates 10 consuming segments. But same issue is observed with 2 partitions.

Pinot Docker.zip

[klsince]

@ajeydudhe could you try to set this server config max.segment.preload.threads to a positive value like 2x the cpu cores.

@tibrewalpratik17 I think this started to happen in 1.2.0 might be due to the refactoring of the preloading logic between 1.1.0 and 1.2.0, and the way to init the _isPreloading boolean flag was changed. Should have a test on this edge condition.

[ajeydudhe]

@ajeydudhe could you try to set this server config max.segment.preload.threads to a positive value like 2x the cpu cores.

@tibrewalpratik17 I think this started to happen in 1.2.0 might be due to the refactoring of the preloading logic between 1.1.0 and 1.2.0, and the way to init the _isPreloading boolean flag was changed. Should have a test on this edge condition.

Thanks @klsince. The issue is not seen if the max.segment.preload.threads config is set. I tested with max.segment.preload.threads = 2.