substreams squashing is slow

[matthewdarwin]

When you run a lot of parallel workers (3000 in this case) and the substream executes fairly quickly (QmYAFz2iRNj41tP8DyAg61X4NoqaAxgf4W4j7Gn1bCtTs7 on arbitrum one in this case), the longest part of the execution time is waiting for the squashing.

All the tier2 jobs finished around 16:52, and the squashing takes until 18:27 to complete.

Does tier1 wait on partial file deletes before squashing next range? if yes, that would slow things down in our environment.
Any way to speed this up?

(leave out the start of the log)
....
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.564Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 262544, "stage": 0}, "number_of_tries": 15, "module_name": ["store_rates_for_last_7_days"], "duration": 160.371042677, "processing_time_per_block": 0.160371042677}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.644Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 262550, "stage": 0}, "number_of_tries": 15, "module_name": ["store_rates_for_last_7_days"], "duration": 160.425898996, "processing_time_per_block": 0.160425898996}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.644Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 261644, "stage": 0}, "number_of_tries": 18, "module_name": ["store_rates_for_last_7_days"], "duration": 183.21294793, "processing_time_per_block": 0.18321294793}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.645Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 263222, "stage": 0}, "number_of_tries": 12, "module_name": ["store_rates_for_last_7_days"], "duration": 142.915947728, "processing_time_per_block": 0.14291594772799998}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.696Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 263184, "stage": 0}, "number_of_tries": 13, "module_name": ["store_rates_for_last_7_days"], "duration": 144.153819327, "processing_time_per_block": 0.144153819327}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.861Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 262331, "stage": 0}, "number_of_tries": 16, "module_name": ["store_rates_for_last_7_days"], "duration": 164.652815812, "processing_time_per_block": 0.164652815812}
Oct 13 16:52:13 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:13.928Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 261638, "stage": 0}, "number_of_tries": 19, "module_name": ["store_rates_for_last_7_days"], "duration": 183.620528755, "processing_time_per_block": 0.183620528755}
Oct 13 16:52:14 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:14.445Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 260814, "stage": 0}, "number_of_tries": 21, "module_name": ["store_rates_for_last_7_days"], "duration": 203.427038603, "processing_time_per_block": 0.203427038603}
Oct 13 16:52:14 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:14.912Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 262400, "stage": 0}, "number_of_tries": 14, "module_name": ["store_rates_for_last_7_days"], "duration": 164.029925533, "processing_time_per_block": 0.164029925533}
Oct 13 16:52:15 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T16:52:15.063Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "2.338082523s", "load_time": "2.334466988s", "merge_time": "54.933µs", "save_time": "3.386207ms", "start_block": 230119000, "end_block": 230120000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
....
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.042Z INFO (substreams-tier1.tier1) deleting partial store {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "store": "partialKV name store_rates_for_last_7_days moduleInitialBlock 204419220  keyCount 3 deltasCount 0 loadFrom 0263381000-0263380000.partial"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.049Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "87.57016ms", "load_time": "80.943899ms", "merge_time": "24.217µs", "save_time": "6.452517ms", "start_block": 263380000, "end_block": 263381000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.063Z INFO (substreams-tier1.tier1) deleting partial store {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "store": "partialKV name store_rates_for_last_7_days moduleInitialBlock 204419220  keyCount 1 deltasCount 0 loadFrom 0263382000-0263381000.partial"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.070Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "19.631222ms", "load_time": "12.591991ms", "merge_time": "30.003µs", "save_time": "6.890635ms", "start_block": 263381000, "end_block": 263382000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.134Z INFO (substreams-tier1.tier1) deleting partial store {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "store": "partialKV name store_rates_for_last_7_days moduleInitialBlock 204419220  keyCount 2 deltasCount 0 loadFrom 0263383000-0263382000.partial"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.141Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "68.516793ms", "load_time": "61.851915ms", "merge_time": "24.524µs", "save_time": "6.530028ms", "start_block": 263382000, "end_block": 263383000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.199Z INFO (substreams-tier1.tier1) deleting partial store {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "store": "partialKV name store_rates_for_last_7_days moduleInitialBlock 204419220  keyCount 1 deltasCount 0 loadFrom 0263384000-0263383000.partial"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.216Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "73.121621ms", "load_time": "55.983691ms", "merge_time": "34.173µs", "save_time": "16.874119ms", "start_block": 263383000, "end_block": 263384000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.306Z INFO (substreams-tier1.tier1) deleting partial store {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "store": "partialKV name store_rates_for_last_7_days moduleInitialBlock 204419220  keyCount 2 deltasCount 0 loadFrom 0263385000-0263384000.partial"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.313Z INFO (substreams-tier1.tier1) squashing time metrics {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "total_time": "95.009651ms", "load_time": "87.886051ms", "merge_time": "25.427µs", "save_time": "6.973472ms", "start_block": 263384000, "end_block": 263385000, "stage": 0, "module_name": "store_rates_for_last_7_days", "module_hash": "a02d979e0d7f4287966e38ad6712933b31d6deba"}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.315Z INFO (substreams-tier1.tier1) scheduler: waiting for output stream to complete, stores ready {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "cached_output_start": 263384, "cached_output_current": 263384, "cached_output_end": 263384}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.322Z INFO (substreams-tier1.tier1) scheduling work {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 263384, "stage": 1}}
Oct 13 18:26:58 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:26:58.329Z INFO (substreams-tier1.tier1) launching remote worker {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "segment": 263384, "stage": 1, "output_module": "graph_out", "attempt": 1, "execution_timeouts": 0}
Oct 13 18:27:49 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:27:49.347Z INFO (substreams-tier1.tier1) job completed {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "unit": {"segment": 263384, "stage": 1}, "number_of_tries": 0, "module_name": ["graph_out"], "duration": 51.018476216, "processing_time_per_block": 0.051018476216}
Oct 13 18:27:49 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:27:49.456Z INFO (substreams-tier1.tier1) scheduler: waiting for output stream to complete, stores ready {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "cached_output_start": 263384, "cached_output_current": 263384, "cached_output_end": 263384}
Oct 13 18:27:54 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:27:54.002Z INFO (substreams-tier1.tier1) scheduler: stores and cached_outputs stream completed, switching to live {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "cached_output_start": 263384, "cached_output_current": 263385, "cached_output_end": 263384}
Oct 13 18:27:54 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:27:54.002Z INFO (substreams-tier1.tier1) stream of blocks ended {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "stop_block_num": 263385000, "eof": true, "stop_block_reached": false}
Oct 13 18:27:54 arbone-sfsf79 sf-nitro[741465]: 2024-10-13T18:27:54.003Z INFO (substreams-tier1.tier1) substreams request stats {"trace_id": "40864bcf0ac166efb35859e3ef45e78b", "user_id": "[2620:7f:e000:2201:8888:8888:3:60]", "api_key_id": "", "output_module_name": "graph_out", "output_module_hash": "03b7f4b581723a62db26db7bfa9464c926d0a9c0", "production_mode": true, "tier": "tier1", "block_rate_per_sec": "0.000", "block_count": 0, "parallel_duration": "1h45m50.03713269s", "module_exec_duration": "0s", "module_wasm_ext_duration": "87h57m48.117s"}