Slow synchronisation of Chain Index

Jeyhey commented 2 years ago

Summary

I am trying to synchronize Plutus Chain Index for the public testnet since about a month. I made it to 93% but observed that it got slower and slower, pausing for 1 to 4 hours after around each 0.1% progress.

The April 6th update of Plutus Chain Index promised some optimisations and speed increase. According to https://github.com/input-output-hk/plutus-apps/issues/249#issuecomment-1094260950 the synchronization should take about one day.

In a first attempt, I used my existing DB, resuming from the 93% progress state. I did not notice any speed increases.

In a second attempt, I started the synchronization completely from start. I started two days ago and am now standing at 77.20% with a DB size of around 1.5 GB. This chart shows the progress:

The progress looks roughly logarithmic to me. Even optimistically assuming a linear development at the right end of the curve, I need 2.5 days more. And this is on testnet. On mainnet I don't see how I can achieve full synchronization in meaningful time at all.

Update from 28th of Apr: After almost on week since sync start, the progress stands at 84% with a DB size of 4.28 GB. And it does not look like it is going to finish soon.

Steps to reproduce the behavior

Start Cardano Node
Start Chain Index
Observe Chain Index Progress

Actual Result

Slow synchronization

Expected Result

Synchronization in about a day as indicated here: https://github.com/input-output-hk/plutus-apps/issues/249#issuecomment-1094260950

Describe the approach you would take to fix this

No response

System info

Plutus App version 03ba6b7e8b9371adf352ffd53df8170633b6dffa (tag of April 6th 2022)
Cardano Node version 1.34.1
MacBook Pro 2018 with 16 GB Ram (2.3 GHz Quad-Core Intel Core i5; 16 GB 2133 MHz LPDDR3); Using an external SDD for DBs of Cardano Node and Chain Index; (CPU, memory and disk usage far below max capacities)

waalge commented 2 years ago

@Jeyhey . My computer fell over. Had to re-run the chain sync from scratch. I don't have a pretty graph like yours, but I can say it took <24hours (probably 12 but i wasn't watching). Moderate hardware. plutus-apps : fdb0eec477fc0f99f5edfdbc11c041dbd35ca6bb

Jeyhey commented 2 years ago

@waalge Very strange. Could you share some logs? How large is your chain index DB after syncing?

Here are some of my most recent logs:

[chain-index:Info:120] [2022-04-30 08:20:48.27 UTC] Syncing (88.92%). Processed 132 blocks, 0 rollbacks in the last 1906s. Current tip is Point(Slot 50627442, BlockId 58abd9001ebfc630ec35a1e028e013cced8b8e436596495506966c46f8d664db) [chain-index:Info:120] [2022-04-30 08:21:34.03 UTC] Syncing (88.92%). Processed 73 blocks, 0 rollbacks in the last 45s. Current tip is Point(Slot 50629949, BlockId ee177fe772d118a1ef3aef7acddc42f162cadfc9c8b390a9861ffd7e73733ad3) [chain-index:Info:120] [2022-04-30 08:22:43.86 UTC] Syncing (88.92%). Processed 34 blocks, 0 rollbacks in the last 69s. Current tip is Point(Slot 50630737, BlockId 0f98ec916724ba2bf20a0857fff85a1a77976f5938057837dcafc02db13bd58d) [chain-index:Info:120] [2022-04-30 08:23:18.53 UTC] Syncing (88.93%). Processed 27 blocks, 0 rollbacks in the last 34s. Current tip is Point(Slot 50631865, BlockId 7fd49cb092c60ca940ef4ca9aec5a5d736aee3e431deeaea9d6fa56bc002a558) [chain-index:Info:120] [2022-04-30 08:27:59.85 UTC] Syncing (88.93%). Processed 154 blocks, 0 rollbacks in the last 281s. Current tip is Point(Slot 50637002, BlockId 58ac069b39707eb466deb3e33e3f5285bbd91071573b7c828d3efbfb96bb5685) [chain-index:Info:120] [2022-04-30 08:30:49.72 UTC] Syncing (88.95%). Processed 227 blocks, 0 rollbacks in the last 169s. Current tip is Point(Slot 50643943, BlockId 850098bc8a972583d20d7a35e2553fb37344229b84b377beb65fba93a716ae98) [chain-index:Info:120] [2022-04-30 08:33:21.69 UTC] Syncing (88.96%). Processed 190 blocks, 0 rollbacks in the last 151s. Current tip is Point(Slot 50649667, BlockId 729d59f76b13bbbd5aadedd086acafa69e3f05bfb6c904314a1599b25eb6f88d) [chain-index:Info:120] [2022-04-30 08:36:09.57 UTC] Syncing (88.97%). Processed 195 blocks, 0 rollbacks in the last 167s. Current tip is Point(Slot 50655796, BlockId 20e4083d9c39f0b9fe4979fbd54092ea3af74e51061aa853d83cda0a3291aae9) [chain-index:Info:120] [2022-04-30 08:38:36.64 UTC] Syncing (88.98%). Processed 197 blocks, 0 rollbacks in the last 147s. Current tip is Point(Slot 50663148, BlockId 7adc88714d76c4ddb9fa41cb1855747bff16abb6965dfda6d16e79630be657fb) [chain-index:Info:120] [2022-04-30 08:42:29.80 UTC] Syncing (88.99%). Processed 219 blocks, 0 rollbacks in the last 233s. Current tip is Point(Slot 50670380, BlockId 13d15a808f5e3a661ca514da2145a9b8e3388c91b85e9eb0bbaa8d9902c876ef) [chain-index:Info:120] [2022-04-30 08:46:31.46 UTC] Syncing (89.00%). Processed 131 blocks, 0 rollbacks in the last 241s. Current tip is Point(Slot 50674285, BlockId 0dae2fc2f1c2df269a846bbdfb3f91b7679a3d4e2d4f36ca8e9b46674d971cb3)

