search

ordinals / ord

👁‍🗨 Rare and exotic sats
https://ordinals.com
Creative Commons Zero v1.0 Universal
3.86k stars 1.38k forks source link

Ord 0.21.0 very slow to index #3999

Closed gmart7t2 closed 1 month ago

gmart7t2 commented 1 month ago

I am building a pair of ord 0.21.0 indexes: 

$ ps -wwwef | grep ord21 | grep -v grep
gm       3114880 3353832 92 Oct12 pts/12   2-07:01:50 /usr/local/bin/ord21 --height-limit 870001 --index-runes --index /home/gm/.local/share/ord/index-0.21-without.redb server --http-port 51021 --csp-origin https://without21.ordstuff.info --decompress
gm       3115151 3353612 90 Oct12 pts/11   2-06:17:16 /usr/local/bin/ord21 --height-limit 870001 --index-runes --index /home/gm/.local/share/ord/index-0.21-with.redb --index-sats --index-addresses server --http-port 50021 --csp-origin https://with21.ordstuff.info --decompress
$ tail -f ord21[yn].log
==> ord21n.log <==
[2024-10-14T22:30:16Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 267 ms
[2024-10-14T22:30:16Z INFO  ord::index::updater] Block 814996 at 2023-11-02 17:55:57 UTC with 3176 transactions…
[2024-10-14T22:30:17Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 788 ms
[2024-10-14T22:30:17Z INFO  ord::index::updater] Block 814997 at 2023-11-02 17:57:34 UTC with 1968 transactions…
[2024-10-14T22:30:18Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 1378 ms
[2024-10-14T22:30:18Z INFO  ord::index::updater] Block 814998 at 2023-11-02 17:57:44 UTC with 1339 transactions…
[2024-10-14T22:30:19Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 389 ms
[2024-10-14T22:30:19Z INFO  ord::index::updater] Block 814999 at 2023-11-02 18:13:12 UTC with 3156 transactions…
[2024-10-14T22:30:19Z INFO  ord::index::updater] Wrote 0 sat ranges from 0 outputs in 196 ms
[2024-10-14T22:30:19Z INFO  ord::index::updater] Committing at block height 815000, 0 outputs traversed, 8166981 in map, 254420874 cached

==> ord21y.log <==
[2024-10-15T12:26:40Z INFO  ord::index::updater] Wrote 195672 sat ranges from 1657 outputs in 17 ms
[2024-10-15T12:26:40Z INFO  ord::index::updater] Block 429996 at 2016-09-15 22:30:07 UTC with 35 transactions…
[2024-10-15T12:26:40Z INFO  ord::index::updater] Wrote 16290 sat ranges from 81 outputs in 1 ms
[2024-10-15T12:26:40Z INFO  ord::index::updater] Block 429997 at 2016-09-15 22:37:13 UTC with 972 transactions…
[2024-10-15T12:26:40Z INFO  ord::index::updater] Wrote 241416 sat ranges from 2039 outputs in 31 ms
[2024-10-15T12:26:40Z INFO  ord::index::updater] Block 429998 at 2016-09-15 23:19:45 UTC with 1485 transactions…
[2024-10-15T12:26:40Z INFO  ord::index::updater] Wrote 1759050 sat ranges from 3228 outputs in 90 ms
[2024-10-15T12:26:41Z INFO  ord::index::updater] Block 429999 at 2016-09-15 23:21:13 UTC with 609 transactions…
[2024-10-15T12:26:41Z INFO  ord::index::updater] Wrote 323202 sat ranges from 1190 outputs in 138 ms
[2024-10-15T12:26:41Z INFO  ord::index::updater] Committing at block height 430000, 18419984 outputs traversed, 3920730 in map, 343196804 cached

Note the 'no sats' index started doing a commit at 10:30pm yesterday and now it's 2:40pm. That's over 16 hours for a commit. I've not seen a commit take more than 2 hours before.

The index files are both currently 25G:

$ ls -lh index-0.21-with*
-rw-r--r-- 1 gm gm 25G Oct 15 07:49 index-0.21-with.redb
-rw-r--r-- 1 gm gm 25G Oct 15 07:49 index-0.21-without.redb
$ df .
Filesystem      Size  Used Avail Use% Mounted on
/dev/sda1       1.8T  1.3T  570G  69% /home
gmart7t2 commented 1 month ago

This is likely caused by the fractal ord server I am running on the same server. Fractal sees frequent reorgs which triggers a lot of disk I/O to restore from the snapshot.

I'll shut down the fractal ord server and see if that fixes the problem.

so7ow commented 1 month ago

I was also running a couple scratch indexes on 0.21.0. (1 was sats/runes/addresses and the other was runes/addresses.) After running overnight, this morning both of them were stopped while committing at block 350000. I watched them both stay there for a couple hours, then pressed ctrl-c and watched them attempt to stop for a couple hours before killing them. Seems like something's up here!

so7ow commented 1 month ago

This is likely caused by the fractal ord server I am running on the same server.

No fractal running on mine, although I did just update Bitcoin core to v28.

somethingbeta commented 1 month ago

I got past 350000 by setting commit-interval to 10. currently near 412000. This is an index build from scratch - with-address/runes windows machine commit interval 10 .. bitcoin 26.1

so7ow commented 1 month ago

I enabled logging and restarted from scratch again, with the default commit interval. I'm in the 300000s now and it's starting to get pretty slow committing to disk.

My sats/runes/addresses run has been working on committing at 305000 for over 30 mins now.

so7ow commented 1 month ago

I got past 350000 by setting commit-interval to 10. currently near 412000. This is an index build from scratch - with-address/runes windows machine commit interval 10 .. bitcoin 26.1

I restarted from scratch again, this time with --commit-interval 20 and I've gotten farther in a couple hours than I got overnight with the default setting. Something sure seems off here!

cryptoni9n commented 1 month ago

this may be related to #3804

so7ow commented 1 month ago

this may be related to #3804

Perhaps it's related but it's new set of symptoms, for me anyway. My system that has been able to crank out a runes/addresses index in 12 hours on 0.20.0 with default 5000 commit interval was stuck at block 350000 overnight on 0.21.0, and even with commit-interval 20 is taking way too long. I'm coming up on a full day and I'm only to block 640000 or so for a runes/addresses/no-sats index.

raphjaph commented 1 month ago

We didn't change any indexing logic from 0.20.1 to 0.21.0 so this is weird. Let me try to reindex on our dev server as well.

ep150de commented 1 month ago

I get the same noticeable slowness tooSent via the Samsung Galaxy Note20 Ultra 5G, an AT&T 5G smartphone -------- Original message --------From: raph @.> Date: 10/16/24 15:00 (GMT-08:00) To: ordinals/ord @.> Cc: Subscribed @.***> Subject: Re: [ordinals/ord] Ord 0.21.0 very slow to index (Issue #3999) We didn't change any indexing logic from 0.20.1 to 0.21.0 so this is weird. Let me try to reindex on our dev server as well.

—Reply to this email directly, view it on GitHub, or unsubscribe.You are receiving this because you are subscribed to this thread.Message ID: @.***>

gus4rs commented 1 month ago

We didn't change any indexing logic from 0.20.1 to 0.21.0

The change was likely done before as nobody re-indexed when 0.20.1 was release because the DB schema version wasn't bumped

Suggestion: setup a nightly representative performance test and plot the results. Take a look for e.g. at https://github.com/sharkdp/hyperfine

so7ow commented 1 month ago

nobody re-indexed when 0.20.1 was release because the DB schema version wasn't bumped

I actually did reindex with 0.20.1 due to the issue with address indexes crashing, and I didn't see this performance issue in that version.

gus4rs commented 1 month ago

nobody re-indexed when 0.20.1 was release because the DB schema version wasn't bumped

I actually did reindex with 0.20.1 due to the issue with address indexes crashing, and I didn't see this performance issue in that version.

Did you do a --index-transactions --index-addresses --index-sats --index-runes ?

so7ow commented 1 month ago

Did you do a --index-transactions --index-addresses --index-sats --index-runes ?

No, just addresses/runes. Same as I'm doing on 21, which has been running for days now. (Used to finish in ~12 hours.)

raphjaph commented 1 month ago

I think I've pinned it down to a regression in redb from version 2.1.3 to 2.1.4. I'm going to test this now and if it fixes it then merge #4003 and make a release.

This version update was done in this commit if you have a look at Cargo.lock.

gmart7t2 commented 1 month ago

4003 appears to have fixed this. Here are some logs showing how the problem happened in 0.21.0 and is resolved again now.

The commits around block heights in the 300k's usually take about 2 minutes but around block 380k they really slow down with redb 2.1.4:

0.20.0 (redb 2.1.3):

[2024-09-04T03:19:48Z INFO  ord::index::updater] Committing at block height 360000, 11172684 outputs traversed, 2360683 in map, 157960852 cached
[2024-09-04T03:21:21Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T03:34:30Z INFO  ord::index::updater] Committing at block height 365000, 17612917 outputs traversed, 6922760 in map, 168651009 cached
[2024-09-04T03:38:08Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T03:51:57Z INFO  ord::index::updater] Committing at block height 370000, 20981144 outputs traversed, 11364884 in map, 178267269 cached
[2024-09-04T03:57:54Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T04:10:58Z INFO  ord::index::updater] Committing at block height 375000, 13811201 outputs traversed, 2783198 in map, 189295273 cached
[2024-09-04T04:13:02Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T04:26:21Z INFO  ord::index::updater] Committing at block height 380000, 12709322 outputs traversed, 2392814 in map, 199611781 cached
[2024-09-04T04:28:24Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T04:42:08Z INFO  ord::index::updater] Committing at block height 385000, 14356358 outputs traversed, 2591878 in map, 211376261 cached
[2024-09-04T04:44:10Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T04:59:38Z INFO  ord::index::updater] Committing at block height 390000, 16311086 outputs traversed, 2904846 in map, 224782501 cached
[2024-09-04T05:01:50Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T05:20:05Z INFO  ord::index::updater] Committing at block height 395000, 16345239 outputs traversed, 2986441 in map, 238141299 cached
[2024-09-04T05:22:29Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/

0.21.0 (redb 2.1.4):

[2024-10-13T07:42:56Z INFO  ord::index::updater] Committing at block height 360000, 11172684 outputs traversed, 2360683 in map, 157960852 cached
[2024-10-13T07:44:30Z INFO  ord::index::updater] Block 360000 at 2015-06-08 14:08:27 UTC with 1223 transactions…
--
[2024-10-13T07:57:06Z INFO  ord::index::updater] Committing at block height 365000, 17612917 outputs traversed, 6922760 in map, 168651009 cached
[2024-10-13T08:00:54Z INFO  ord::index::updater] Block 365000 at 2015-07-12 13:20:07 UTC with 1786 transactions…
--
[2024-10-13T08:14:32Z INFO  ord::index::updater] Committing at block height 370000, 20981144 outputs traversed, 11364884 in map, 178267269 cached
[2024-10-13T09:24:13Z INFO  ord::index::updater] Block 370000 at 2015-08-15 18:12:49 UTC with 1434 transactions…
--
[2024-10-13T09:36:32Z INFO  ord::index::updater] Committing at block height 375000, 13811201 outputs traversed, 2783198 in map, 189295273 cached
[2024-10-13T09:38:19Z INFO  ord::index::updater] Block 375000 at 2015-09-18 00:17:59 UTC with 294 transactions…
--
[2024-10-13T09:50:30Z INFO  ord::index::updater] Committing at block height 380000, 12709322 outputs traversed, 2392814 in map, 199611781 cached
[2024-10-13T10:31:30Z INFO  ord::index::updater] Block 380000 at 2015-10-22 06:08:01 UTC with 687 transactions…
--
[2024-10-13T10:45:24Z INFO  ord::index::updater] Committing at block height 385000, 14356358 outputs traversed, 2591878 in map, 211376261 cached
[2024-10-13T11:47:48Z INFO  ord::index::updater] Block 385000 at 2015-11-23 18:03:21 UTC with 1969 transactions…
--
[2024-10-13T12:02:11Z INFO  ord::index::updater] Committing at block height 390000, 16311086 outputs traversed, 2904846 in map, 224782501 cached
[2024-10-13T13:07:59Z INFO  ord::index::updater] Block 390000 at 2015-12-24 17:33:51 UTC with 854 transactions…
--
[2024-10-13T13:23:17Z INFO  ord::index::updater] Committing at block height 395000, 16345239 outputs traversed, 2986441 in map, 238141299 cached
[2024-10-13T15:13:56Z INFO  ord::index::updater] Block 395000 at 2016-01-25 16:06:26 UTC with 2832 transactions…

origin/master (redb 2.1.3):

[2024-10-20T03:54:01Z INFO  ord::index::updater] Committing at block height 360000, 11172684 outputs traversed, 2360683 in map, 157960852 cached
[2024-10-20T03:55:40Z INFO  ord::index::updater] Block 360000 at 2015-06-08 14:08:27 UTC with 1223 transactions…
--
[2024-10-20T04:08:15Z INFO  ord::index::updater] Committing at block height 365000, 17612917 outputs traversed, 6922760 in map, 168651009 cached
[2024-10-20T04:12:22Z INFO  ord::index::updater] Block 365000 at 2015-07-12 13:20:07 UTC with 1786 transactions…
--
[2024-10-20T04:26:03Z INFO  ord::index::updater] Committing at block height 370000, 20981144 outputs traversed, 11364884 in map, 178267269 cached
[2024-10-20T04:32:21Z INFO  ord::index::updater] Block 370000 at 2015-08-15 18:12:49 UTC with 1434 transactions…
--
[2024-10-20T04:44:41Z INFO  ord::index::updater] Committing at block height 375000, 13811201 outputs traversed, 2783198 in map, 189295273 cached
[2024-10-20T04:46:48Z INFO  ord::index::updater] Block 375000 at 2015-09-18 00:17:59 UTC with 294 transactions…
--
[2024-10-20T04:59:38Z INFO  ord::index::updater] Committing at block height 380000, 12709322 outputs traversed, 2392814 in map, 199611781 cached
[2024-10-20T05:01:40Z INFO  ord::index::updater] Block 380000 at 2015-10-22 06:08:01 UTC with 687 transactions…
--
[2024-10-20T05:15:28Z INFO  ord::index::updater] Committing at block height 385000, 14356358 outputs traversed, 2591878 in map, 211376261 cached
[2024-10-20T05:17:44Z INFO  ord::index::updater] Block 385000 at 2015-11-23 18:03:21 UTC with 1969 transactions…
--
[2024-10-20T05:32:23Z INFO  ord::index::updater] Committing at block height 390000, 16311086 outputs traversed, 2904846 in map, 224782501 cached
[2024-10-20T05:35:02Z INFO  ord::index::updater] Block 390000 at 2015-12-24 17:33:51 UTC with 854 transactions…
--
[2024-10-20T05:51:13Z INFO  ord::index::updater] Committing at block height 395000, 16345239 outputs traversed, 2986441 in map, 238141299 cached
[2024-10-20T05:53:58Z INFO  ord::index::updater] Block 395000 at 2016-01-25 16:06:26 UTC with 2832 transactions…
gmart7t2 commented 1 month ago

Here's the same but without --index-sats. It doesn't start getting slow until block 805k:

0.20.0 (redb 2.1.3) - 8 to 10 minutes per commit:

[2024-09-04T03:41:28Z INFO  ord::index::updater] Committing at block height 800000, 0 outputs traversed, 12639276 in map, 169547160 cached
[2024-09-04T03:50:04Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T04:27:19Z INFO  ord::index::updater] Committing at block height 805000, 0 outputs traversed, 13444507 in map, 199075184 cached
[2024-09-04T04:36:54Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T05:14:26Z INFO  ord::index::updater] Committing at block height 810000, 0 outputs traversed, 13179841 in map, 229436297 cached
[2024-09-04T05:24:36Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/
--
[2024-09-04T06:10:31Z INFO  ord::index::updater] Committing at block height 815000, 0 outputs traversed, 8166981 in map, 254420874 cached
[2024-09-04T06:18:24Z INFO  ord::settings] Connecting to Bitcoin Core at 127.0.0.1:8332/

0.21.0 (redb 2.1.4) - 3 minutes to 19 hours per commit:

[2024-10-13T07:56:25Z INFO  ord::index::updater] Committing at block height 800000, 0 outputs traversed, 12639276 in map, 169547160 cached
[2024-10-13T07:59:36Z INFO  ord::index::updater] Block 800000 at 2023-07-24 03:17:09 UTC with 3721 transactions…
--
[2024-10-13T08:36:15Z INFO  ord::index::updater] Committing at block height 805000, 0 outputs traversed, 13444507 in map, 199075184 cached
[2024-10-13T12:28:32Z INFO  ord::index::updater] Block 805000 at 2023-08-27 03:31:42 UTC with 3196 transactions…
--
[2024-10-13T13:33:28Z INFO  ord::index::updater] Committing at block height 810000, 0 outputs traversed, 13179841 in map, 229436297 cached
[2024-10-14T21:40:41Z INFO  ord::index::updater] Block 810000 at 2023-09-30 09:51:04 UTC with 1690 transactions…
--
[2024-10-14T22:30:19Z INFO  ord::index::updater] Committing at block height 815000, 0 outputs traversed, 8166981 in map, 254420874 cached
[2024-10-15T17:06:28Z INFO  ord::index::updater] Block 815000 at 2023-11-02 18:26:42 UTC with 3372 transactions…

origin/master (redb 2.1.3) - 3 to 4 minutes per commit:

[2024-10-20T03:58:37Z INFO  ord::index::updater] Committing at block height 800000, 0 outputs traversed, 12639276 in map, 169547160 cached
[2024-10-20T04:01:42Z INFO  ord::index::updater] Block 800000 at 2023-07-24 03:17:09 UTC with 3721 transactions…
--
[2024-10-20T04:37:56Z INFO  ord::index::updater] Committing at block height 805000, 0 outputs traversed, 13444507 in map, 199075184 cached
[2024-10-20T04:41:35Z INFO  ord::index::updater] Block 805000 at 2023-08-27 03:31:42 UTC with 3196 transactions…
--
[2024-10-20T05:18:11Z INFO  ord::index::updater] Committing at block height 810000, 0 outputs traversed, 13179841 in map, 229436297 cached
[2024-10-20T05:22:17Z INFO  ord::index::updater] Block 810000 at 2023-09-30 09:51:04 UTC with 1690 transactions…
--
[2024-10-20T06:11:20Z INFO  ord::index::updater] Committing at block height 815000, 0 outputs traversed, 8166981 in map, 254420874 cached
[2024-10-20T06:15:04Z INFO  ord::index::updater] Block 815000 at 2023-11-02 18:26:42 UTC with 3372 transactions…