Open craigraw opened 2 years ago
Well, ElectrumX is CPU-bound because it's running in Python, which is incredibly taxing on the CPU. Fulcrum uses much less CPU and as a result its cost is dominated by either IO costs or bitcoind slowness. That being said, a faster CPU always helps.
Even on a desktop it did take me 2-3 days to sync bitcoin BTC. I am not surprised on an RPi is may take a while. Note that sometimes progress slows to a crawl then picks up again. Most of this is cost on the Fulcrum end is inside rocksdb which I cannot control from Fulcrum easily. And yes, there is some cost from bitcoind which can be heavy as well.
bitcoind's RPC interface that is the cause, specifically bitcoind's global locks that are noted in the Fulcrum configuration file for the bitcoind_clients paramete
Yes, this is possible. bitcoind is not very efficient with this.
Hmm I have to try out the p2p interface. I am not entirely sure that's the bottleneck or if it's something in the data model of Fulcrum. So you are saying you looked at the iops and other stuff and it appears that the disk I/O is not saturated? And neither is CPU? It could very well be network/bitcoind communication-related.
I will see about adding p2p interface support. It would certainly reduce overhead significantly.
So you are saying you looked at the iops and other stuff and it appears that the disk I/O is not saturated?
Yes - I'm using iotop
and generally not seeing either read or write exceed 2Mb/s (usually lower) for the four Fulcrum threads, whereas the previously measured disk read performance is over 200Mb/s. Occasionally, one of the threads does reach a higher 20+ Mb/s write for a short period.
And neither is CPU?
Of the theoretical 400% max, CPU is generally around 100%, dropping to 20% and spiking to 280% from time to time.
Hmm. Baffling. Well there are a number of avenues of attack here for me to explore. I had no idea Electrs was that much faster. If it is it clearly proves faster may be possible.
A few points that come up in my mind, mainly for me to explore:
You know you can always try raising db_men
in the conf file (if your rpi has enough memory). The default setting (if unspecified) is db_mem=420
(420 MB). You can try setting it to 512
or 1024
.
Another thing for you to try is setting: db_max_open_files
The default is 20
. But maybe set it to like 200
or 1000
or something. Each open .sst
files consumes memory though so if you set it too high it may OOM on an RPi.
Note you can always hit Ctrl-C
during a sync and the app will gracefully exit, and will resume synching where it last left off (this way you can try out various options to see how they impact sync time).
I have been wondering how to determine if the RPC interface is a bottleneck, so I put together a small application to benchmark block reading performance: https://github.com/craigraw/blockreader.
Currently, it is using bitcoin-cli
to read blocks using the getblockheader
followed by the getblock
call to retrieve the block hex for a configurable number of blocks starting at a random block height around 500,000, using a configurable number of threads.
Here are the results for 4 threads reading 100 blocks each:
Read 125863808 bytes in 21607 ms (5825.14 Kb/sec)
Read 158320726 bytes in 24894 ms (6359.79 Kb/sec)
Read 165610670 bytes in 25650 ms (6456.56 Kb/sec)
Read 193962550 bytes in 27723 ms (6996.45 Kb/sec)
Total 643757754 bytes in 27723 ms (23221.07 Kb/sec)
This was surprising, and seems to indicate that block reading via the RPC interface should not necessarily be a limiting factor - at this rate all the blocks can be retrieved in a few hours. That said, I do notice that ElectrumX does block prefetching to avoid waiting for bitcoind - I'm not sure if Fulcrum does this?
I tried increasing the db_mem=1024
and db_max_open_files=200
- there may be a slight improvement. I'm currently Processed height: 607000, 84.4%, 1.24 blocks/sec, 2637.0 txs/sec, 9159.5 addrs/sec
.
Thanks for the feedback. Yes, your observations do correlate with what I remembered about the situation, in that RPC was surprisingly fast (or fast enough). Fulcrum does prefetch tens or even hundreds of blocks at a time. Also it retrieves blocks in a separate thread anyway as the processing thread is adding them to the db.
I suspect the choking is in rocksdb somehow. rocksdb is fairly opaque to me but I can try and experiment with various ways to get it to speed up.
A quick update on this - while indexing I am getting random freezes on my RPi which cause index corruption. I don't believe they are Fulcrum's fault, but rather something hardware related caused during intensive IO. This machine never experienced them before, so it might be due to the new sd card or OS. Anyway after many indexing restarts I am now doing regular backups of the index, so I can recover when it happens. I am currently at 62%.
One thought I had regarding "what is different to Electrs" is that Fulcrum might be doing some kind of read-and-then-write, while Electrs is just writing. My cursory examination of the code did not seem to bear this out, but I thought I'd mention it anyway. I'm not sure if SSD seek times are easily measured.
Your intuition is correct -- it writes to the UTXO db for each block, creating new UTXOs as they are created and deleting old ones as they are spent.
Then for the next block it needs to read back from this very same DB to figure out which coins were spent all over again. Sometimes referencing the same UTXOs it just wrote out.
I suspect Electrs uses some different strategy to mitigate this. I still haven't looked at their code. (However the fact that they have very poor support for large wallets leads me to believe they may be saving data in some normalized fashion, thus making queries more expensive -- Fulcrum saves data in a more denormalized way for faster queries after sync...).
When I designed this, I assumed rocksdb would cache stuff intelligently, and indeed with sufficient db_mem it's very fast in practice while running -- but during a sync it can eat performance and also causes rocksdb to stall weirdly, especially on RPi it seems.
I actually am working on a private branch to cache all the UTXOs in memory (as much as would fit anyway) explicitly, using a hashmap. It yields a +40% speed boost in my testing. I may release this soon as a new experimental, opt-in-only feature.
This new UTXO cache I am using makes it much less heavy on the DB. It basically only periodically "commits" UTXO changes to the DB. The advantage of this is a lot of reduced back-and-forth to rocksDB. And if you have enough memory, it can be a real boost.
The disadvantage is of course.. it eats memory.
Strange about the RPi stalls. I have also seen my RPi stall when doing things like compiling code. Like total freeze! I have an RPi 4. If I compile code with make -j16
or something it will lock up for long periods of time and sometimes forever. If I compile with make -j 4
it's fine.
I thought my RPi was broken. Maybe it's not.. maybe this is something common?
I never used my Rpi to sync fulcrum.. :)
@craigraw Well, I pushed my batch support to master, as you may have seen. Also, I added a new option --experimental-fast-sync
which should reduce the write -> read -> delete lifecycle for many "ephemeral" UTXOs (which turned out to be a bottleneck in synching).
See this PR: https://github.com/cculianu/Fulcrum/pull/98
I may just merge this to master today since I've spent the better part of a week on this testing it and re-testing it and reviewing my own code. It should be a win to use this option (provided you have enough memory to store lots of UTXOs in RAM).
The option is off by default and so if not used the code path for synching remains the same.
I'm fairly confident Electrs does save data in a normalized fashion, relying on RocksDB to do db compaction on duplicate keys afterwards. There is no indication in the db schema that they are storing multiple block heights against a script hash for example.
I've just compiled the wip_utxo_cache
branch. Small note: I added the experimental-fast-sync
to the config file initially and the logs told me it wasn't enabled. I then added it to the systemd script as well and the logs told me it was added in both places. In any case, it's enabled now at 2048Mb. I'll feed back on any observed performance improvements later.
I think the RPi freezes may have been due to the OS autosuspending the SSD drive, on which I have the OS swap file. I made a change to the configuration, if it persists I might go back to Raspbian 64bit which is more heavily tested on this hardware.
Oh Fulcrum isn't like bitcoind where CLI args == conf file args. Some of them are equal to conf file args, most of them aren't. Not every conf file arg can be specified on the CLI, and not every CLI arg can be specified in the conf file... Yeah this is a CLI only arg, sorry I should have mentioned that. I figure it should be explicitly enabled by the user and not something to have in the conf file....
Well I don't know what electrs does. All I know is it's slower than Fulcrum in general once you sync. Look at it this way: you sync only once. Once you sync Fulcrum is blazing. :)
As for the RPi issues -- yeah I wonder what it could be too. Do let me know if you get to the bottom of it because like I said, I had similar.
I've updated to the latest in wip_utxo_cache
. It does appear to be faster:
Previous:
Processed height: 461000, 64.1%, 1.14 blocks/sec, 2057.4 txs/sec, 8000.9 addrs/sec
Processed height: 462000, 64.3%, 58.1 blocks/min, 1770.9 txs/sec, 7133.3 addrs/sec
Current:
Processed height: 598000, 83.1%, 1.60 blocks/sec, 3537.6 txs/sec, 11526.0 addrs/sec
Processed height: 599000, 83.2%, 2.43 blocks/sec, 5146.7 txs/sec, 16615.8 addrs/sec
These are very encouraging results, suggesting a full sync can complete in under 48 hours on an RPi. This brings it to within striking distance of Electrs indexing-wise, so that it may be easily substituted. That Fulcrum is much, much faster in serving requests, I have no doubt :)
Understood on the CLI/config args. I'm sure once this functionality is no longer considered experimental it will be promoted to a config file option to configure the cache memory limit.
So far, the RPi has not failed again, so I am hoping the autosuspend change was the trick. For the record, the change I made was to disable autosuspend in the RPI's internal USB hub that the SSD is connected to using echo 'on' > '/sys/bus/usb/devices/usb2/power/control'
. It was previously set to auto
.
Awesome! Yeah so the new UTXO Cache thing basically reduces back-and-forth to the DB.. so yay! Great to hear!
Yeah I'm seeing similar improvements. I gave it a good 12000 MB on my (somewhat old) 2015 x86 system and it synced in under 8 hours. Usually it takes at least 12 hours or maybe 16 hours.
I'm still working on the feature. It has no bugs, but it just is not as elegantly implemented as I would like, and I am still ironing out ideas to improve efficiency further (hence why it's not merged yet).
This is great news! Thanks man for testing!
So far, the RPi has not failed again, so I am hoping the autosuspend change was the trick. For the record, the change I made was to disable autosuspend in the RPI's internal USB hub that the SSD is connected to using echo 'on' > '/sys/bus/usb/devices/usb2/power/control'. It was previously set to auto.
OMFG It's set to auto
for me here too. Thanks UBUNTU!!. Ok, I'm setting it to on
as well. Dammit. Now to search online about how to persist this setting in the "elergant" way.. :)
Indexing completed! The server is serving non-batched requests successfully.
Should the memory usage decrease once the initial sync is done? There was a log line suggesting the UTXO cache was being shut down, but the reported memory use appeared to be the same post indexing, as if the UTXO cache was still present. That said I'm not very familiar with memory handling in C++.
It should disappear but due to memory fragmentation it may not all go away. If you use jemalloc
with Fulcrum (you must install jemalloc then recompile) it should be better. I recommend restarting the server to bring memory usage down. Heap fragmentation plagues any language, this is not specific to C++. It comes down to the low-level allocator in glibc being not as good as jemalloc.
On 1 system here without jemalloc
after synching with that huge UTXO cache memory usage stayed high-ish at over 1.5g (down from 8g while it was running). On my other box with jemalloc
it went back down to 800MB or so (which is nominal for Fulcrum normally).
So yeah.. heap fragmentation. Blame glibc's malloc.
You think I can close this? I think we concluded at least that it wasn't the p2p/network layer as the issue. Or.. maybe I can just rename this issue to: "Initial synch performance" instead...
Yes, agreed. I don’t think we yet know exactly how Fulcrum is bounded on an RPi - it doesn’t appear to be CPU.
Any recommended value for the fast sync?
I'm using Raspi4B 8GB with only bitcoind running, I was once using 5000 and 4000 for the value, but both always made Fulcrum OOM at ~60% sync.
14 22:50:53 raspberrypi Fulcrum[60901]:
Processed height: 440000, 60.1%, 4.06 blocks/sec, 7416.5 txs/sec, 26537.9 addrs/sec Apr 14 22:52:30 raspberrypi Fulcrum[60901]: Storage UTXO Cache: Flushing to DB ... Apr 14 22:52:30 raspberrypi kernel: [48749.555193] systemd-journal invoked oom-killer: gfp_mask=0x1100cca(GFP_HIGHUSER_MOVABLE), order=0, oom_score_adj=-250 Apr 14 22:52:30 raspberrypi kernel: [48749.555225] CPU: 2 PID: 150 Comm: systemd-journal Tainted: G C 5.15.32-v8+ #1538 Apr 14 22:52:30 raspberrypi kernel: [48749.555231] Hardware name: Raspberry Pi 4 Model B Rev 1.4 (DT) Apr 14 22:52:30 raspberrypi kernel: [48749.555235] Call trace: Apr 14 22:52:30 raspberrypi kernel: [48749.555237] dump_backtrace+0x0/0x1b8 Apr 14 22:52:30 raspberrypi kernel: [48749.555251] show_stack+0x20/0x30 Apr 14 22:52:30 raspberrypi kernel: [48749.555257] dump_stack_lvl+0x8c/0xb8 Apr 14 22:52:30 raspberrypi kernel: [48749.555263] dump_stack+0x18/0x34 Apr 14 22:52:30 raspberrypi kernel: [48749.555266] dump_header+0x4c/0x204 Apr 14 22:52:30 raspberrypi kernel: [48749.555272] oom_kill_process+0x1f8/0x200 Apr 14 22:52:30 raspberrypi kernel: [48749.555277] out_of_memory+0xf0/0x330 Apr 14 22:52:30 raspberrypi kernel: [48749.555281] alloc_pages_slowpath.constprop.150+0x84c/0xba0 Apr 14 22:52:30 raspberrypi kernel: [48749.555288] alloc_pages+0x2b0/0x330 Apr 14 22:52:30 raspberrypi kernel: [48749.555293] pagecache_get_page+0x1a0/0x3a0 Apr 14 22:52:30 raspberrypi kernel: [48749.555299] filemap_fault+0x50c/0x820 Apr 14 22:52:30 raspberrypi kernel: [48749.555304] __do_fault+0x44/0x168 Apr 14 22:52:30 raspberrypi kernel: [48749.555309] __handle_mm_fault+0x508/0xa38 Apr 14 22:52:30 raspberrypi kernel: [48749.555313] handle_mm_fault+0x1a4/0x288 Apr 14 22:52:30 raspberrypi kernel: [48749.555317] do_page_fault+0x240/0x480 Apr 14 22:52:30 raspberrypi kernel: [48749.555322] do_translation_fault+0x60/0x78 Apr 14 22:52:30 raspberrypi kernel: [48749.555326] do_mem_abort+0x48/0xb8 Apr 14 22:52:30 raspberrypi kernel: [48749.555331] el0_ia+0x68/0xe8 Apr 14 22:52:30 raspberrypi kernel: [48749.555336] el0t_64_sync_handler+0x78/0xb8 Apr 14 22:52:30 raspberrypi kernel: [48749.555341] el0t_64_sync+0x1a0/0x1a4 Apr 14 22:52:30 raspberrypi kernel: [48749.555346] Mem-Info: Apr 14 22:52:30 raspberrypi kernel: [48749.555351] active_anon:165 inactive_anon:1919753 isolated_anon:0 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] active_file:135 inactive_file:136 isolated_file:45 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] unevictable:4 dirty:0 writeback:0 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] slab_reclaimable:31781 slab_unreclaimable:7272 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] mapped:60 shmem:234 pagetables:9252 bounce:0 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] kernel_misc_reclaimable:0 Apr 14 22:52:30 raspberrypi kernel: [48749.555351] free:22929 free_pcp:545 free_cma:2291 Apr 14 22:52:30 raspberrypi kernel: [48749.555361] Node 0 active_anon:660kB inactive_anon:7679012kB active_file:540kB inactive_file:544kB unevictable:16kB isolated(anon):0kB isolated(file):180kB mapped:240kB dirty:0kB writeback:0kB shmem:936kB writeback_tmp:0kB kernel_stack:3440kB pagetables:37008kB all_unreclaimable? no Apr 14 22:52:30 raspberrypi kernel: [48749.555371] DMA free:29408kB min:1812kB low:2696kB high:3580kB reserved_highatomic:0KB active_anon:0kB inactive_anon:834408kB active_file:0kB inactive_file:56kB unevictable:0kB writepending:0kB present:969728kB managed:885516kB mlocked:0kB bounce:0kB free_pcp:716kB local_pcp:12kB free_cma:9164kB Apr 14 22:52:30 raspberrypi kernel: [48749.555382] lowmem_reserve[]: 0 3008 6946 6946 Apr 14 22:52:30 raspberrypi kernel: [48749.555402] DMA32 free:27072kB min:25008kB low:28088kB high:31168kB reserved_highatomic:0KB active_anon:4kB inactive_anon:3014336kB active_file:48kB inactive_file:492kB unevictable:0kB writepending:0kB present:3080192kB managed:3080192kB mlocked:0kB bounce:0kB free_pcp:292kB local_pcp:220kB free_cma:0kB Apr 14 22:52:30 raspberrypi kernel: [48749.555412] lowmem_reserve[]: 0 0 3938 3938 Apr 14 22:52:30 raspberrypi kernel: [48749.555428] Normal free:35236kB min:32744kB low:36776kB high:40808kB reserved_highatomic:4096KB active_anon:656kB inactive_anon:3829676kB active_file:408kB inactive_file:612kB unevictable:16kB writepending:0kB present:4194304kB managed:4033236kB mlocked:16kB bounce:0kB free_pcp:1172kB local_pcp:440kB free_cma:0kB Apr 14 22:52:30 raspberrypi kernel: [48749.555438] lowmem_reserve[]: 0 0 0 0 Apr 14 22:52:30 raspberrypi kernel: [48749.555454] DMA: 764kB (UEC) 1408kB (UEC) 21816kB (UEC) 11532kB (UE) 4864kB (UE) 24128kB (UE) 3256kB (UE) 1512kB (E) 11024kB (E) 02048kB 34096kB (UC) = 29328kB Apr 14 22:52:30 raspberrypi kernel: [48749.555534] DMA32: 554kB (ME) 48kB (ME) 74816kB (UME) 36732kB (UE) 5864kB (UE) 0128kB 0256kB 0512kB 01024kB 02048kB 04096kB = 27676kB Apr 14 22:52:30 raspberrypi kernel: [48749.555591] Normal: 224kB (MH) 3758kB (UEH) 110416kB (UEH) 34532kB (UEH) 4464kB (UEH) 0128kB 0256kB 0512kB 01024kB 02048kB 0*4096kB = 34608kB Apr 14 22:52:30 raspberrypi kernel: [48749.555647] 596 total pagecache pages Apr 14 22:52:30 raspberrypi kernel: [48749.555650] 0 pages in swap cache Apr 14 22:52:30 raspberrypi kernel: [48749.555654] Swap cache stats: add 0, delete 0, find 0/0 Apr 14 22:52:30 raspberrypi kernel: [48749.555658] Free swap = 0kB Apr 14 22:52:30 raspberrypi kernel: [48749.555661] Total swap = 0kB Apr 14 22:52:30 raspberrypi kernel: [48749.555665] 2061056 pages RAM Apr 14 22:52:30 raspberrypi kernel: [48749.555668] 0 pages HighMem/MovableOnly Apr 14 22:52:30 raspberrypi kernel: [48749.555671] 61320 pages reserved Apr 14 22:52:30 raspberrypi kernel: [48749.555674] 81920 pages cma reserved Apr 14 22:52:30 raspberrypi kernel: [48749.555678] Tasks state (memory values in pages): Apr 14 22:52:30 raspberrypi kernel: [48749.555681] [ pid ] uid tgid total_vm rss pgtables_bytes swapents oom_score_adj name Apr 14 22:52:30 raspberrypi kernel: [48749.555707] [ 150] 0 150 28486 270 196608 0 -250 systemd-journal Apr 14 22:52:30 raspberrypi kernel: [48749.555715] [ 217] 0 217 5314 534 57344 0 -1000 systemd-udevd Apr 14 22:52:30 raspberrypi kernel: [48749.555733] [ 534] 108 534 1768 117 49152 0 0 avahi-daemon Apr 14 22:52:30 raspberrypi kernel: [48749.555740] [ 535] 0 535 1674 63 40960 0 0 cron Apr 14 22:52:30 raspberrypi kernel: [48749.555746] [ 536] 104 536 1996 178 40960 0 -900 dbus-daemon Apr 14 22:52:30 raspberrypi kernel: [48749.555753] [ 538] 108 538 1723 78 49152 0 0 avahi-daemon Apr 14 22:52:30 raspberrypi kernel: [48749.555759] [ 550] 0 550 55222 329 65536 0 0 rsyslogd Apr 14 22:52:30 raspberrypi kernel: [48749.555766] [ 556] 0 556 3641 218 61440 0 0 systemd-logind Apr 14 22:52:30 raspberrypi kernel: [48749.555772] [ 559] 65534 559 1372 58 40960 0 0 thd Apr 14 22:52:30 raspberrypi kernel: [48749.555779] [ 563] 0 563 3392 165 57344 0 0 wpa_supplicant Apr 14 22:52:30 raspberrypi kernel: [48749.555785] [ 601] 0 601 23074 38 45056 0 0 rngd Apr 14 22:52:30 raspberrypi kernel: [48749.555792] [ 626] 110 626 1160 154 36864 0 0 vnstatd Apr 14 22:52:30 raspberrypi kernel: [48749.555798] [ 629] 0 629 98987 2716 126976 0 0 fail2ban-server Apr 14 22:52:30 raspberrypi kernel: [48749.555804] [ 636] 0 636 3411 236 57344 0 -1000 sshd Apr 14 22:52:30 raspberrypi kernel: [48749.555810] [ 641] 0 641 3491 235 61440 0 0 wpa_supplicant Apr 14 22:52:30 raspberrypi kernel: [48749.555817] [ 653] 0 653 13324 370 81920 0 0 nginx Apr 14 22:52:30 raspberrypi kernel: [48749.555824] [ 654] 33 654 13416 441 86016 0 0 nginx Apr 14 22:52:30 raspberrypi kernel: [48749.555831] [ 701] 0 701 533 33 28672 0 0 hciattach Apr 14 22:52:30 raspberrypi kernel: [48749.555838] [ 715] 0 715 5896 295 77824 0 0 bluetoothd Apr 14 22:52:30 raspberrypi kernel: [48749.555845] [ 850] 103 850 22023 190 61440 0 0 systemd-timesyn Apr 14 22:52:30 raspberrypi kernel: [48749.555852] [ 852] 0 852 762 112 36864 0 0 dhcpcd Apr 14 22:52:30 raspberrypi kernel: [48749.555859] [ 857] 0 857 2290 163 45056 0 0 login Apr 14 22:52:30 raspberrypi kernel: [48749.555867] [ 982] 1000 982 4001 320 61440 0 0 systemd Apr 14 22:52:30 raspberrypi kernel: [48749.555874] [ 983] 1000 983 42200 734 94208 0 0 (sd-pam) Apr 14 22:52:30 raspberrypi kernel: [48749.555881] [ 996] 1000 996 2500 408 49152 0 0 zsh Apr 14 22:52:30 raspberrypi kernel: [48749.555888] [ 1146] 109 1146 150368 88206 983040 0 0 tor Apr 14 22:52:30 raspberrypi kernel: [48749.555896] [ 1216] 1001 1216 1251259 113627 8269824 0 0 bitcoind Apr 14 22:52:30 raspberrypi kernel: [48749.555903] [ 60901] 1003 60901 3737045 1707274 26476544 0 0 Fulcrum Apr 14 22:52:30 raspberrypi kernel: [48749.555912] [ 62520] 0 62520 4015 305 57344 0 0 sshd Apr 14 22:52:30 raspberrypi kernel: [48749.555918] [ 62526] 1000 62526 4015 304 57344 0 0 sshd Apr 14 22:52:30 raspberrypi kernel: [48749.555925] [ 62527] 1000 62527 2523 412 49152 0 0 zsh Apr 14 22:52:30 raspberrypi kernel: [48749.555932] [ 62546] 0 62546 4015 305 65536 0 0 sshd Apr 14 22:52:30 raspberrypi kernel: [48749.555938] [ 62552] 1000 62552 4015 304 61440 0 0 sshd Apr 14 22:52:30 raspberrypi kernel: [48749.555944] [ 62553] 1000 62553 2523 412 49152 0 0 zsh Apr 14 22:52:30 raspberrypi kernel: [48749.555951] [ 62572] 1000 62572 3109 140 53248 0 0 sudo Apr 14 22:52:30 raspberrypi kernel: [48749.555957] [ 62573] 0 62573 1243 23 36864 0 0 tail Apr 14 22:52:30 raspberrypi kernel: [48749.555963] [ 62575] 1000 62575 1243 16 40960 0 0 tail Apr 14 22:52:30 raspberrypi kernel: [48749.555970] oom-kill:constraint=CONSTRAINT_NONE,nodemask=(null),cpuset=/,mems_allowed=0,global_oom,task_memcg=/,task=Fulcrum,pid=60901,uid=1003 Apr 14 22:52:30 raspberrypi kernel: [48749.556041] Out of memory: Killed process 60901 (Fulcrum) total-vm:14948180kB, anon-rss:6829096kB, file-rss:0kB, shmem-rss:0kB, UID:1003 pgtables:25856kB oom_score_adj:0 Apr 14 22:52:31 raspberrypi kernel: [48751.054776] oom_reaper: reaped process 60901 (Fulcrum), now anon-rss:0kB, file-rss:0kB, shmem-rss:0kB Apr 14 22:52:31 raspberrypi systemd[1]: fulcrum.service: Main process exited, code=killed, status=9/KILL Apr 14 22:52:31 raspberrypi systemd[1]: fulcrum.service: Failed with result 'signal'. Apr 14 22:52:31 raspberrypi systemd[1]: fulcrum.service: Consumed 11h 14min 52.413s CPU time. Apr 14 22:53:02 raspberrypi systemd[1]: fulcrum.service: Scheduled restart job, restart counter is at 1. Apr 14 22:53:02 raspberrypi systemd[1]: Stopped Fulcrum daemon. Apr 14 22:53:02 raspberrypi systemd[1]: fulcrum.service: Consumed 11h 14min 52.413s CPU time. Apr 14 22:53:02 raspberrypi systemd[1]: Started Fulcrum daemon. Apr 14 22:53:02 raspberrypi Fulcrum[62632]: Enabled JSON parser: simdjson Apr 14 22:53:02 raspberrypi Fulcrum[62632]: simdjson implementations: Apr 14 22:53:02 raspberrypi Fulcrum[62632]: fallback: Generic fallback implementation [supported] Apr 14 22:53:02 raspberrypi Fulcrum[62632]: active implementation: fallback Apr 14 22:53:02 raspberrypi Fulcrum[62632]: jemalloc: version 5.2.1-0-gea6b3e9 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: Qt: version 5.15.2 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: rocksdb: version 6.14.6-ed43161 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: simdjson: version 0.6.0 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: ssl: OpenSSL 1.1.1n 15 Mar 2022 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: zmq: libzmq version: 4.3.3, cppzmq version: 4.7.1 Apr 14 22:53:02 raspberrypi Fulcrum[62632]: Fulcrum 1.6.0 (Release 5e95c0f) - Thu Apr 14, 2022 22:53:02.203 WIB - starting up ... Apr 14 22:53:02 raspberrypi Fulcrum[62632]: Max open files: 524288 (increased from default: 1024) Apr 14 22:53:02 raspberrypi Fulcrum[62632]: Loading database ... Apr 14 22:53:16 raspberrypi Fulcrum[62632]: DB memory: 512.00 MiB Apr 14 22:53:16 raspberrypi Fulcrum[62632]: Coin: BTC Apr 14 22:53:16 raspberrypi Fulcrum[62632]: Chain: main Apr 14 22:53:16 raspberrypi Fulcrum[62632]: FATAL: Caught exception: It appears that Fulcrum was forcefully killed in the middle of committing a block to the db. We cannot figure out where exactly in the update process Fulcrum was killed, so we cannot undo the inconsistent state caused by the unexpected shutdown. Sorry!#012#012The database has been corrupted. Please delete the datadir and resynch to bitcoind. Apr 14 22:53:16 raspberrypi Fulcrum[62632]: Stopping Controller ... Apr 14 22:53:16 raspberrypi Fulcrum[62632]: Closing storage ... Apr 14 22:53:16 raspberrypi Fulcrum[62632]: Shutdown complete
Yeesh.. 14GB 6GB resident. Ouch. Hmm. I guess that was too much for your system. I have to play around with this more but it looks like the memory allocator may not be 100% kosher here, and it's hanging on to memory that it should be returning to the OS. Strange that on my macOS x86 and on my Linux x86 system none of this happens... and it tends to stay within constraints for the memory consumption. EDIT: It appears to have stayed within constraints (6GB) but apparently still that was too much for this system.
FWIW I have had great success with even as little as 256MB for fast-sync. Any amount seems to pay off, even if it seems small. Sometimes less is more, especially on memory constrained systems.
Finished the sync with 512 fast-sync value, Pi running with SSD. Thanks!
Apr 15 02:15:26 raspberrypi Fulcrum[110051]: <Controller> Processed height: 1000, 0.1%, 1097.6 blocks/sec, 1118.4 txs/sec, 1146.9 addrs/sec
Apr 16 22:32:36 raspberrypi Fulcrum[110051]: <Controller> Processed height: 731000, 99.9%, 1.77 blocks/sec, 3267.7 txs/sec, 16975.7 addrs/sec
https://github.com/rootzoll/raspiblitz/issues/2924#issuecomment-1202459496
The install script config.scripts/bonus.fulcrum.sh
bundled with Raspiblitz 1.8.0 img worked flawlessly on my Pi4b 8GB with USB 3.1 NVME in an external enclosure.
Sync time about 63 hours, no changes were made to the config.scripts/bonus.fulcrum.sh
SparrowWallet connects to fulcrum via Tor on ports
50021 (v6) ALLOW Anywhere (v6) # Fulcrum TCP
50022 (v6) ALLOW Anywhere (v6) # Fulcrum SSL
For reference on performance, around BTC block 788,000.
Ryzen 5 3600 with bitcoind on spinning disk and nvme for the Fulcrum db. Fast-sync at 8000.
5h30min for full sync and total disk size of 117.8GB. Timing about 3-4x faster than E-X (long time E-X user and debating a conversion to Fulcrum)
I recently started to work with Fulcrum on a bitcoin core project. My tech level is basic user. I have experienced a very long synch. I have multiple times tried to sync for 4-6 days, and the system basically stalls at around 75% complete before I get tired or waiting on it, delete the database, and start over. Trying to shut it down times out and the database gets corrupt. At the point that I give up, I have noticed in every case, the machine memory has slowly inched up until all the memory is exhausted, and it starts consuming swap space.
I realize that my latest attempt is not in anyway a good fix, but it seems to be working, so I thought I would pass it along, as insight, more than as a solution.
I have set the machine up so that it automatically starts and runs Fulcrum for 10 minutes (it is at this point that the memory starts crawling up faster), automatically shuts down nicely, restarts, waits 10 minutes, repeat.
The result is, the memory drops back to base, the database storage utxo cache flushes without corruption, and it starts up again running with a higher rate. I am hoping it will complete this time!
I have no idea why the memory climbs up as high as it does, but that is when it seems to really slow down to a crawl. I will let you know if I get the synch finished.
Thank you for the great work, I am really looking forward to using Fulcrum once it gets synced.
Cheers
When building the initial index using Fulcrum on a RPi (connected to a 1Tb SSD), my expectation was that the process would be entirely CPU bound parsing blocks. This is the case for single-threaded ElectrumX, but my hope was that Fulcrum, using a non-interpreted language and multiple threads, would be able to significantly increase the speed of this process. ElectrumX takes almost 2 months to build the initial index on such limited hardware, and frequently fails with memory allocation errors.
This expectation has been borne out to a great extent - 70% indexing after 40 hours is much better progress. That said, processing has now dropped (at times) to 26 blocks/min around height 513000, presumably as the result of larger blocks. At this rate it will take another 4-8 days to finish the index. This can be compared to some extent against Electrs, which builds its (admittedly more limited) index within 24 hours on the same hardware.
I have been trying to determine the bottleneck - it appears that Fulcrum is neither CPU or IO bound, generally running at a quarter CPU available and modest IO. This leads me to believe that it is bitcoind's RPC interface that is the cause, specifically bitcoind's global locks that are noted in the Fulcrum configuration file for the bitcoind_clients parameter. Note that in the case of my setup, I have bitcoind running on another (similarly low power) machine on the local network. I've also tried running Fulcrum on a Linux desktop machine against the same bitcoind node, and have noted even lower CPU usage, which seems to support this.
I believe the reason that Electrs is able to achieve such fast processing is it's use of P2P interface to download blocks (see implementation here). No locks are obtained, and the IP Fulcrum is running on can be whitelisted in bitcoind so there are no restrictions in total bandwidth. This effectively mimics the IBD for bitcoind, but against a single peer. Of course, it's possible to use the P2P interface for more than the initial indexing as well.
My hope is that if initial indexing on Fulcrum can be brought to a comparable speed to Electrs, it can replace Electrs on popular prebuilt node packages which generally target the RPi4. Electrs faces significant challenges loading deep wallets due to the data architecture design, which I have described here: https://www.sparrowwallet.com/docs/server-performance.html. Barring a significant architectural change to that project, I believe Fulcrum could be a better alternative as it can perform the address-to-txid+height lookup internally. This may be the case already, but having a similar indexing speed would make the comparison even clearer.