Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Reduce claimtrie temp allocs. #51

Draft
wants to merge 4 commits into
base: master
Choose a base branch
from

Conversation

moodyjon
Copy link
Collaborator

@moodyjon moodyjon commented Jun 6, 2022

Unbundled from PR #43

See that for usage/testing.

Based on work by @BrannonKing in mem_pressure_try_2 and reduce_memory_pressure.

The commits 8482890 and 787098e are newly added to claw back costs from node cache and node.Clone().

moodyjon and others added 4 commits June 6, 2022 17:56
Return []Changes and a "closer" func to return them to Pool.
Update tests for LoadChanges new return values.
…tring entails lots of temporary allocations.
@coveralls
Copy link

Pull Request Test Coverage Report for Build 2450737946

  • 71 of 112 (63.39%) changed or added relevant lines in 9 files are covered.
  • 15 unchanged lines in 5 files lost coverage.
  • Overall coverage increased (+0.002%) to 51.818%

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%
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%
Totals Coverage Status
Change from base Build 2450492318: 0.002%
Covered Lines: 22490
Relevant Lines: 43402

💛 - Coveralls

@roylee17
Copy link
Collaborator

roylee17 commented Jun 9, 2022

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
Copy link
Collaborator Author

moodyjon commented Jun 9, 2022

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
Copy link
Collaborator

roylee17 commented Jun 9, 2022

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
Copy link
Collaborator Author

moodyjon commented Jun 10, 2022

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
Copy link
Collaborator Author

moodyjon commented Jun 10, 2022

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
Copy link
Collaborator Author

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
Copy link
Member

kauffj commented Jun 13, 2022

Thanks for your contributions @moodyjon!

Can you send me an email at [email protected]? You're welcome to stay anonymous if that's your preference.

@kauffj kauffj requested a review from roylee17 July 11, 2022 15:22
@lbry-bot lbry-bot assigned roylee17 and unassigned roylee17 Jul 11, 2022
@moodyjon moodyjon marked this pull request as draft July 28, 2022 01:51
@moodyjon
Copy link
Collaborator Author

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

#71

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

5 participants