[SUPPORT] Facing long index lookup times with dynamic bloom filter

**Describe the problem you faced**

We have a process that ingests 100 - 130GB of data per day into a COW table partitioned on year/month/day. The key is timestamp_eventId_skuNumber. A single batch may contain events that span up to 14 event dates (meaning we fan out to up to 14 partitions). Our write operation is an UPSERT in order to not have duplicates in the table.

For some input batches, we see very long index lookup times (3 - 10 hours), with large shuffle writes and reads (10 - 25 TB).



When I look at the tasks, it seems like each task is reading in a large amount of data, requiring us to create clusters with 1 executor per node. See the following task list:


When I look at the tasks that take the longest, I see the following types of log statements:

```
2025-04-04 04:35:01,928 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.common.table.view.RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-133-87.ec2.internal:43393/v1/hoodie/view/datafile/latest/partition?partition=region%3DNA%2Fyear%3D2025%2Fmonth%3D03%2Fday%3D16&basepath=s3%3A%2F%2Fmads-ms-conversions-prod%2Fdaily-data%2Fglider&fileid=85460a75-3674-412c-8bec-36ea8a4345e7-0&lastinstantts=20250403234937872&timelinehash=30ed4d42429b272930e0456aba07ccac0e1b20f0cd421dab56afb2f1b6126952)
2025-04-04 04:35:01,967 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.io.HoodieKeyLookupHandle: Total records (7915696), bloom filter candidates (0)/fp(0), actual matches (0)
2025-04-04 04:35:01,967 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.common.table.view.RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-133-87.ec2.internal:43393/v1/hoodie/view/datafile/latest/partition?partition=region%3DNA%2Fyear%3D2025%2Fmonth%3D03%2Fday%3D06&basepath=s3%3A%2F%2Fmads-ms-conversions-prod%2Fdaily-data%2Fglider&fileid=a9c2acd3-8dde-4d15-b0d8-458cd8847242-0&lastinstantts=20250403234937872&timelinehash=30ed4d42429b272930e0456aba07ccac0e1b20f0cd421dab56afb2f1b6126952)
2025-04-04 04:35:02,388 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) com.amazon.ws.emr.hadoop.fs.s3n.S3NativeFileSystem: Opening 's3://mads-ms-conversions-prod/daily-data/glider/region=NA/year=2025/month=03/day=06/a9c2acd3-8dde-4d15-b0d8-458cd8847242-0_2-2066-1095662_20250327160656670.parquet' for reading
2025-04-04 04:35:03,035 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.io.HoodieKeyLookupHandle: Read bloom filter from (region=NA/year=2025/month=03/day=06,a9c2acd3-8dde-4d15-b0d8-458cd8847242-0) in 1068 ms
2025-04-04 04:35:03,808 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.common.table.view.RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-133-87.ec2.internal:43393/v1/hoodie/view/datafile/latest/partition?partition=region%3DNA%2Fyear%3D2025%2Fmonth%3D03%2Fday%3D06&basepath=s3%3A%2F%2Fmads-ms-conversions-prod%2Fdaily-data%2Fglider&fileid=a9c2acd3-8dde-4d15-b0d8-458cd8847242-0&lastinstantts=20250403234937872&timelinehash=30ed4d42429b272930e0456aba07ccac0e1b20f0cd421dab56afb2f1b6126952)
2025-04-04 04:35:03,847 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.io.HoodieKeyLookupHandle: Total records (17873), bloom filter candidates (0)/fp(0), actual matches (0)
2025-04-04 04:35:03,847 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.common.table.view.RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-133-87.ec2.internal:43393/v1/hoodie/view/datafile/latest/partition?partition=region%3DNA%2Fyear%3D2025%2Fmonth%3D03%2Fday%3D09&basepath=s3%3A%2F%2Fmads-ms-conversions-prod%2Fdaily-data%2Fglider&fileid=df7becfe-2b4d-4e91-bc2d-e23f3bc91aa9-0&lastinstantts=20250403234937872&timelinehash=30ed4d42429b272930e0456aba07ccac0e1b20f0cd421dab56afb2f1b6126952)
2025-04-04 04:35:04,099 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) com.amazon.ws.emr.hadoop.fs.s3n.S3NativeFileSystem: Opening 's3://mads-ms-conversions-prod/daily-data/glider/region=NA/year=2025/month=03/day=09/df7becfe-2b4d-4e91-bc2d-e23f3bc91aa9-0_2-1502-791157_20250327143233103.parquet' for reading
2025-04-04 04:35:04,726 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.io.HoodieKeyLookupHandle: Read bloom filter from (region=NA/year=2025/month=03/day=09,df7becfe-2b4d-4e91-bc2d-e23f3bc91aa9-0) in 879 ms
2025-04-04 04:35:05,905 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.common.table.view.RemoteHoodieTableFileSystemView: Sending request : (http://ip-10-0-133-87.ec2.internal:43393/v1/hoodie/view/datafile/latest/partition?partition=region%3DNA%2Fyear%3D2025%2Fmonth%3D03%2Fday%3D09&basepath=s3%3A%2F%2Fmads-ms-conversions-prod%2Fdaily-data%2Fglider&fileid=df7becfe-2b4d-4e91-bc2d-e23f3bc91aa9-0&lastinstantts=20250403234937872&timelinehash=30ed4d42429b272930e0456aba07ccac0e1b20f0cd421dab56afb2f1b6126952)
2025-04-04 04:35:05,952 [INFO] (Executor task launch worker for task 0.0 in stage 32.0 (TID 66836)) org.apache.hudi.io.HoodieKeyLookupHandle: Total records (27262), bloom filter candidates (0)/fp(0), actual matches (0)
```

