Cardano db sync takes extremely long to revert a fork block

[xdzurman]

It takes db-sync more than 3 minutes to revert a fork block, here are db sync's logs:

[db-sync-node:Info:96] [2021-01-22 09:20:35.58 UTC] insertShelleyBlock(Allegra): epoch 243, slot 19740942, block 5242014, hash 649d3a63e41d94003b6d6a1d43325d99b2017042536b48a7dcdf3fb2e66d0f56
[db-sync-node:Info:96] [2021-01-22 09:21:15.68 UTC] insertShelleyBlock(Allegra): epoch 243, slot 19740984, block 5242015, hash 8b601c5e732ee1b0746f21503a4f4741ac072abd920dc2248404d2d5e772e81a
[db-sync-node:Info:96] [2021-01-22 09:21:19.89 UTC] Rolling back to slot 19740942, hash 649d3a63e41d94003b6d6a1d43325d99b2017042536b48a7dcdf3fb2e66d0f56
[db-sync-node:Info:96] [2021-01-22 09:21:19.89 UTC] Deleting slots numbered: [19740984]
[db-sync-node:Info:96] [2021-01-22 09:24:40.42 UTC] insertShelleyBlock(Allegra): epoch 243, slot 19740984, block 5242015, hash 95687df531f8098a0a6aa8d995cb10abcae8e03263157c7bf69298b142a9ff72

On the other hand, cardano node recovers almost instantly:

[af752952:cardano.node.ChainDB:Notice:310] [2021-01-22 09:21:15.36 UTC] Chain extended, new tip: 8b601c5e732ee1b0746f21503a4f4741ac072abd920dc2248404d2d5e772e81a at slot 19740984
[af752952:cardano.node.Mempool:Info:318] [2021-01-22 09:21:15.38 UTC] fromList [("kind",String "TraceMempoolRemoveTxs"),("mempoolSize",Object (fromList [("numTxs",Number 0.0),("bytes",Number 0.0)])),("txs",Array [Object (fromList [("txid",String "txid: TxId {_unTxId = \"bb954b78d19a76a30296275c91dca434b1e10dc6f5bde883ac30f7f85d0fe8d7\"}")]),Object (fromList [("txid",String "txid: TxId {_unTxId = \"ac27e19e84df3207be35ac40855f10b7b7189ba847fefe990e4d6fb16377f1e4\"}")]),Object (fromList [("txid",String "txid: TxId {_unTxId = \"b7068bc1ffcab956c1330cedb1cdc91d00d0ba7de8e800e3b27b2f889e33ebf9\"}")]),Object (fromList [("txid",String "txid: TxId {_unTxId = \"cd7afed7b8a800cdaf6021a151190338f01984570fcda7d4d99b0412a153366c\"}")]),Object (fromList [("txid",String "txid: TxId {_unTxId = \"657968defcc7407b1d39559cce6aecca6f7f33cff1c457519e8c3b8697c5a7f6\"}")]),Object (fromList [("txid",String "txid: TxId {_unTxId = \"844883270d7ab2da8b6cc3874584257567b254bdab03d3b7124199006f05bc5f\"}")])])]
[af752952:cardano.node.ChainDB:Info:310] [2021-01-22 09:21:15.38 UTC] Block fits onto some fork: 95687df531f8098a0a6aa8d995cb10abcae8e03263157c7bf69298b142a9ff72 at slot 19740984
[af752952:cardano.node.ChainDB:Info:310] [2021-01-22 09:21:15.38 UTC] Valid candidate 95687df531f8098a0a6aa8d995cb10abcae8e03263157c7bf69298b142a9ff72 at slot 19740984
[af752952:cardano.node.ChainDB:Notice:310] [2021-01-22 09:21:15.65 UTC] Switched to a fork, new tip: 95687df531f8098a0a6aa8d995cb10abcae8e03263157c7bf69298b142a9ff72 at slot 19740984
[af752952:cardano.node:Info:154672] [2021-01-22 09:21:19.33 UTC] fromList [("time(ps)",Number 3.629532492654353e18),("kind",String "MeasureTxsTimeStart"),("mempoolNumBytes",Number 288.0),("mempoolNumTxs",Number 1.0)]
[af752952:cardano.node.Mempool:Info:154672] [2021-01-22 09:21:19.33 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"8ca37de36f49b9d19955f5111827ec0ef7a4ca3f8259d27d95b7671415ce072e\"}")])),("kind",String "TraceMempoolAddedTx"),("mempoolSize",Object (fromList [("numTxs",Number 1.0),("bytes",Number 288.0)]))]
[af752952:cardano.node.Mempool:Info:333687] [2021-01-22 09:21:19.33 UTC] fromList [("tx",Object (fromList [("txid",String "txid: TxId {_unTxId = \"8ca37de36f49b9d19955f5111827ec0ef7a4ca3f8259d27d95b7671415ce072e\"}")])),("kind",String "TraceMempoolRejectedTx"),("mempoolSize",Object (fromList [("numTxs",Number 1.0),("bytes",Number 288.0)])),("err",Object (fromList [("kind",String "BadInputsUTxO"),("error",String "The transaction contains inputs that do not exist in the UTxO set."),("consumed",Number 0.0),("badInputs",Array [Array [String "657968defcc7407b1d39559cce6aecca6f7f33cff1c457519e8c3b8697c5a7f6",Number 23.0]]),("produced",Number 4.9999e10)]))]
[af752952:cardano.node.ChainDB:Notice:310] [2021-01-22 09:21:20.28 UTC] Chain extended, new tip: 930451bb268a5b6933494d8c97f11a32fbbe47d5bc419a58076243e61fb028f9 at slot 19740988
[af752952:cardano.node.ChainDB:Notice:310] [2021-01-22 09:21:24.71 UTC] Chain extended, new tip: 2635bbc5da85ca331437492d1a59d438818fb0b679d459964e46eb5a866df372 at slot 19740993
[af752952:cardano.node.Mempool:Info:318] [2021-01-22 09:21:24.71 UTC] fromList [("kind",String "TraceMempoolRemoveTxs"),("mempoolSize",Object (fromList [("numTxs",Number 0.0),("bytes",Number 0.0)])),("txs",Array [Object (fromList [("txid",String "txid: TxId {_unTxId = \"8ca37de36f49b9d19955f5111827ec0ef7a4ca3f8259d27d95b7671415ce072e\"}")])])]

This has been happening for around 2 weeks, increasing in intensity.

[erikd]

The upcoming 8.0.0 release (should be released early next week) has vastly improved rollbacks (rollbacks as done in PostgreSQL without any Haskell doing any processing). I have seen it roll back from chain tip, right back to the Byron era (over a year of blocks) in under 10 minutes.

That said, db-sync rollbacks are always going to be slower than node rollbacks.

[erikd]

Here is a rollback with the current improved rolbacks:

[db-sync-node:Info:50] [2021-01-23 09:49:22.66 UTC] Rolling back to slot 19829014, hash 1369c36907c449da8232ee746da9a392feeb0ad114db8ff565981922e54735c9
[db-sync-node:Info:50] [2021-01-23 09:49:22.66 UTC] Deleting slots numbered: [19829066]
[db-sync-node:Info:50] [2021-01-23 09:49:22.68 UTC] Slots deleted

So according to the logs, the rollback happened in less than a second.

[erikd]

This is fixed in the 8.0.0 release (probably today).