waalge commented 2 years ago

Similar

[chain-index:Error:173] [2022-05-02 02:57:12.58 UTC] ChainIndexError: Insertion failed: UTxO insertion failed - already a block with the given number
[chain-index:Info:173] [2022-05-02 02:57:51.84 UTC] Still in sync. Processed 31 blocks, 1 rollbacks in the last 1034s. Current tip is Point(Slot 57091015, BlockId 220657b6ef31f8111784969f89a73b52755f37465b39794d70b99c584b3af226)
[chain-index:Info:173] [2022-05-02 03:22:51.41 UTC] Still in sync. Processed 46 blocks, 0 rollbacks in the last 1499s. Current tip is Point(Slot 57092554, BlockId 9c083491202bef176842733fcfa239c09e3c3cbc7b202c51fc382b696cc1d6c8)
[chain-index:Info:173] [2022-05-02 03:34:16.43 UTC] Still in sync. Processed 24 blocks, 0 rollbacks in the last 685s. Current tip is Point(Slot 57093239, BlockId 3edd33da69939db85bfc7768f7ec0c1d9ec7a23285a89f72c12c47c92e82d547)
[chain-index:Info:173] [2022-05-02 03:46:05.31 UTC] Still in sync. Processed 11 blocks, 0 rollbacks in the last 708s. Current tip is Point(Slot 57093948, BlockId ee83038d1a5bf7cfda6c9d5a0891daee5b1afdbc822d58eb4c31df51dbe90164)
[chain-index:Info:173] [2022-05-02 03:55:05.75 UTC] Still in sync. Processed 9 blocks, 0 rollbacks in the last 540s. Current tip is Point(Slot 57094488, BlockId e833649b60d119436c7876daaa27c8a284ac1985d6edabdb59eab4cf7c54a897)
[chain-index:Info:173] [2022-05-02 04:14:43.21 UTC] Still in sync. Processed 28 blocks, 0 rollbacks in the last 1177s. Current tip is Point(Slot 57095667, BlockId 3bb179c64e99be836f287df0b7f8d8740194d94011e34e4e2933896ce36f7418)

However, I've just found it was consuming almost all the cpu on the machine. I killed the process and reran but it's yet to print more sync logs or do report anything. I think all is not well with the chain index.

koslambrou commented 2 years ago

Same here: Took less than 24h to sync on testnet for me. However, I set the config option cicAppendTransactionQueueSize to 10000 in order to batch more transactions, so that might explain why it's faster. However, the higher the value, the more memory it uses.

Can you restart the synchronisation with a higher queue size and see if solves your issue?

ross-spencer commented 1 year ago

Same here: Took less than 24h to sync on testnet for me.

Working with preprod it only takes a few hours in general on pretty low performing machines. Mainnet however.... that performs more like the OPs graph... any tips for speeding that up, or performance enhancements incoming would be appreciated.

IntersectMBO / plutus-apps