search

lbryio / lbcd

An alternative full node implementation of LBRY's blockchain written in Go (golang)
https://lbry.com/
ISC License
38 stars 25 forks source link

Reduce claimtrie temp allocs. #51

Open moodyjon opened 2 years ago

moodyjon commented 2 years ago

Unbundled from PR https://github.com/lbryio/lbcd/pull/43

See that for usage/testing.

Based on work by @BrannonKing in mem_pressure_try_2 and reduce_memory_pressure.

The commits 84828907593e597856f977af18649637bd5b8c6c and 787098e2a2f4692c7c3e6eab1a1ba25d00a54ae0 are newly added to claw back costs from node cache and node.Clone().

coveralls commented 2 years ago

Pull Request Test Coverage Report for Build 2450737946

Changes Missing Coverage Covered Lines Changed/Added Lines %
claimtrie/node/hashfork_manager.go 0 1 0.0%
claimtrie/node/normalizing_manager.go 0 1 0.0%
blockchain/claimtrie.go 0 4 0.0%
rpcclaimtrie.go 0 4 0.0%
claimtrie/node/node.go 45 51 88.24%
claimtrie/node/noderepo/pebble.go 11 17 64.71%
claimtrie/node/cache.go 3 12 25.0%
claimtrie/node/manager.go 9 19 47.37%
<!-- Total: 71 112 63.39% -->
Files with Coverage Reduction New Missed Lines %
claimtrie/node/cache.go 1 62.16%
claimtrie/node/noderepo/pebble.go 1 68.75%
integration/rpctest/blockgen.go 2 83.78%
btcec/signature.go 3 92.82%
peer/peer.go 8 76.31%
<!-- Total: 15 -->
Totals Coverage Status
Change from base Build 2450492318: 0.002%
Covered Lines: 22490
Relevant Lines: 43402
💛 - Coveralls
roylee17 commented 2 years ago

The tuning doesn't work out, both sync time and startup time got worse.

Sync time

Before (pr46):

2022-06-06 06:37:12.838 [INF] MAIN: Version 0.0.0-local.0+15191b7ede02f4c052a2a61c55c8ef7a95d8e134
2022-06-06 20:31:12.230 [INF] SYNC: Processed 63 blocks in the last 10s (10282 transactions, height 1163018, 2022-05-20 23:52:46 +0000 UTC)

After:

2022-06-07 19:39:26.514 [INF] MAIN: Version 0.0.0-local.0+787098e2a2f4692c7c3e6eab1a1ba25d00a54ae0
2022-06-08 13:58:51.657 [INF] SYNC: Processed 70 blocks in the last 10.22s (9345 transactions, height 1163069, 2022-05-21 02:04:36 +0000 UTC)

(Re)startup time

Before (pr46):

2022-06-06 20:47:34.503 [INF] MAIN: Version 0.0.0-local.0+c4e7528a6a87e37d631925ad19e8a78675609fa0
2022-06-06 20:51:05.282 [INF] CHAN: Loading block index...

After:

2022-06-09 05:40:36.626 [INF] MAIN: Version 0.0.0-local.0+787098e2a2f4692c7c3e6eab1a1ba25d00a54ae0
2022-06-09 05:50:55.352 [INF] CHAN: Loading block index...
moodyjon commented 2 years ago

