progress eta is very wrong

[aatifsyed]

Our ETA was 8m, but the actual elapsed was 35m.

We shouldn't provide an ETA in this case, it's the opposite of helpful.

Is this because our length isn't known? Or do we take much more time to process later entries than earlier entries?

# FOREST_KEYSTORE_PHRASE="" ./forest-rustalloc --no-gc --import-snapshot forest_snapshot_mainnet_2023-07-11_height_3026477.car.zst --height=-10000 --halt-after-import
2023-07-12T17:20:38.556413Z  INFO forest_filecoin::daemon::main: Using default mainnet config
...
2023-07-12T17:20:40.138738Z  INFO forest_filecoin::utils::net: Downloading file: https://github.com/filecoin-project/builtin-actors/releases/download/v11.0.0/builtin-actors-mainnet.car
2023-07-12T17:20:40.728769Z  INFO forest_filecoin::daemon::bundle: Loaded actors bundle with CID: bafy2bzaceb6j6666h36xnhksu3ww4kxb6e25niayfgkdnifaqi6m6ooc66i6i
...
2023-07-12T17:20:40.796208Z  INFO forest_filecoin::genesis: Importing chain from snapshot at: forest_snapshot_mainnet_2023-07-11_height_3026477.car.zst
2023-07-12T17:20:40.796242Z  INFO forest_filecoin::utils::net: Reading file: forest_snapshot_mainnet_2023-07-11_height_3026477.car.zst
2023-07-12T17:20:40.797923Z  INFO forest_filecoin::rpc: Ready for RPC connections
2023-07-12T17:20:45.797206Z  INFO forest::progress: Loading 549027840 (elapsed: 5s, eta: 8m 8s)
...
2023-07-12T17:21:40.798182Z  INFO forest::progress: Loading 4407803904 (elapsed: 1m, eta: 11m 17s)
...
2023-07-12T17:22:40.804105Z  INFO forest::progress: Loading 8215158784 (elapsed: 2m, eta: 11m 11s)
...
2023-07-12T17:23:40.873091Z  INFO forest::progress: Loading 12295192576 (elapsed: 3m, eta: 10m 13s)
...
2023-07-12T17:24:40.893787Z  INFO forest::progress: Loading 16441917440 (elapsed: 4m, eta: 9m 11s)
...
2023-07-12T17:25:40.895755Z  INFO forest::progress: Loading 20574224384 (elapsed: 5m, eta: 8m 10s)
...
2023-07-12T17:26:44.056856Z  INFO forest::progress: Loading 23229718528 (elapsed: 6m 3s, eta: 8m 4s)
...
2023-07-12T17:27:44.100128Z  INFO forest::progress: Loading 27141562368 (elapsed: 7m 3s, eta: 7m 1s)
...
2023-07-12T17:28:44.110286Z  INFO forest::progress: Loading 31023841280 (elapsed: 8m 3s, eta: 6m 1s)
...
2023-07-12T17:29:44.137701Z  INFO forest::progress: Loading 35018358784 (elapsed: 9m 3s, eta: 4m 57s)
2023-07-12T17:29:49.137883Z  INFO forest::progress: Loading 35375341568 (elapsed: 9m 8s, eta: 4m 51s)
2023-07-12T17:29:52.893017Z  INFO parity-db: Started reindex for i00-20
...
2023-07-12T17:30:44.164707Z  INFO forest::progress: Loading 38057787392 (elapsed: 10m 3s, eta: 4m 15s)
...
2023-07-12T17:31:32.543153Z  INFO parity-db: Completed reindex i00-20 into i00-21
2023-07-12T17:31:34.243658Z  INFO forest::progress: Loading 38761250816 (elapsed: 10m 53s, eta: 4m 20s)
2023-07-12T17:31:39.250429Z  INFO forest::progress: Loading 38812106752 (elapsed: 10m 58s, eta: 4m 21s)
2023-07-12T17:31:44.270700Z  INFO forest::progress: Loading 38862176256 (elapsed: 11m 3s, eta: 4m 21s)
...
2023-07-12T17:32:44.417512Z  INFO forest::progress: Loading 39482851328 (elapsed: 12m 3s, eta: 4m 29s)
...
2023-07-12T17:33:44.531399Z  INFO forest::progress: Loading 40115224576 (elapsed: 13m 3s, eta: 4m 35s)
...
2023-07-12T17:34:44.708245Z  INFO forest::progress: Loading 40739389440 (elapsed: 14m 3s, eta: 4m 38s)
...
2023-07-12T17:35:44.848140Z  INFO forest::progress: Loading 41342468096 (elapsed: 15m 4s, eta: 4m 41s)
...
2023-07-12T17:36:44.997339Z  INFO forest::progress: Loading 41945251840 (elapsed: 16m 4s, eta: 4m 41s)
...
2023-07-12T17:37:45.296906Z  INFO forest::progress: Loading 42551590912 (elapsed: 17m 4s, eta: 4m 40s)
...
2023-07-12T17:38:45.417383Z  INFO forest::progress: Loading 43175624704 (elapsed: 18m 4s, eta: 4m 36s)
...
2023-07-12T17:39:45.530865Z  INFO forest::progress: Loading 43794153472 (elapsed: 19m 4s, eta: 4m 31s)
...
2023-07-12T17:40:45.637894Z  INFO forest::progress: Loading 44394201088 (elapsed: 20m 4s, eta: 4m 26s)
...
2023-07-12T17:41:45.746587Z  INFO forest::progress: Loading 45020151808 (elapsed: 21m 4s, eta: 4m 17s)
...
2023-07-12T17:42:40.835537Z  INFO forest::progress: Loading 45576470528 (elapsed: 22m, eta: 4m 9s)
...
2023-07-12T17:43:40.987946Z  INFO forest::progress: Loading 46193557504 (elapsed: 23m, eta: 3m 59s)
...
2023-07-12T17:44:41.126058Z  INFO forest::progress: Loading 46797799424 (elapsed: 24m, eta: 3m 47s)
...
2023-07-12T17:45:41.303884Z  INFO forest::progress: Loading 47407415296 (elapsed: 25m, eta: 3m 34s)
...
2023-07-12T17:46:41.446483Z  INFO forest::progress: Loading 48016506880 (elapsed: 26m, eta: 3m 20s)
...
2023-07-12T17:47:41.549214Z  INFO forest::progress: Loading 48660856832 (elapsed: 27m, eta: 3m 4s)
...
2023-07-12T17:48:41.649944Z  INFO forest::progress: Loading 49279516672 (elapsed: 28m, eta: 2m 47s)
...
2023-07-12T17:49:41.790760Z  INFO forest::progress: Loading 49894768640 (elapsed: 29m, eta: 2m 30s)
...
2023-07-12T17:50:41.956789Z  INFO forest::progress: Loading 50517360640 (elapsed: 30m 1s, eta: 2m 11s)
...
2023-07-12T17:51:42.071401Z  INFO forest::progress: Loading 51145457664 (elapsed: 31m 1s, eta: 1m 51s)
...
2023-07-12T17:52:42.241924Z  INFO forest::progress: Loading 51786792960 (elapsed: 32m 1s, eta: 1m 29s)
...
2023-07-12T17:53:42.319437Z  INFO forest::progress: Loading 52469284864 (elapsed: 33m 1s, eta: 1m 5s)
...
2023-07-12T17:54:42.408098Z  INFO forest::progress: Loading 53206040576 (elapsed: 34m 1s, eta: 38s)
...
2023-07-12T17:55:42.591633Z  INFO forest::progress: Loading 53911470080 (elapsed: 35m 1s, eta: 11s)
2023-07-12T17:55:47.598976Z  INFO forest::progress: Loading 53969272832 (elapsed: 35m 6s, eta: 8s)
2023-07-12T17:55:52.599017Z  INFO forest::progress: Loading 54025510912 (elapsed: 35m 11s, eta: 6s)
2023-07-12T17:55:57.617438Z  INFO forest::progress: Loading 54081601536 (elapsed: 35m 16s, eta: 4s)
2023-07-12T17:56:02.637536Z  INFO forest::progress: Loading 54137831424 (elapsed: 35m 21s, eta: 2s)
2023-07-12T17:56:07.644014Z  INFO forest::progress: Loading 54195503104 (elapsed: 35m 26s, eta: 0s)
2023-07-12T17:56:07.972288Z  INFO forest_filecoin::genesis: Loaded 57544880 records from .car file in 2127s

[aatifsyed]

cc @elmattic

[LesnyRumcajs]

It's likely because the DB write speed is negatively correlated with the number of entries in the DB, from what I've noticed. I'm okay with disabling it altogether. Maybe we could contrive a smarter estimator, but I don't think it's worth it.

That being said, I don't understand why this happens; I would assume the DB would use, e.g., a merge tree or something similar underneath to not slow down. That is another topic, though.

[elmattic]

@aatifsyed the way we compute the ETA is really simple, to compute the throughput a mean of the number of items processed over time is done.
Maybe using a moving average could be better when performances are getting slower and slower, like in this case.

[LesnyRumcajs]

A moving average would bring it closer to reality but still inaccurate. If we would want to be precise, we would need to calculate the slope of the download speed function, which may not be linear and may change on any ParityDb update. It's overkill.

[lemmih]

A moving average would bring it closer to reality but still inaccurate. If we would want to be precise, we would need to calculate the slope of the download speed function, which may not be linear and may change on any ParityDb update. It's overkill.

Or train a NN to predict the completion time. We could finally become an AI project. DeepForest - 8B parameters to predict snapshot import times.