You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@hudi.apache.org by "voonhous (via GitHub)" <gi...@apache.org> on 2025/12/25 13:00:59 UTC
[I] Consistency Guard Causes 25-Second Delays in CleanActionExecutor on Strongly Consistent Filesystems [hudi]
voonhous opened a new issue, #17714:
URL: https://github.com/apache/hudi/issues/17714
### Bug Description
**What happened:**
When consistency guard is enabled, file deletion operations in `CleanActionExecutor` experience severe performance degradation, taking ~25 seconds per file on strongly consistent filesystems (e.g., local file://) where instant consistency is guaranteed.
This occurs due to unnecessary exponential backoff waiting in `getPathInfo()` calls.
Something interesting is that the timeouts for file deletions all match up to the exponential backoff times:
**FailSafeConsistencyGuard.waitTillFileAppears()** retries with exponential backoff:
- Attempt 1: 400ms
- Attempt 2: 800ms
- Attempt 3: 1600ms
- Attempt 4: 3200ms
- Attempt 5: 6400ms
- Attempt 6: 12800ms
- **Total: 25200ms (25.2 seconds)**
**Evidence from Production Logs**
Note: Full log can be found below
```
11782 [Executor task launch worker for task 1.0] DEBUG CleanActionExecutor - Working on delete path: ...parquet
37014 [task-result-getter-1] INFO TaskSetManager - Finished task 1.0 in stage 166.0 (TID 1091) in 25234 ms
```
Multiple concurrent tasks showed consistent ~25-second delays:
- Task 1.0: **25234ms**
- Task 5.0: **25243ms**
- Task 3.0: **25248ms**
- Task 7.0: **25248ms**
- Task 11.0: **25244ms**
- Task 9.0: **25247ms**
- Task 13.0: **25246ms**
- Task 15.0: **25226ms**
**What you expected:**
Strongly consistent systems should not block at all.
**Steps to reproduce:**
1. Run any test in `org.apache.hudi.table.action.clean.TestCleanerInsertAndCleanByVersions`
2. Running all tests in `TestCleanerInsertAndCleanByVersions` takes around 12 minute locally
3. Disabling consistency guard `withConsistencyCheckEnabled(false)` reduces the execution time to ~40 seconds.
**logs**
```log
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 1.0 in stage 166.0 (TID 1091) (192.168.1.190, executor driver, partition 1, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 2.0 in stage 166.0 (TID 1092) (192.168.1.190, executor driver, partition 2, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 3.0 in stage 166.0 (TID 1093) (192.168.1.190, executor driver, partition 3, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 4.0 in stage 166.0 (TID 1094) (192.168.1.190, executor driver, partition 4, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 5.0 in stage 166.0 (TID 1095) (192.168.1.190, executor driver, partition 5, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 6.0 in stage 166.0 (TID 1096) (192.168.1.190, executor driver, partition 6, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 7.0 in stage 166.0 (TID 1097) (192.168.1.190, executor driver, partition 7, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11780 [Executor task launch worker for task 1.0 in stage 166.0 (TID 1091)] INFO org.apache.spark.executor.Executor [] - Running task 1.0 in stage 166.0 (TID 1091)
11780 [Executor task launch worker for task 0.0 in stage 166.0 (TID 1090)] INFO org.apache.spark.executor.Executor [] - Running task 0.0 in stage 166.0 (TID 1090)
11780 [Executor task launch worker for task 4.0 in stage 166.0 (TID 1094)] INFO org.apache.spark.executor.Executor [] - Running task 4.0 in stage 166.0 (TID 1094)
11780 [Executor task launch worker for task 2.0 in stage 166.0 (TID 1092)] INFO org.apache.spark.executor.Executor [] - Running task 2.0 in stage 166.0 (TID 1092)
11780 [Executor task launch worker for task 6.0 in stage 166.0 (TID 1096)] INFO org.apache.spark.executor.Executor [] - Running task 6.0 in stage 166.0 (TID 1096)
11780 [Executor task launch worker for task 5.0 in stage 166.0 (TID 1095)] INFO org.apache.spark.executor.Executor [] - Running task 5.0 in stage 166.0 (TID 1095)
11780 [Executor task launch worker for task 7.0 in stage 166.0 (TID 1097)] INFO org.apache.spark.executor.Executor [] - Running task 7.0 in stage 166.0 (TID 1097)
11780 [Executor task launch worker for task 3.0 in stage 166.0 (TID 1093)] INFO org.apache.spark.executor.Executor [] - Running task 3.0 in stage 166.0 (TID 1093)
11782 [Executor task launch worker for task 6.0 in stage 166.0 (TID 1096)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/428ee013-be77-4249-aeb7-7cedbc4bdaef-2_4-84-388_20251225195229434.parquet
11782 [Executor task launch worker for task 5.0 in stage 166.0 (TID 1095)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-0_3-56-205_20251225195218434.parquet
11782 [Executor task launch worker for task 0.0 in stage 166.0 (TID 1090)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-2_1-84-385_20251225195229434.parquet
11782 [Executor task launch worker for task 4.0 in stage 166.0 (TID 1094)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-0_3-84-387_20251225195229434.parquet
11782 [Executor task launch worker for task 2.0 in stage 166.0 (TID 1092)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/60332686-a57d-4a14-8e55-dc4ecfee0a61-0_2-84-386_20251225195229434.parquet
11782 [Executor task launch worker for task 1.0 in stage 166.0 (TID 1091)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-2_1-56-203_20251225195218434.parquet
11782 [Executor task launch worker for task 7.0 in stage 166.0 (TID 1097)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/428ee013-be77-4249-aeb7-7cedbc4bdaef-2_4-56-206_20251225195218434.parquet
11782 [Executor task launch worker for task 6.0 in stage 166.0 (TID 1096)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/428ee013-be77-4249-aeb7-7cedbc4bdaef-2_4-84-388_20251225195229434.parquet
11782 [Executor task launch worker for task 2.0 in stage 166.0 (TID 1092)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/60332686-a57d-4a14-8e55-dc4ecfee0a61-0_2-84-386_20251225195229434.parquet
11782 [Executor task launch worker for task 4.0 in stage 166.0 (TID 1094)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-0_3-84-387_20251225195229434.parquet
11782 [Executor task launch worker for task 3.0 in stage 166.0 (TID 1093)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/60332686-a57d-4a14-8e55-dc4ecfee0a61-0_2-56-204_20251225195218434.parquet
11782 [Executor task launch worker for task 0.0 in stage 166.0 (TID 1090)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-2_1-84-385_20251225195229434.parquet
11784 [Executor task launch worker for task 4.0 in stage 166.0 (TID 1094)] INFO org.apache.spark.executor.Executor [] - Finished task 4.0 in stage 166.0 (TID 1094). 1148 bytes result sent to driver
11785 [dispatcher-event-loop-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 8.0 in stage 166.0 (TID 1098) (192.168.1.190, executor driver, partition 8, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11785 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 4.0 in stage 166.0 (TID 1094) in 5 ms on 192.168.1.190 (executor driver) (1/54)
11785 [Executor task launch worker for task 8.0 in stage 166.0 (TID 1098)] INFO org.apache.spark.executor.Executor [] - Running task 8.0 in stage 166.0 (TID 1098)
11785 [Executor task launch worker for task 0.0 in stage 166.0 (TID 1090)] INFO org.apache.spark.executor.Executor [] - Finished task 0.0 in stage 166.0 (TID 1090). 1148 bytes result sent to driver
11785 [dispatcher-event-loop-4] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 9.0 in stage 166.0 (TID 1099) (192.168.1.190, executor driver, partition 9, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11785 [Executor task launch worker for task 2.0 in stage 166.0 (TID 1092)] INFO org.apache.spark.executor.Executor [] - Finished task 2.0 in stage 166.0 (TID 1092). 1148 bytes result sent to driver
11785 [dispatcher-event-loop-6] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 10.0 in stage 166.0 (TID 1100) (192.168.1.190, executor driver, partition 10, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11785 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 0.0 in stage 166.0 (TID 1090) in 5 ms on 192.168.1.190 (executor driver) (2/54)
11786 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 2.0 in stage 166.0 (TID 1092) in 6 ms on 192.168.1.190 (executor driver) (3/54)
11786 [Executor task launch worker for task 9.0 in stage 166.0 (TID 1099)] INFO org.apache.spark.executor.Executor [] - Running task 9.0 in stage 166.0 (TID 1099)
11786 [Executor task launch worker for task 8.0 in stage 166.0 (TID 1098)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/8b2806c0-a13e-45a6-a642-40c27deecf64-0_5-84-389_20251225195229434.parquet
11786 [Executor task launch worker for task 6.0 in stage 166.0 (TID 1096)] INFO org.apache.spark.executor.Executor [] - Finished task 6.0 in stage 166.0 (TID 1096). 1148 bytes result sent to driver
11786 [dispatcher-event-loop-5] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 11.0 in stage 166.0 (TID 1101) (192.168.1.190, executor driver, partition 11, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11786 [Executor task launch worker for task 10.0 in stage 166.0 (TID 1100)] INFO org.apache.spark.executor.Executor [] - Running task 10.0 in stage 166.0 (TID 1100)
11786 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 6.0 in stage 166.0 (TID 1096) in 6 ms on 192.168.1.190 (executor driver) (4/54)
11786 [Executor task launch worker for task 8.0 in stage 166.0 (TID 1098)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/8b2806c0-a13e-45a6-a642-40c27deecf64-0_5-84-389_20251225195229434.parquet
11786 [Executor task launch worker for task 11.0 in stage 166.0 (TID 1101)] INFO org.apache.spark.executor.Executor [] - Running task 11.0 in stage 166.0 (TID 1101)
11786 [Executor task launch worker for task 9.0 in stage 166.0 (TID 1099)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/8b2806c0-a13e-45a6-a642-40c27deecf64-0_5-56-207_20251225195218434.parquet
11787 [Executor task launch worker for task 10.0 in stage 166.0 (TID 1100)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-2_7-84-391_20251225195229434.parquet
11787 [Executor task launch worker for task 11.0 in stage 166.0 (TID 1101)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-2_6-56-208_20251225195218434.parquet
11787 [Executor task launch worker for task 10.0 in stage 166.0 (TID 1100)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-2_7-84-391_20251225195229434.parquet
11788 [Executor task launch worker for task 8.0 in stage 166.0 (TID 1098)] INFO org.apache.spark.executor.Executor [] - Finished task 8.0 in stage 166.0 (TID 1098). 1105 bytes result sent to driver
11788 [dispatcher-event-loop-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 12.0 in stage 166.0 (TID 1102) (192.168.1.190, executor driver, partition 12, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11788 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 8.0 in stage 166.0 (TID 1098) in 3 ms on 192.168.1.190 (executor driver) (5/54)
11788 [Executor task launch worker for task 12.0 in stage 166.0 (TID 1102)] INFO org.apache.spark.executor.Executor [] - Running task 12.0 in stage 166.0 (TID 1102)
11788 [Executor task launch worker for task 10.0 in stage 166.0 (TID 1100)] INFO org.apache.spark.executor.Executor [] - Finished task 10.0 in stage 166.0 (TID 1100). 1105 bytes result sent to driver
11788 [dispatcher-event-loop-6] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 13.0 in stage 166.0 (TID 1103) (192.168.1.190, executor driver, partition 13, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11788 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 10.0 in stage 166.0 (TID 1100) in 3 ms on 192.168.1.190 (executor driver) (6/54)
11788 [Executor task launch worker for task 13.0 in stage 166.0 (TID 1103)] INFO org.apache.spark.executor.Executor [] - Running task 13.0 in stage 166.0 (TID 1103)
11802 [Executor task launch worker for task 12.0 in stage 166.0 (TID 1102)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6f8227b9-bfe1-4d3e-b29e-0e9aeb9893a0-0_6-84-390_20251225195229434.parquet
11803 [Executor task launch worker for task 12.0 in stage 166.0 (TID 1102)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6f8227b9-bfe1-4d3e-b29e-0e9aeb9893a0-0_6-84-390_20251225195229434.parquet
11803 [Executor task launch worker for task 13.0 in stage 166.0 (TID 1103)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6f8227b9-bfe1-4d3e-b29e-0e9aeb9893a0-0_7-56-209_20251225195218434.parquet
11805 [Executor task launch worker for task 12.0 in stage 166.0 (TID 1102)] INFO org.apache.spark.executor.Executor [] - Finished task 12.0 in stage 166.0 (TID 1102). 1148 bytes result sent to driver
11805 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 14.0 in stage 166.0 (TID 1104) (192.168.1.190, executor driver, partition 14, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11806 [Executor task launch worker for task 14.0 in stage 166.0 (TID 1104)] INFO org.apache.spark.executor.Executor [] - Running task 14.0 in stage 166.0 (TID 1104)
11806 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 12.0 in stage 166.0 (TID 1102) in 18 ms on 192.168.1.190 (executor driver) (7/54)
11807 [Executor task launch worker for task 14.0 in stage 166.0 (TID 1104)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/b3ddc06a-6593-484f-b419-beec46621aa0-2_9-84-393_20251225195229434.parquet
11807 [Executor task launch worker for task 14.0 in stage 166.0 (TID 1104)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/b3ddc06a-6593-484f-b419-beec46621aa0-2_9-84-393_20251225195229434.parquet
11808 [Executor task launch worker for task 14.0 in stage 166.0 (TID 1104)] INFO org.apache.spark.executor.Executor [] - Finished task 14.0 in stage 166.0 (TID 1104). 1105 bytes result sent to driver
11809 [dispatcher-event-loop-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 15.0 in stage 166.0 (TID 1105) (192.168.1.190, executor driver, partition 15, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
11809 [task-result-getter-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 14.0 in stage 166.0 (TID 1104) in 4 ms on 192.168.1.190 (executor driver) (8/54)
11809 [Executor task launch worker for task 15.0 in stage 166.0 (TID 1105)] INFO org.apache.spark.executor.Executor [] - Running task 15.0 in stage 166.0 (TID 1105)
11810 [Executor task launch worker for task 15.0 in stage 166.0 (TID 1105)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/b3ddc06a-6593-484f-b419-beec46621aa0-2_8-56-210_20251225195218434.parquet
37010 [Executor task launch worker for task 1.0 in stage 166.0 (TID 1091)] INFO org.apache.spark.executor.Executor [] - Finished task 1.0 in stage 166.0 (TID 1091). 1148 bytes result sent to driver
37012 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 16.0 in stage 166.0 (TID 1106) (192.168.1.190, executor driver, partition 16, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
37013 [Executor task launch worker for task 16.0 in stage 166.0 (TID 1106)] INFO org.apache.spark.executor.Executor [] - Running task 16.0 in stage 166.0 (TID 1106)
37014 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 1.0 in stage 166.0 (TID 1091) in 25234 ms on 192.168.1.190 (executor driver) (9/54)
37017 [Executor task launch worker for task 5.0 in stage 166.0 (TID 1095)] INFO org.apache.spark.executor.Executor [] - Finished task 5.0 in stage 166.0 (TID 1095). 1148 bytes result sent to driver
37020 [Executor task launch worker for task 16.0 in stage 166.0 (TID 1106)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6ca91470-0050-4166-9627-4ced97e77b35-2_8-84-392_20251225195229434.parquet
37021 [dispatcher-event-loop-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 17.0 in stage 166.0 (TID 1107) (192.168.1.190, executor driver, partition 17, PROCESS_LOCAL, 4604 bytes) taskResourceAssignments Map()
37022 [Executor task launch worker for task 3.0 in stage 166.0 (TID 1093)] INFO org.apache.spark.executor.Executor [] - Finished task 3.0 in stage 166.0 (TID 1093). 1148 bytes result sent to driver
37022 [Executor task launch worker for task 16.0 in stage 166.0 (TID 1106)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6ca91470-0050-4166-9627-4ced97e77b35-2_8-84-392_20251225195229434.parquet
37023 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 5.0 in stage 166.0 (TID 1095) in 25243 ms on 192.168.1.190 (executor driver) (10/54)
37024 [Executor task launch worker for task 17.0 in stage 166.0 (TID 1107)] INFO org.apache.spark.executor.Executor [] - Running task 17.0 in stage 166.0 (TID 1107)
37026 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 18.0 in stage 166.0 (TID 1108) (192.168.1.190, executor driver, partition 18, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37026 [Executor task launch worker for task 7.0 in stage 166.0 (TID 1097)] INFO org.apache.spark.executor.Executor [] - Finished task 7.0 in stage 166.0 (TID 1097). 1148 bytes result sent to driver
37027 [dispatcher-event-loop-7] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 19.0 in stage 166.0 (TID 1109) (192.168.1.190, executor driver, partition 19, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37028 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 3.0 in stage 166.0 (TID 1093) in 25248 ms on 192.168.1.190 (executor driver) (11/54)
37028 [Executor task launch worker for task 18.0 in stage 166.0 (TID 1108)] INFO org.apache.spark.executor.Executor [] - Running task 18.0 in stage 166.0 (TID 1108)
37028 [task-result-getter-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 7.0 in stage 166.0 (TID 1097) in 25248 ms on 192.168.1.190 (executor driver) (12/54)
37028 [Executor task launch worker for task 19.0 in stage 166.0 (TID 1109)] INFO org.apache.spark.executor.Executor [] - Running task 19.0 in stage 166.0 (TID 1109)
37030 [Executor task launch worker for task 11.0 in stage 166.0 (TID 1101)] INFO org.apache.spark.executor.Executor [] - Finished task 11.0 in stage 166.0 (TID 1101). 1105 bytes result sent to driver
37030 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 20.0 in stage 166.0 (TID 1110) (192.168.1.190, executor driver, partition 20, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37031 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 11.0 in stage 166.0 (TID 1101) in 25244 ms on 192.168.1.190 (executor driver) (13/54)
37031 [Executor task launch worker for task 20.0 in stage 166.0 (TID 1110)] INFO org.apache.spark.executor.Executor [] - Running task 20.0 in stage 166.0 (TID 1110)
37031 [Executor task launch worker for task 9.0 in stage 166.0 (TID 1099)] INFO org.apache.spark.executor.Executor [] - Finished task 9.0 in stage 166.0 (TID 1099). 1105 bytes result sent to driver
37031 [Executor task launch worker for task 18.0 in stage 166.0 (TID 1108)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-0_10-84-394_20251225195229434.parquet
37032 [Executor task launch worker for task 17.0 in stage 166.0 (TID 1107)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2016/03/15/6ca91470-0050-4166-9627-4ced97e77b35-2_9-56-211_20251225195218434.parquet
37032 [Executor task launch worker for task 19.0 in stage 166.0 (TID 1109)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-0_10-56-212_20251225195218434.parquet
37032 [dispatcher-event-loop-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 21.0 in stage 166.0 (TID 1111) (192.168.1.190, executor driver, partition 21, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37032 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 9.0 in stage 166.0 (TID 1099) in 25247 ms on 192.168.1.190 (executor driver) (14/54)
37032 [Executor task launch worker for task 21.0 in stage 166.0 (TID 1111)] INFO org.apache.spark.executor.Executor [] - Running task 21.0 in stage 166.0 (TID 1111)
37032 [Executor task launch worker for task 18.0 in stage 166.0 (TID 1108)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/5f7a912c-5cfa-4ddf-b0a7-ebdd61950ed6-0_10-84-394_20251225195229434.parquet
37033 [Executor task launch worker for task 16.0 in stage 166.0 (TID 1106)] INFO org.apache.spark.executor.Executor [] - Finished task 16.0 in stage 166.0 (TID 1106). 1148 bytes result sent to driver
37033 [dispatcher-event-loop-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 22.0 in stage 166.0 (TID 1112) (192.168.1.190, executor driver, partition 22, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37033 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 16.0 in stage 166.0 (TID 1106) in 21 ms on 192.168.1.190 (executor driver) (15/54)
37033 [Executor task launch worker for task 20.0 in stage 166.0 (TID 1110)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/60332686-a57d-4a14-8e55-dc4ecfee0a61-2_11-84-395_20251225195229434.parquet
37033 [Executor task launch worker for task 22.0 in stage 166.0 (TID 1112)] INFO org.apache.spark.executor.Executor [] - Running task 22.0 in stage 166.0 (TID 1112)
37034 [Executor task launch worker for task 20.0 in stage 166.0 (TID 1110)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/60332686-a57d-4a14-8e55-dc4ecfee0a61-2_11-84-395_20251225195229434.parquet
37034 [Executor task launch worker for task 13.0 in stage 166.0 (TID 1103)] INFO org.apache.spark.executor.Executor [] - Finished task 13.0 in stage 166.0 (TID 1103). 1148 bytes result sent to driver
37034 [dispatcher-event-loop-6] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 23.0 in stage 166.0 (TID 1113) (192.168.1.190, executor driver, partition 23, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37034 [task-result-getter-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 13.0 in stage 166.0 (TID 1103) in 25246 ms on 192.168.1.190 (executor driver) (16/54)
37034 [Executor task launch worker for task 23.0 in stage 166.0 (TID 1113)] INFO org.apache.spark.executor.Executor [] - Running task 23.0 in stage 166.0 (TID 1113)
37034 [Executor task launch worker for task 21.0 in stage 166.0 (TID 1111)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/60332686-a57d-4a14-8e55-dc4ecfee0a61-2_11-56-213_20251225195218434.parquet
37035 [Executor task launch worker for task 15.0 in stage 166.0 (TID 1105)] INFO org.apache.spark.executor.Executor [] - Finished task 15.0 in stage 166.0 (TID 1105). 1105 bytes result sent to driver
37035 [Executor task launch worker for task 22.0 in stage 166.0 (TID 1112)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-2_13-84-397_20251225195229434.parquet
37035 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 24.0 in stage 166.0 (TID 1114) (192.168.1.190, executor driver, partition 24, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37035 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 15.0 in stage 166.0 (TID 1105) in 25226 ms on 192.168.1.190 (executor driver) (17/54)
37035 [Executor task launch worker for task 24.0 in stage 166.0 (TID 1114)] INFO org.apache.spark.executor.Executor [] - Running task 24.0 in stage 166.0 (TID 1114)
37035 [Executor task launch worker for task 22.0 in stage 166.0 (TID 1112)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-2_13-84-397_20251225195229434.parquet
37035 [Executor task launch worker for task 18.0 in stage 166.0 (TID 1108)] INFO org.apache.spark.executor.Executor [] - Finished task 18.0 in stage 166.0 (TID 1108). 1148 bytes result sent to driver
37036 [dispatcher-event-loop-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 25.0 in stage 166.0 (TID 1115) (192.168.1.190, executor driver, partition 25, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37036 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 18.0 in stage 166.0 (TID 1108) in 10 ms on 192.168.1.190 (executor driver) (18/54)
37036 [Executor task launch worker for task 25.0 in stage 166.0 (TID 1115)] INFO org.apache.spark.executor.Executor [] - Running task 25.0 in stage 166.0 (TID 1115)
37036 [Executor task launch worker for task 23.0 in stage 166.0 (TID 1113)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/49508c54-e5c7-42b5-bb2d-cb57f4fc762d-2_13-56-215_20251225195218434.parquet
37036 [Executor task launch worker for task 20.0 in stage 166.0 (TID 1110)] INFO org.apache.spark.executor.Executor [] - Finished task 20.0 in stage 166.0 (TID 1110). 1148 bytes result sent to driver
37036 [dispatcher-event-loop-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 26.0 in stage 166.0 (TID 1116) (192.168.1.190, executor driver, partition 26, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37037 [Executor task launch worker for task 26.0 in stage 166.0 (TID 1116)] INFO org.apache.spark.executor.Executor [] - Running task 26.0 in stage 166.0 (TID 1116)
37037 [Executor task launch worker for task 24.0 in stage 166.0 (TID 1114)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-0_12-84-396_20251225195229434.parquet
37037 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 20.0 in stage 166.0 (TID 1110) in 7 ms on 192.168.1.190 (executor driver) (19/54)
37037 [Executor task launch worker for task 24.0 in stage 166.0 (TID 1114)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-0_12-84-396_20251225195229434.parquet
37037 [Executor task launch worker for task 25.0 in stage 166.0 (TID 1115)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6dd0970e-0f42-45a0-bfaf-056b3e8928a2-0_12-56-214_20251225195218434.parquet
37038 [Executor task launch worker for task 22.0 in stage 166.0 (TID 1112)] INFO org.apache.spark.executor.Executor [] - Finished task 22.0 in stage 166.0 (TID 1112). 1148 bytes result sent to driver
37038 [Executor task launch worker for task 26.0 in stage 166.0 (TID 1116)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/8b2806c0-a13e-45a6-a642-40c27deecf64-1_14-84-398_20251225195229434.parquet
37038 [dispatcher-event-loop-6] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 27.0 in stage 166.0 (TID 1117) (192.168.1.190, executor driver, partition 27, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37038 [task-result-getter-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 22.0 in stage 166.0 (TID 1112) in 5 ms on 192.168.1.190 (executor driver) (20/54)
37038 [Executor task launch worker for task 27.0 in stage 166.0 (TID 1117)] INFO org.apache.spark.executor.Executor [] - Running task 27.0 in stage 166.0 (TID 1117)
37038 [Executor task launch worker for task 26.0 in stage 166.0 (TID 1116)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/8b2806c0-a13e-45a6-a642-40c27deecf64-1_14-84-398_20251225195229434.parquet
37039 [Executor task launch worker for task 24.0 in stage 166.0 (TID 1114)] INFO org.apache.spark.executor.Executor [] - Finished task 24.0 in stage 166.0 (TID 1114). 1148 bytes result sent to driver
37039 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 28.0 in stage 166.0 (TID 1118) (192.168.1.190, executor driver, partition 28, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37039 [Executor task launch worker for task 28.0 in stage 166.0 (TID 1118)] INFO org.apache.spark.executor.Executor [] - Running task 28.0 in stage 166.0 (TID 1118)
37039 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 24.0 in stage 166.0 (TID 1114) in 4 ms on 192.168.1.190 (executor driver) (21/54)
37040 [Executor task launch worker for task 27.0 in stage 166.0 (TID 1117)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/8b2806c0-a13e-45a6-a642-40c27deecf64-1_14-56-216_20251225195218434.parquet
37040 [Executor task launch worker for task 26.0 in stage 166.0 (TID 1116)] INFO org.apache.spark.executor.Executor [] - Finished task 26.0 in stage 166.0 (TID 1116). 1148 bytes result sent to driver
37040 [dispatcher-event-loop-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 29.0 in stage 166.0 (TID 1119) (192.168.1.190, executor driver, partition 29, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37041 [task-result-getter-0] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 26.0 in stage 166.0 (TID 1116) in 5 ms on 192.168.1.190 (executor driver) (22/54)
37041 [Executor task launch worker for task 29.0 in stage 166.0 (TID 1119)] INFO org.apache.spark.executor.Executor [] - Running task 29.0 in stage 166.0 (TID 1119)
37041 [Executor task launch worker for task 28.0 in stage 166.0 (TID 1118)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/b3ddc06a-6593-484f-b419-beec46621aa0-0_15-84-399_20251225195229434.parquet
37041 [Executor task launch worker for task 28.0 in stage 166.0 (TID 1118)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/b3ddc06a-6593-484f-b419-beec46621aa0-0_15-84-399_20251225195229434.parquet
37042 [Executor task launch worker for task 29.0 in stage 166.0 (TID 1119)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/b3ddc06a-6593-484f-b419-beec46621aa0-0_15-56-217_20251225195218434.parquet
37043 [Executor task launch worker for task 28.0 in stage 166.0 (TID 1118)] INFO org.apache.spark.executor.Executor [] - Finished task 28.0 in stage 166.0 (TID 1118). 1148 bytes result sent to driver
37044 [dispatcher-event-loop-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 30.0 in stage 166.0 (TID 1120) (192.168.1.190, executor driver, partition 30, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37044 [task-result-getter-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 28.0 in stage 166.0 (TID 1118) in 5 ms on 192.168.1.190 (executor driver) (23/54)
37044 [Executor task launch worker for task 30.0 in stage 166.0 (TID 1120)] INFO org.apache.spark.executor.Executor [] - Running task 30.0 in stage 166.0 (TID 1120)
37045 [Executor task launch worker for task 30.0 in stage 166.0 (TID 1120)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6f8227b9-bfe1-4d3e-b29e-0e9aeb9893a0-1_16-56-218_20251225195218434.parquet
37045 [Executor task launch worker for task 30.0 in stage 166.0 (TID 1120)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6f8227b9-bfe1-4d3e-b29e-0e9aeb9893a0-1_16-56-218_20251225195218434.parquet
37047 [Executor task launch worker for task 30.0 in stage 166.0 (TID 1120)] INFO org.apache.spark.executor.Executor [] - Finished task 30.0 in stage 166.0 (TID 1120). 1148 bytes result sent to driver
37047 [dispatcher-event-loop-6] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 31.0 in stage 166.0 (TID 1121) (192.168.1.190, executor driver, partition 31, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37048 [task-result-getter-3] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 30.0 in stage 166.0 (TID 1120) in 3 ms on 192.168.1.190 (executor driver) (24/54)
37048 [Executor task launch worker for task 31.0 in stage 166.0 (TID 1121)] INFO org.apache.spark.executor.Executor [] - Running task 31.0 in stage 166.0 (TID 1121)
37049 [Executor task launch worker for task 31.0 in stage 166.0 (TID 1121)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6ca91470-0050-4166-9627-4ced97e77b35-1_16-84-400_20251225195229434.parquet
37049 [Executor task launch worker for task 31.0 in stage 166.0 (TID 1121)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Cleaned file at path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6ca91470-0050-4166-9627-4ced97e77b35-1_16-84-400_20251225195229434.parquet
37051 [Executor task launch worker for task 31.0 in stage 166.0 (TID 1121)] INFO org.apache.spark.executor.Executor [] - Finished task 31.0 in stage 166.0 (TID 1121). 1105 bytes result sent to driver
37051 [dispatcher-event-loop-2] INFO org.apache.spark.scheduler.TaskSetManager [] - Starting task 32.0 in stage 166.0 (TID 1122) (192.168.1.190, executor driver, partition 32, PROCESS_LOCAL, 4605 bytes) taskResourceAssignments Map()
37051 [task-result-getter-1] INFO org.apache.spark.scheduler.TaskSetManager [] - Finished task 31.0 in stage 166.0 (TID 1121) in 4 ms on 192.168.1.190 (executor driver) (25/54)
37051 [Executor task launch worker for task 32.0 in stage 166.0 (TID 1122)] INFO org.apache.spark.executor.Executor [] - Running task 32.0 in stage 166.0 (TID 1122)
37052 [Executor task launch worker for task 32.0 in stage 166.0 (TID 1122)] DEBUG org.apache.hudi.table.action.clean.CleanActionExecutor [] - Working on delete path:
file:/var/folders/vh/zgs02hf51dn7r08pbl5m2jc00000gn/T/junit-4455038699931073331/2015/03/16/6ca91470-0050-4166-9627-4ced97e77b35-1_17-56-219_20251225195218434.parquet
```
### Environment
**Hudi version:** 1.2.0-SNAPSHOT (affects all versions with consistency guard)
**Query engine:** (Spark/Flink/Trino etc)
**Relevant configs:** Local filesystem (`file://`) - strongly consistent, Consistency guard enabled via `ConsistencyGuardConfig`
**Observed in**: `CleanActionExecutor.deleteFileAndGetResult()`
### Logs and Stack Trace
_No response_
--
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.
To unsubscribe, e-mail: commits-unsubscribe@hudi.apache.org.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Consistency Guard Causes 25-Second Delays in CleanActionExecutor on Strongly Consistent Filesystems [hudi]
Posted by "voonhous (via GitHub)" <gi...@apache.org>.
voonhous commented on issue #17714:
URL: https://github.com/apache/hudi/issues/17714#issuecomment-3691539207
# Main root cause:
1. MDT is stale, causing files that were cleaned in `CLEAN_PLAN_A` to be candidates for `CLEAN_PLAN_B`.
2. `FILEGROUP_A.ver1` is now candidate in both `CLEAN_PLAN_A` and `CLEAN_PLAN_B`
3. `FILEGROUP_A.ver1` is deleted after `CLEAN_PLAN_A` has completed.
4. When `CLEAN_PLAN_B` executes, `FILEGROUP_A.ver1` will be deleted again, but it does not exist
# Interplay with consistency guard
1. Assuming we are running the test with **consistency guard = true**, i.e. we are running in an eventually consistent file system
2. Before deletion, `storage.getPathInfo(deletePath).isDirectory()` to check if the path is a directory before deleting
3. This triggers `HoodieHadoopStorage.getPathInfo()` -> `FileSystem.getFileStatus()` -> `HoodieWrapperFileSystem.getFileStatus()`
4. `HoodieWrapperFileSystem.getFileStatus()` calls `consistencyGuard.waitTillFileAppears(f)`
5. File is deleted, so it keeps waiting with exponential backoff of **200ms** with 6 retries up to a maximum of **12,800ms,** cumulatively waiting a total of **25,200ms**
6. After the exponential backoff, the assumption is made that the system is now consistent, there's high confidence that the file is indeed deleted, instead of "in the midst of being propagated"
7. File has been deleted, end.
# Verification
I augmented the test to disable MDT and the run times were similar of disabling consistency guard of around 40 seconds.
# Final thoughts
This is definitely not a problem with consistency guard as we are being very very conservative, enforcing an exponential backoff during WRITEs and also READs to remove any chance of false positives.
e.g. File has been deleted in previous clean, but job doesn't know about this. Since, file may not be propagated or it has been deleted, Hudi takes the conservative route to wait out the exponential back off, rather than eagerly delete the file. This is the correct tradeoff as i feel waiting a 25 seconds is much much better than having an orphaned data file, silently corrupting the table.
# Fixing this test
We can speed up the test by:
1. Disabling MDT
2. Disabling consistency guard (I am more inclined to choose this as S3 has since been strongly consistent, and has been for awhile, which the config was introduced to guard against)
# Final thoughts
1. Is MDT being out of sync acceptable in such scenarios?
2. While it doesn't cause any silent data corruptions (SDC) in our test case here, have we verified that this will not cause SDC in other edge cases?
--
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.
To unsubscribe, e-mail: commits-unsubscribe@hudi.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Consistency Guard Causes 25-Second Delays in CleanActionExecutor on Strongly Consistent Filesystems [hudi]
Posted by "voonhous (via GitHub)" <gi...@apache.org>.
voonhous commented on issue #17714:
URL: https://github.com/apache/hudi/issues/17714#issuecomment-4701910310
## Investigation + CI verification
Root-caused and reproduced on macOS; **verified not reproducible on CI/Linux**.
### Root cause
`CleanActionExecutor.deleteFileAndGetResult` calls `storage.getPathInfo(deletePath)` (to pick file-vs-directory delete), which routes through `HoodieWrapperFileSystem.getFileStatus`:
```java
public FileStatus getFileStatus(Path f) throws IOException {
return executeFuncWithTimeMetrics(MetricName.getFileStatus.name(), f, () -> {
try {
consistencyGuard.waitTillFileAppears(convertToDefaultStoragePath(f)); // full ~25.2s backoff
} catch (TimeoutException e) {
// pass
}
return fileSystem.getFileStatus(convertToDefaultPath(f));
});
}
```
On macOS local `file://`, `waitTillFileAppears` checks `convertToDefaultStoragePath(f)`, never sees the file, and runs the full exponential backoff (`0.4 + 0.8 + 1.6 + 3.2 + 6.4 + 12.8 = ~25.2s`) per deleted file before swallowing the `TimeoutException` (`// pass`). The file is still deleted correctly - it is purely wasted wall-clock.
### Local (macOS) reproduction
- Full `TestCleanerInsertAndCleanByVersions` (4 methods): ~12 min, ~183 tasks each stalling ~25.2s.
- A single method (`testInsertAndCleanByVersions`): ~1 min, ~6 stalls.
- JDK 11 and JDK 17 are identical (the backoff is `Thread.sleep`, JDK-independent); the per-method count just scales with how many files the method cleans.
### CI/Linux: not reproducible (verified)
A run with verbose logging (`-Pwarn-log` dropped, `-Dsurefire.useFile=false`, so per-task timings are visible):
- 7,109 `Finished task ... in N ms` lines emitted (logging confirmed working) and 1,454 cleaner/delete lines (the delete path was genuinely exercised).
- Tasks at ~25s: **0**. Tasks at 10s+: **0**. **Slowest task: 2.87s.** Class finished in ~84-120s.
So on CI's Linux filesystem the path resolves immediately and the backoff never fires.
### Conclusion
This is specific to **macOS local `file://` path translation**, not a general code defect, and is invisible on CI. The gotcha is now documented inline next to `withConsistencyCheckEnabled(true)` in the test so the next person hitting a slow local run knows why.
--
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.
To unsubscribe, e-mail: commits-unsubscribe@hudi.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [I] Consistency Guard Causes 25-Second Delays in CleanActionExecutor on Strongly Consistent Filesystems [hudi]
Posted by "voonhous (via GitHub)" <gi...@apache.org>.
voonhous closed issue #17714: Consistency Guard Causes 25-Second Delays in CleanActionExecutor on Strongly Consistent Filesystems
URL: https://github.com/apache/hudi/issues/17714
--
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.
To unsubscribe, e-mail: commits-unsubscribe@hudi.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org