Wow. 10 minutes for claimtrie build. :-( Something's not right.... That's so bad that it makes me suspect that there was some extra load on the machine at some point.

Can you rerun it with profile collection? Just the restart case at first to see whether 10min is reproducible.

./lbcd --memprofile=./after.mem --cpuprofile=./after.cpu

When I run it on an 8core arm64 Mac mini, it continues to be about 3 min (before) and 2.2min (after) for claimtrie build.

Before:

swdev1@Mac-mini lbcd % ./lbcd --memprofile=./before7.mem --cpuprofile=./before7.cpu
2022-06-09 12:59:18.282 [INF] MAIN: Version 0.0.0-local.0+3772b1ef1d7625b6f71f107e00d47f89136e5071-dirty
2022-06-09 12:59:18.283 [INF] MAIN: Loading block database from '/Users/swdev1/Library/Application Support/Lbcd/data/mainnet/blocks_ffldb'
2022-06-09 12:59:18.577 [INF] MAIN: Block database loaded
2022-06-09 12:59:21.579 [INF] SRVR: Can't discover UPnP-enabled device: write udp4 0.0.0.0:55040->239.255.255.250:1900: i/o timeout
2022-06-09 12:59:21.586 [INF] INDX: Transaction index is enabled
2022-06-09 12:59:21.586 [INF] INDX: Committed filter index is enabled
2022-06-09 12:59:22.063 [INF] LBRY: Normalizing strings via Go. Casefold and NFD table versions: 11.0.0 (from ICU 63.2)
2022-06-09 12:59:22.064 [INF] LBRY: Building the entire claim trie in RAM...
2022-06-09 12:59:26.136 [INF] LBRY: Spending claim but missing existing claim with TXO bd183d94dc0b2c38d500838f4ab7c93b643123f46e87214d3e37f5e9e0d4baf5:0, Name: 1791l-trumpcnn, ID: 6a28cbbe64c3c54113770705c928e80a138ddae9
2022-06-09 12:59:58.719 [INF] MAIN: RAM: using 1.3 GB with 2.7 available, DISK: using 122.3 GB with 786.7 available
2022-06-09 13:00:27.944 [INF] LBRY: Spending claim but missing existing claim with TXO 546a1b99218f5935d6d11d6a5632ba199b24d6dbb6c07e75bea1089eee23987d:0, Name: ggminingpool-xzc, ID: 0b9e8ea179d6f68d3b37ab0e636af6ab1b93b52e
2022-06-09 13:00:27.949 [INF] LBRY: Spending claim but missing existing claim with TXO 5dff52209029a63547f8805c3e92fce87e3744a15f6539a12011fe0c421ca132:0, Name: ggminingpoolxzc, ID: 3fa8d7113bd4873e79ec02019bea3c7840f0deee
2022-06-09 13:00:38.821 [INF] MAIN: RAM: using 2.1 GB with 2.7 available, DISK: using 122.3 GB with 786.7 available
2022-06-09 13:01:09.422 [INF] LBRY: Spending claim but missing existing claim with TXO 022a25b42e0327d6bf7a741cd3bae34404453549635d916e5b05eb15edb05019:1, Name: redbullfourthphase, ID: f054e085e8d38c0a0e63a472b033e42d437a4014
2022-06-09 13:01:18.640 [INF] MAIN: RAM: using 2.8 GB with 2.7 available, DISK: using 122.3 GB with 785.7 available
2022-06-09 13:01:33.753 [INF] LBRY: Spending claim but missing existing claim with TXO d549351f731019573d921f5db8e2844449edf3011073b3e5f4ce9b0d9aee5490:1, Name: timcast-sweden-day1, ID: 247895d4b9389b74038ea5a4fd807cafc97ede53
2022-06-09 13:01:37.968 [INF] LBRY: Spending claim but missing existing claim with TXO 36a719a156a1df178531f3c712b8b37f8e7cc3b36eea532df961229d936272a1:0, Name: two, ID: bb6168c9a56286999c7c938c7b8c5afb221d38d0
2022-06-09 13:01:58.644 [INF] MAIN: RAM: using 3.0 GB with 2.7 available, DISK: using 122.3 GB with 785.7 available
2022-06-09 13:02:17.393 [INF] CHAN: Loading block index...
2022-06-09 13:02:31.779 [INF] CHAN: Chain state (height 1173692, hash 4554e96707dd2a5af693e838909198b054c93341143bd6483de95cbf81c3a0cd, totaltx 80332019, work 44494961111535296297409)

After:

swdev1@Mac-mini lbcd % ./lbcd --memprofile=./after7.mem --cpuprofile=./after7.cpu  
2022-06-09 13:09:19.742 [INF] MAIN: Version 0.0.0-local.0+787098e2a2f4692c7c3e6eab1a1ba25d00a54ae0-dirty
2022-06-09 13:09:19.743 [INF] MAIN: Loading block database from '/Users/swdev1/Library/Application Support/Lbcd/data/mainnet/blocks_ffldb'
2022-06-09 13:09:19.995 [INF] MAIN: Block database loaded
2022-06-09 13:09:22.997 [INF] SRVR: Can't discover UPnP-enabled device: write udp4 0.0.0.0:54877->239.255.255.250:1900: i/o timeout
2022-06-09 13:09:23.005 [INF] INDX: Transaction index is enabled
2022-06-09 13:09:23.007 [INF] INDX: Committed filter index is enabled
2022-06-09 13:09:23.548 [INF] LBRY: Normalizing strings via Go. Casefold and NFD table versions: 11.0.0 (from ICU 63.2)
2022-06-09 13:09:23.548 [INF] LBRY: Building the entire claim trie in RAM...
2022-06-09 13:09:26.987 [INF] LBRY: Spending claim but missing existing claim with TXO bd183d94dc0b2c38d500838f4ab7c93b643123f46e87214d3e37f5e9e0d4baf5:0, Name: 1791l-trumpcnn, ID: 6a28cbbe64c3c54113770705c928e80a138ddae9
2022-06-09 13:10:00.234 [INF] MAIN: RAM: using 1.4 GB with 2.7 available, DISK: using 122.3 GB with 786.8 available
2022-06-09 13:10:16.859 [INF] LBRY: Spending claim but missing existing claim with TXO 5dff52209029a63547f8805c3e92fce87e3744a15f6539a12011fe0c421ca132:0, Name: ggminingpoolxzc, ID: 3fa8d7113bd4873e79ec02019bea3c7840f0deee
2022-06-09 13:10:16.859 [INF] LBRY: Spending claim but missing existing claim with TXO 546a1b99218f5935d6d11d6a5632ba199b24d6dbb6c07e75bea1089eee23987d:0, Name: ggminingpool-xzc, ID: 0b9e8ea179d6f68d3b37ab0e636af6ab1b93b52e
2022-06-09 13:10:40.122 [INF] MAIN: RAM: using 2.4 GB with 2.7 available, DISK: using 122.3 GB with 786.8 available
2022-06-09 13:10:48.349 [INF] LBRY: Spending claim but missing existing claim with TXO 022a25b42e0327d6bf7a741cd3bae34404453549635d916e5b05eb15edb05019:1, Name: redbullfourthphase, ID: f054e085e8d38c0a0e63a472b033e42d437a4014
2022-06-09 13:11:01.676 [INF] LBRY: Spending claim but missing existing claim with TXO d549351f731019573d921f5db8e2844449edf3011073b3e5f4ce9b0d9aee5490:1, Name: timcast-sweden-day1, ID: 247895d4b9389b74038ea5a4fd807cafc97ede53
2022-06-09 13:11:04.191 [INF] LBRY: Spending claim but missing existing claim with TXO 36a719a156a1df178531f3c712b8b37f8e7cc3b36eea532df961229d936272a1:0, Name: two, ID: bb6168c9a56286999c7c938c7b8c5afb221d38d0
2022-06-09 13:11:20.361 [INF] MAIN: RAM: using 3.0 GB with 2.7 available, DISK: using 122.3 GB with 785.7 available
2022-06-09 13:11:33.715 [INF] CHAN: Loading block index...
2022-06-09 13:11:45.898 [INF] CHAN: Chain state (height 1173695, hash 2bda7b7cd69805029b02cf66dc34e92418843b00310bc90c38b12d36f5bb8d6a, totaltx 80332222, work 44495327569169772684103)
roylee17 commented 2 years ago

Hm.. a re-run does perform closer to what it was. But no significant changes though. 

2022-06-09 18:30:16.146 [INF] MAIN: Version 0.0.0-local.0+787098e2a2f4692c7c3e6eab1a1ba25d00a54ae0
2022-06-09 18:34:43.958 [INF] CHAN: Loading block index...

Attach the profiled data.

after.zip

Does it show improvements on the sync time in your environment?

moodyjon commented 2 years ago

Yes, it's showing claimtrie build time improvement (2min after, 3min before), but not overall sync time AFAICT. It takes me many days to sync from a remote node.

Here is my run: after2.zip

I tried to get a comparable one with 317s wall clock runtime. CPU profiles are very different. Yours shows a lot more CPU time consumed in GC, makeNameHashNext func1 and func2. The descendants of sstable Reader.readBlock() are very different. Some stuff like Sha256 does not even show up in mine under the default pprof options.

My hardware specs (16GB RAM 2TB SSD variant): https://en.wikipedia.org/wiki/Mac_Mini#Technical_specifications_5

My guess is you've reached some hardware limitation (RAM throughput/latency?), so demonstrating improvement becomes impossible. Just like I can't see any improvement in overall sync time because fetching blocks from a remote node is the limiting factor.

I assume you are syncing blocks over LAN. What is your test hardware? SSD? CPUs? RAM type? What about isolation from other load? Is this a virtual machine?

moodyjon commented 2 years ago

Regarding sha256 performance discrepancy: https://github.com/golang/go/tree/master/src/crypto/sha256

The performance you get depends on availability of special CPU instructions.

go tool pprof --svg --show_from sha256 XXX.cpu

Mine (arm64): profile006

Yours (???): profile007

moodyjon commented 2 years ago

Focusing on GC scanobject:

go tool pprof --svg --show_from scanobject XXX.cpu

Mine (arm64): profile008

Yours (???): profile009

I don't see anything obviously architecture-specific. But yours is registering a lot more time spent. The mem allocs report is ~28GB for yours and 26GB for mine, so GC should be triggering about the same number of times.

kauffj commented 2 years ago

Thanks for your contributions @moodyjon!

Can you send me an email at jeremy@lbry.com? You're welcome to stay anonymous if that's your preference.

moodyjon commented 2 years ago

Demote to draft status as this is a sensitive code area. There is an outstanding bug being investigated at this time:

https://github.com/lbryio/lbcd/issues/71