It seems to me like something isn't working correctly with our index, but I'm having trouble understanding what exactly is going on in order to help me tune our settings correctly. The following settings are being used for our job:

```
Computed insert options:
hoodie.datasource.write.insert.drop.duplicates -> false
hoodie.parquet.small.file.limit -> 104857600
hoodie.copyonwrite.record.size.estimate -> 106
hoodie.insert.shuffle.parallelism -> 12000
hoodie.datasource.write.precombine.field -> eventVersion
hoodie.bloom.index.filter.dynamic.max.entries -> 1270220
hoodie.cleaner.fileversions.retained -> 2
hoodie.parquet.max.file.size -> 134217728
hoodie.cleaner.parallelism -> 12000
hoodie.write.lock.client.num_retries -> 10
hoodie.bloom.index.prune.by.ranges -> true
hoodie.metadata.enable -> true
hoodie.clean.automatic -> false
hoodie.datasource.write.operation -> UPSERT
hoodie.write.lock.wait_time_ms -> 600000
hoodie.metrics.reporter.type -> CLOUDWATCH
hoodie.datasource.write.recordkey.field -> timestamp,eventId,trackedItem
hoodie.table.name -> ******
hoodie.datasource.write.table.type -> COPY_ON_WRITE
hoodie.datasource.write.hive_style_partitioning -> true
hoodie.write.lock.dynamodb.partition_key -> ******
hoodie.cleaner.policy -> KEEP_LATEST_FILE_VERSIONS
hoodie.write.markers.type -> DIRECT
hoodie.metrics.on -> false
hoodie.datasource.write.reconcile.schema -> true
hoodie.datasource.write.keygenerator.class -> org.apache.hudi.keygen.ComplexKeyGenerator
hoodie.cleaner.policy.failed.writes -> LAZY
hoodie.upsert.shuffle.parallelism -> 12000
hoodie.write.lock.dynamodb.table -> HoodieLockTable
hoodie.write.lock.provider -> org.apache.hudi.aws.transaction.lock.DynamoDBBasedLockProvider
hoodie.datasource.write.partitionpath.field -> region,year,month,day
hoodie.bloom.index.filter.type -> DYNAMIC_V0
hoodie.write.lock.wait_time_ms_between_retry -> 30000
hoodie.write.concurrency.mode -> optimistic_concurrency_control
hoodie.write.lock.dynamodb.region -> us-east-1
```

We're using a
**To Reproduce**

Steps to reproduce the behavior:

I'm unclear on how to fully reproduce, some batches of data ingest quickly (20 - 30 min), others take 3 - 10 hours. A couple of questions on my end are:

1. How can we better inspect the index behavior and verify it's doing the right thing?
2. Is there a way to log more verbose logs related to index behavior?
3. What does it mean if the bloom filter has 0 candidates?
4. I'm not 100% clear on how `hoodie.index.bloom.num_entries` and `hoodie.bloom.index.filter.dynamic.max.entries` interact. Does the first setting indicate the initial size and then does the second setting indicate the max size before HUDI will resize it? When does this resize happen? When the file receives updates?

Thanks in advance!!

**Environment Description**

* Hudi version : 11.1

* Spark version : 3.2.1

* Hive version : 3.1.3

* Hadoop version : 3.2.1

* Storage (HDFS/S3/GCS..) : s3

* Running on Docker? (yes/no) : no

Start with the HoodieKeyLookupHandle and RemoteHoodieTableFileSystemView log entries, then review the DYNAMIC_V0 settings listed in the issue, especially hoodie.index.bloom.num_entries and hoodie.bloom.index.filter.dynamic.max.entries. Use the reported S3 and Spark workload details to investigate index behavior and logging options. Done means explaining the zero-candidate results, configuration interaction, and likely cause of the variable lookup times.

Written by the indexing model from the issue text.