Possible performance regression from redb version 2.1.3 to 2.1.4

[raphjaph]

From ord version 0.20.1 to version 0.21.0 some users have run into problems indexing. I've tested it myself on our dev server and it stopped at block 375000 (doesn't finish the commit), others reported 350000, 430000 and 815000. We update redb from 2.1.3 in ord 0.20.1 to redb 2.1.4 in ord 0.21.0 and we think that might be the culprit.

Here's the tracking issue and the version update commit.

I've now pinned redb to version 2.1.3 here and running the index seems to work again.

[cberner]

Uh oh! I'll take a look. It's been a while since I ran ord, will these steps reproduce the issue?

bitcoind -txindex

cargo run --release -- --data-dir=./ord_db --db-cache-size 2147483648 --height-limit=750000 index run

[raphjaph]

Thanks for looking into it!

This command should do it:

bitcoind -txindex
git checkout 0.21.0
cargo run --release -- --data-dir=./ord_db --db-cache-size 2147483648 --height-limit=850000 index update

You don't have to set the --db-cache-size (it's set to 1/4 of available memory by default) but it might help you debug if it's set. You can also always do ord --help or ord <SUBCOMMAND> --help to see all the config options.

[gmart7t2]

The difference in speed between 2.1.3 and 2.1.4 is enormous. I kept time-stamped logs.

Here are some commit timings from 2.1.3:

$ grep -A1 "Committing at block height 4[0-5]0000," ord20y.log
[2024-09-04T05:39:56Z INFO  ord::index::updater] Committing at block height 400000, 18573429 outputs traversed, 3426924 in map, 253287804 cached
[2024-09-04T05:42:41Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T06:20:51Z INFO  ord::index::updater] Committing at block height 410000, 19342514 outputs traversed, 4226816 in map, 283058763 cached
[2024-09-04T06:24:00Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T07:05:05Z INFO  ord::index::updater] Committing at block height 420000, 19899271 outputs traversed, 4448719 in map, 313875348 cached
[2024-09-04T07:08:41Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T07:49:04Z INFO  ord::index::updater] Committing at block height 430000, 18419984 outputs traversed, 3920730 in map, 343196804 cached
[2024-09-04T07:52:30Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T08:33:27Z INFO  ord::index::updater] Committing at block height 440000, 20551077 outputs traversed, 4534620 in map, 374714183 cached
[2024-09-04T08:37:21Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T09:22:07Z INFO  ord::index::updater] Committing at block height 450000, 21272063 outputs traversed, 4671429 in map, 408995881 cached
[2024-09-04T09:26:33Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/

See how the slowest commit is about 4 minutes.

Here are the same commits, committing the same data in 2.1.4:

$ grep -A1 "Committing at block height 4[0-5]0000," ord21y.log
[2024-10-13T15:29:54Z INFO  ord::index::updater] Committing at block height 400000, 18573429 outputs traversed, 3426924 in map, 253287804 cached
[2024-10-13T19:56:37Z INFO  ord::index::updater] Block 400000 at 2016-02-25 16:24:44 UTC with 1660 transactions…
--
[2024-10-14T01:48:51Z INFO  ord::index::updater] Committing at block height 410000, 19342514 outputs traversed, 4226816 in map, 283058763 cached
[2024-10-14T08:15:59Z INFO  ord::index::updater] Block 410000 at 2016-05-03 07:11:32 UTC with 612 transactions…
--
[2024-10-14T15:37:05Z INFO  ord::index::updater] Committing at block height 420000, 19899271 outputs traversed, 4448719 in map, 313875348 cached
[2024-10-15T01:30:21Z INFO  ord::index::updater] Block 420000 at 2016-07-09 16:46:13 UTC with 1257 transactions…
--
[2024-10-15T12:26:41Z INFO  ord::index::updater] Committing at block height 430000, 18419984 outputs traversed, 3920730 in map, 343196804 cached
[2024-10-15T21:08:33Z INFO  ord::index::updater] Block 430000 at 2016-09-15 23:39:08 UTC with 1772 transactions…
--
[2024-10-16T07:41:46Z INFO  ord::index::updater] Committing at block height 440000, 20551077 outputs traversed, 4534620 in map, 374714183 cached
[2024-10-17T01:43:09Z INFO  ord::index::updater] Block 440000 at 2016-11-22 01:25:04 UTC with 1833 transactions…
--
[2024-10-18T06:09:23Z INFO  ord::index::updater] Committing at block height 450000, 21272063 outputs traversed, 4671429 in map, 408995881 cached
[2024-10-19T15:56:46Z INFO  ord::index::updater] Block 450000 at 2017-01-25 22:11:29 UTC with 2156 transactions…

Here the commits take 4 and 33 hours...

[cberner]

Thanks for the additional info. I'm waiting for my bitcoin node to sync and will test locally. 2.1.4 changed the page caching algorithm to LRU, which is the most likely cause of this issue.

I'm curious, if you stop the ord indexing process and resume it does the speed change at all?

[cberner]

@raphjaph I have a fully sync'ed bitcoin v28.0.0 node running locally now with bitcoind -txindex. But ord fails with this error:

cargo run --release -- --data-dir=./ord_db-2-1-4 --index-cache-size 2147483648 --height-limit=400000 index update
    Finished `release` profile [optimized] target(s) in 0.14s
     Running `target/release/ord --data-dir=./ord_db-2-1-4 --index-cache-size 2147483648 --height-limit=400000 index update`
error: Failed to connect to Bitcoin Core RPC at `127.0.0.1:8332/`:  JSON error: invalid type: sequence, expected a string

Do I need to configure something else?

[raphjaph]

Ah yes, for ord v0.20.1 you will need to use Bitcoin v27.0.0. No need to reindex Bitcoin Core just downgrade the version of the binary. ord v0.21.0 should also work with v27.0.0 (but now also supports v28.0.0).

[cberner]

@gmart7t2 what's the exact ord command you ran? I just ran this:

time cargo run --release -- --data-dir=./ord_db-2-1-4 --index-cache-size 2147483648 --height-limit=450000 index update
    Finished `release` profile [optimized] target(s) in 0.14s
     Running `target/release/ord --data-dir=./ord_db-2-1-4 --index-cache-size 2147483648 --height-limit=450000 index update`

real	1m27.406s
user	0m20.823s
sys	0m17.190s

Which finished in only 1min 27secs

[cberner]

I figured out the issue. There is a bug in 2.1.4 where the read cache is LRU, but the write cache became random eviction. I retested just now with: cargo run --release -- --data-dir=./ord_db --index-cache-size 2147483648 --height-limit=850000 index update and master is about 5% faster than 2.1.3 on my computer.

[cberner]

@raphjaph this is fixed in 2.2.0

[casey]

Nice! Trying it out on our test server now.

[raphjaph]

@raphjaph this is fixed in 2.2.0

Perfect, thanks!

[casey]

Full sync worked, it took 20h as opposed to 21h on 2.1.3, so nice speedup!

[gmart7t2]

@gmart7t2 what's the exact ord command you ran? I just ran this:

time cargo run --release -- --data-dir=./ord_db-2-1-4 --index-cache-size 2147483648 --height-limit=450000 index update

Sorry I didn't see your question until now.

The difference is the --index-sats flag. It needs to be present when the index.redb file is created, and makes the slowness show up earlier due to the increased amount of data in the index.