kvdb+channeldb: speed up graph cache #6111

joostjager · 2021-12-23T09:30:49Z

This PR adds ForAll to kvdb to allow for efficient range queries. The graph cache loader is rewritten to take advantage of this new method, improving loading time on my machine by approx 150x.

Fixes #6041
Fixes #6107

joostjager · 2021-12-23T09:42:45Z

@guggero @bhandras looking for concept ack

bhandras · 2021-12-23T09:47:00Z

kvdb/postgres/readwrite_bucket.go

+
+func (b *readWriteBucket) Prefetch(paths ...[]string) {}
+
+func (b *readWriteBucket) ForEachFast(cb func(k, v []byte) error) error {


How about naming this ForAll? Since it'd be a valid question to ask why ForEach is not as fast as ForEachFast.

Hm naming is difficult. ForEach and ForAll also sounds like the same thing to me. The functional difference is that the faster one doesn't allow further queries in the callback. Maybe that can somehow be expressed in the name.

Aha, I missed the not allowing more queries in the callback part. What I've expected instead is that it'll simply batch fetch more items at once under the hood.

Also weighing in on the naming discussion :) How about ForEachUnordered (the main promise of the cursor based ForEach is the sort by key and seek functionality, right?) or ForEachNative (implying that the underlying implementation might decide on the best approach for executing it, could also mention no specific ordering is guaranteed).

This is what I wanted to do originally with the cursor. In that case, no new method is needed either. But I remember there was a problem with that, only what was it?

I don't think it was writing to the bucket inside the loop, because that is already not supported with bbolt - or is it? Don't we have these iterate and delete loops? We can also only do the optimization for read-only transactions.

Or alternatively we can use start (index). That would translate to OFFSET .. LIMIT .. in sql.

I think it is still the case with GetAllPaginated that the callback isn't allowed to do other queries, so maybe this is just scope creep beyond a single ForAll?

Or maybe your idea is to not have a callback with GetAllPaginated and return []KV ?

Interesting. So this would also allow nested keys to be retrieved in a single query. And besides limit you'd also want to specify some kind of fromKey right?

Yes.

Or alternatively we can use start (index). That would translate to OFFSET .. LIMIT .. in sql.

I think fromKey is more "portable".

I think it is still the case with GetAllPaginated that the callback isn't allowed to do other queries, so maybe this is just scope creep beyond a single ForAll?

Maybe we should go even further and add it to the kvdb.DB interface as an extension. That'd indicate that it's a pure optimization thing and is not needed to be compatible with the rest of the kvdb interfaces.

Or maybe your idea is to not have a callback with GetAllPaginated and return []KV ?

Yeah, sgtm!

I get the idea, but after sleeping on it, I think we should do the minimum that is necessary at this point. Just fix the immediate problem with postgres startup loading.

If another critical optimization comes up, we can look at what is needed for that. I don't expect that updating the ForAllNative that we use now to something slightly different in the future will be a problem.

bhandras · 2021-12-23T09:47:21Z

Concept ACK.

guggero

Concept ACK from my side as well.

I'm asking myself why the ForEach would be implemented by using cursors in the first place? I get that this is coming from porting over the bbolt bucket logic. But thinking about it now, is there ever a reason to use cursors instead of basically doing what ForEachFast does now (but maybe with an ORDER BY clause)?

guggero · 2021-12-23T10:49:25Z

kvdb/postgres/readwrite_bucket.go

+
+func (b *readWriteBucket) Prefetch(paths ...[]string) {}
+
+func (b *readWriteBucket) ForEachFast(cb func(k, v []byte) error) error {


Also weighing in on the naming discussion :) How about ForEachUnordered (the main promise of the cursor based ForEach is the sort by key and seek functionality, right?) or ForEachNative (implying that the underlying implementation might decide on the best approach for executing it, could also mention no specific ordering is guaranteed).

joostjager · 2021-12-23T12:22:31Z

I'm asking myself why the ForEach would be implemented by using cursors in the first place? I get that this is coming from porting over the bbolt bucket logic. But thinking about it now, is there ever a reason to use cursors instead of basically doing what ForEachFast does now (but maybe with an ORDER BY clause)?

The reason to use a cursor (or really a single query per row) is that it wouldn't be possible otherwise to query within the callback. While the SELECT is running, nothing else can be done in that same tx.

kvdb/interface.go

joostjager · 2021-12-24T12:26:25Z

Cleaned up PR, added test coverage for graph cache population.

joostjager · 2021-12-26T14:43:57Z

I discovered that DescribeGraph suffers from the same slowness as the cache loading. Restructured the code to use the efficient ForEachChannel also for DescribeGraph. I briefly worried about memory usage on low end devices, but then realized that DescribeGraph is already loading the full graph in memory for grpc serialization anyway. Perhaps a streaming version would be more appropriate if memory usage is really a concern.

lightninglabs-deploy · 2022-01-03T00:21:32Z

@bhandras: review reminder
@guggero: review reminder

guggero

Did a first level pass. Very nice performance improvement!
Will run some performance and other manual tests during the next pass.

Also, can be rebased now that #6116 is merged to fix the postgres itests.

channeldb/graph.go

channeldb/graph_test.go

docs/release-notes/release-notes-0.14.2.md

channeldb/graph.go

Allows for pure deserialization without depending on a database connection.

guggero · 2022-01-12T18:20:12Z

So previously the problem was the number of allocations and garbage collection of those, and not so much the total memory requirement?

Yes, the problem for low-ish memory environments was that there was a huge initial spike in memory but then most of it could be garbage collected. So a lot of throw-away instances/allocations.

guggero · 2022-01-13T11:06:07Z

I ran some tests (imported a mainnet channel graph into a regtest node with the help of #6149).

Current master (`ed511bb`)

Database open time: 2m 8s

Memory profile:

Showing nodes accounting for 45.52MB, 85.78% of 53.07MB total
Showing top 10 nodes out of 124
      flat  flat%   sum%        cum   cum%
   10.50MB 19.79% 19.79%    10.50MB 19.79%  github.com/lightningnetwork/lnd/channeldb.NewCachedPolicy
      10MB 18.85% 38.63%    26.02MB 49.04%  github.com/lightningnetwork/lnd/channeldb.(*GraphCache).AddChannel
    7.01MB 13.20% 51.84%     7.01MB 13.20%  runtime.allocm
    5.52MB 10.41% 62.24%     5.52MB 10.41%  github.com/lightningnetwork/lnd/channeldb.(*GraphCache).updateOrAddEdge
    4.39MB  8.26% 70.51%     4.39MB  8.26%  github.com/lightningnetwork/lnd/channeldb.NewGraphCache
    2.66MB  5.01% 75.52%     2.66MB  5.01%  google.golang.org/grpc/internal/transport.newBufWriter
    2.28MB  4.30% 79.82%     2.28MB  4.30%  github.com/lightningnetwork/lnd/channeldb.newRejectCache
    1.11MB  2.09% 81.91%     1.11MB  2.09%  github.com/btcsuite/btcd/btcec.loadS256BytePoints
    1.03MB  1.94% 83.85%     1.03MB  1.94%  bufio.NewReaderSize
    1.03MB  1.93% 85.78%     1.03MB  1.93%  regexp/syntax.(*compiler).inst

This PR (0cca4549)

Database open time: 3.3s

Memory profile:

Showing nodes accounting for 78MB, 93.68% of 83.27MB total
Showing top 10 nodes out of 126
      flat  flat%   sum%        cum   cum%
   45.01MB 54.05% 54.05%    47.01MB 56.45%  github.com/lightningnetwork/lnd/channeldb.deserializeChanEdgePolicyRaw
   13.55MB 16.27% 70.32%    60.55MB 72.72%  github.com/lightningnetwork/lnd/channeldb.(*ChannelGraph).getChannelMap.func1
       5MB  6.01% 76.33%        5MB  6.01%  runtime.allocm
    4.39MB  5.27% 81.60%     4.39MB  5.27%  github.com/lightningnetwork/lnd/channeldb.NewGraphCache
    2.66MB  3.19% 84.79%     2.66MB  3.19%  google.golang.org/grpc/internal/transport.newBufWriter
    2.28MB  2.74% 87.53%     2.28MB  2.74%  github.com/lightningnetwork/lnd/channeldb.newRejectCache
    1.50MB  1.80% 89.34%     1.50MB  1.80%  runtime.malg
    1.50MB  1.80% 91.14%     1.50MB  1.80%  github.com/btcsuite/btcd/wire.ReadVarBytes
    1.11MB  1.33% 92.47%     1.11MB  1.33%  github.com/btcsuite/btcd/btcec.loadS256BytePoints
    1.01MB  1.21% 93.68%     1.01MB  1.21%  github.com/jackc/chunkreader/v2.(*ChunkReader).newBuf

So while this PR massively decreases the time to initialize the graph cache (and also fixes the DescribeGraph RPC being very slow), this comes at some allocation cost. I assume this is because we have yet another layer of cache (the channelMap) which can be seen in the profile. But that is memory that should be garbage collected eventually.

While I think we could still optimize the memory usage (by effectively making it possible to re-use the channelMap for the graph cache directly), I don't think it's worth doing so at this point. Mobile users for example won't be turning on the graph cache in the first place to save on memory, so they won't be running into this increased use anyway (unless DescribeGraph is used).

bhandras

LGTM 👍

bhandras · 2022-01-13T15:52:01Z

channeldb/graph.go

+
+	err := kvdb.ForAll(edges, func(k, edgeBytes []byte) error {
+		// Skip embedded buckets.
+		if bytes.Equal(k, edgeIndexBucket) ||


I'm thinking maybe a more future proof way to avoid iterating the embedded buckets is to check if the value is nil. Not perfect either, but AFAIK there's no nil valued key in this bucket other than sub buckets. The unknown policy is an empty slice ([]byte{}) so that would work too.

I made it explicit as a sanity check that there is nothing unexpected in this bucket. But you could also consider it less future proof to not skip over unexpected data.

bhandras · 2022-01-13T16:10:50Z

channeldb/graph.go


 	// Skip ahead:
 	// - LastUpdate (8 bytes)
-	if _, err := r.Read(node.nodeScratch[:]); err != nil {
-		return err
+	if _, err := r.Read(nodeScratch[:]); err != nil {


I digged into this a bit and I think many of the allocations might be just due to us using the io.Reader interface here, since both Read and ReadFull do allocate. We may in the future want to switch to just passing around the byte slices to these deserialize functions and just copy out the important parts.

Seems related to: #4884

joostjager · 2022-01-13T16:13:24Z

@guggero at what point exactly did you insert the memory profile write action? Haven't used the mem profiler much and trying to repro.

[update]
I can repro now, but only if I don't garbage collect before writing the heap profile. Did you call the GC? Otherwise I think that it is a bit more random what you're getting, depending on when the gc last ran.

guggero · 2022-01-13T16:19:07Z

I extracted the memory profile through HTTP (using --profile=1111) so I didn't explicitly call GC.

joostjager · 2022-01-13T16:22:50Z

So you timed it somewhere during the cache population phase? As mentioned, I know embarrassing little about mem profiling, but will what you did get you the info you're looking for?

guggero · 2022-01-13T16:37:27Z

I waited until the log said the cache was filled. Then I ran curl http://localhost:1111/debug/pprof/heap > heap-6111-done.prof followed by go tool pprof heap-6111-done.prof where I typed top to get that output I posted.
I'm also not extremely proficient with profiling, maybe I'm doing it incorrectly (or at the wrong time)...

Roasbeef · 2022-01-13T23:21:54Z

Does this PR also need #6136? Or will that one be what ultimately gets merged?

Roasbeef · 2022-01-13T23:25:40Z

I waited until the log said the cache was filled. Then I ran curl http://localhost:1111/debug/pprof/heap > heap-6111-done.prof followed by go tool pprof heap-6111-done.prof where I typed top to get that output I posted.

Alternatively you could do something like this @joostjager:

go tool pprof --http=localhost:8083 http://localhost:5000/debug/pprof/heap

Assuming --profile=5000 is set, this'll open up the nicer web based UI that also can give you break downs like the above, but with svg's and flame graphs, etc.

Timing is somewhat tricky as Oliver mentions since it's based on that logging point. Alternatively you could rig lnd to shut down as soon as the graph is populated, and set the cpuprofile (I think this'll also write the memory as well?) and use oli's command above.

Roasbeef · 2022-01-13T23:30:11Z

kvdb/postgres/readwrite_bucket.go

+	defer cancel()
+
+	for rows.Next() {
+		var key, value []byte


Declare at the top of this loop, with the assumption that the caller won't use the byte slices outside of the scope of the closure? A similar assumption exists w.r.t the way bbolt works.

For ForEach, the bbolt docs say:

Please note that keys and values in ForEach() are only valid while the transaction is open. If you need to use a key or value outside of the transaction, you must use copy() to copy it to another byte slice.

So the scope for this is wider than just the callback?

channeldb/graph.go

Roasbeef · 2022-01-13T23:36:28Z

channeldb/graph.go

+
+		// First, load all edges in memory indexed by node and channel
+		// id.
+		channelMap, err := c.getChannelMap(edges)


This impacts all other callers of this method (which ideally should just be hitting the main graph cache instead?) to optimize for only the start up case.

There are no other callers besides graph cache population and DescribeGraph which needs this optimization as well.

It can't hit the main graph cache, because that only contains a subset of the graph data needed for pathfinding.

and DescribeGraph which needs this optimization as well.
FWIW we now have in-memory caching of the proto serialization now here.

Roasbeef · 2022-01-13T23:37:53Z

channeldb/graph.go


 	// Skip ahead:
 	// - LastUpdate (8 bytes)
-	if _, err := r.Read(node.nodeScratch[:]); err != nil {
-		return err
+	if _, err := r.Read(nodeScratch[:]); err != nil {


Seems related to: #4884

channeldb/graph.go

Roasbeef

hit wrong button...

Roasbeef · 2022-01-13T23:40:37Z

Another heavy call that shows up in profiles: func (c *ChannelGraph) FilterKnownChanIDs. It is called with 85k channels during initial sync.

Yeah this can just hit the channel graph cache instead. Prob worthy of spinning out into another issue. Alternatively it can used a bloom filter, not that big of a deal if we fetch some stuff we don't actually need.

Roasbeef · 2022-01-13T23:53:42Z

channeldb/graph.go

 			},
 		)
 		if err != nil {
 			return nil, err
 		}

+		err = g.ForEachChannel(func(info *ChannelEdgeInfo,


Related to my comment elsewhere: perhaps we just want to have a new private forEachChannelX method here that skips the intermediate map and inserts directly into the cache?

joostjager · 2022-01-14T12:30:06Z

Timing is somewhat tricky as Oliver mentions since it's based on that logging point. Alternatively you could rig lnd to shut down as soon as the graph is populated, and set the cpuprofile (I think this'll also write the memory as well?) and use oli's command above.

Yes, this is what I did. I saved a mem profile right after graph population. But interestingly some allocations were already gone. Perhaps because the go compiler already knew that I wasn't going to use that data anymore even though the function hadn't returned yet.

I guess what we really want to know here is peak allocations rather than a snap shot.

In this commit, we modify the implementation of ForEachChannel to utilize the new kvdb method ForAll. This greatly reduces the number of round-trips to the database needed to iterate over all channels in the graph.

Allows cacheableNode to be used outside of the callback. This is a preparation for optimization of the graph cache population.

Use the optimized ForEachChannel method to reduce the graph cache loading time.

joostjager · 2022-01-14T15:27:02Z

Does this PR also need #6136? Or will that one be what ultimately gets merged?

This PR doesn't need #6136

bhandras · 2022-01-14T15:55:47Z

Does this PR also need #6136? Or will that one be what ultimately gets merged?

We can cherry-pick it into this PR, however it's OK to separate them too. See #6111 (comment)

Roasbeef

LGTM ☄️

Roasbeef · 2022-01-21T01:34:00Z

channeldb/graph.go

+
+		// First, load all edges in memory indexed by node and channel
+		// id.
+		channelMap, err := c.getChannelMap(edges)


and DescribeGraph which needs this optimization as well.
FWIW we now have in-memory caching of the proto serialization now here.

joostjager · 2022-01-25T09:21:41Z

@guggero @bhandras the repo needs a kvdb v1.3.0 tag

guggero · 2022-01-25T09:40:49Z

Ah right, thanks for the reminder! Pushed the tag now.

joostjager mentioned this pull request Dec 23, 2021

In-memory graph population is very slow when running with Postgres backend #6107

Closed

joostjager requested review from bhandras and guggero December 23, 2021 09:42

bhandras reviewed Dec 23, 2021

View reviewed changes

joostjager force-pushed the cache-loading branch from 2fc8656 to cd403eb Compare December 23, 2021 10:19

guggero reviewed Dec 23, 2021

View reviewed changes

joostjager force-pushed the cache-loading branch 3 times, most recently from 0d43346 to 6270ba1 Compare December 24, 2021 12:23

joostjager commented Dec 24, 2021

View reviewed changes

kvdb/interface.go Show resolved Hide resolved

joostjager force-pushed the cache-loading branch from 6270ba1 to 91ab9ea Compare December 24, 2021 12:25

joostjager requested review from bhandras and guggero December 24, 2021 12:26

joostjager force-pushed the cache-loading branch 3 times, most recently from 4bd2ad3 to f3802e2 Compare December 26, 2021 14:41

joostjager mentioned this pull request Dec 27, 2021

Error when restoring a wallet on a fresh LND install configured with postgresql db backend #6041

Closed

joostjager marked this pull request as ready for review December 27, 2021 08:44

Roasbeef added optimization postgres labels Jan 3, 2022

Roasbeef added this to the v0.14.2 milestone Jan 3, 2022

Roasbeef added database Related to the database/storage of LND graph labels Jan 3, 2022

guggero reviewed Jan 4, 2022

View reviewed changes

channeldb: extract deserializeChanEdgePolicyRaw

54324d5

Allows for pure deserialization without depending on a database connection.

joostjager force-pushed the cache-loading branch from 4003cb1 to 0cca454 Compare January 12, 2022 18:12

guggero approved these changes Jan 13, 2022

View reviewed changes

bhandras approved these changes Jan 13, 2022

View reviewed changes

Roasbeef reviewed Jan 13, 2022

View reviewed changes

Roasbeef requested changes Jan 13, 2022

View reviewed changes

Roasbeef reviewed Jan 13, 2022

View reviewed changes

joostjager added 3 commits January 14, 2022 14:57

channeldb: optimize ForEachChannel

cb47036

In this commit, we modify the implementation of ForEachChannel to utilize the new kvdb method ForAll. This greatly reduces the number of round-trips to the database needed to iterate over all channels in the graph.

channeldb: reallocate node in ForEachNodeCacheable

2e2229a

Allows cacheableNode to be used outside of the callback. This is a preparation for optimization of the graph cache population.

channeldb: speed up graph cache loading

352008a

Use the optimized ForEachChannel method to reduce the graph cache loading time.

joostjager force-pushed the cache-loading branch from 0cca454 to 352008a Compare January 14, 2022 13:57

joostjager requested a review from Roasbeef January 14, 2022 13:58

Roasbeef mentioned this pull request Jan 21, 2022

channeldb: make channel graph population async #6187

Open

Roasbeef approved these changes Jan 21, 2022

View reviewed changes

Roasbeef merged commit d67e6d5 into lightningnetwork:master Jan 21, 2022

guggero mentioned this pull request Jan 26, 2022

multi: create v0.14.2-beta-rc1 branch #6201

Merged


		func (b *readWriteBucket) Prefetch(paths ...[]string) {}

		func (b *readWriteBucket) ForEachFast(cb func(k, v []byte) error) error {

kvdb+channeldb: speed up graph cache #6111

kvdb+channeldb: speed up graph cache #6111

Conversation

joostjager commented Dec 23, 2021 • edited by Roasbeef Loading

joostjager commented Dec 23, 2021

Choose a reason for hiding this comment

joostjager Dec 23, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager Dec 23, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager Dec 23, 2021 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

bhandras commented Dec 23, 2021

guggero left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager commented Dec 23, 2021

joostjager commented Dec 24, 2021

joostjager commented Dec 26, 2021

lightninglabs-deploy commented Jan 3, 2022

guggero left a comment

Choose a reason for hiding this comment

guggero commented Jan 12, 2022

guggero commented Jan 13, 2022

Current master (ed511bb)

This PR (0cca4549)

bhandras left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager commented Jan 13, 2022 • edited Loading

guggero commented Jan 13, 2022

joostjager commented Jan 13, 2022

guggero commented Jan 13, 2022

Roasbeef commented Jan 13, 2022

Roasbeef commented Jan 13, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager Jan 14, 2022 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Roasbeef left a comment

Choose a reason for hiding this comment

Roasbeef commented Jan 13, 2022

Choose a reason for hiding this comment

joostjager commented Jan 14, 2022

joostjager commented Jan 14, 2022

bhandras commented Jan 14, 2022

Roasbeef left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

joostjager commented Jan 25, 2022

guggero commented Jan 25, 2022

joostjager commented Dec 23, 2021 •

edited by Roasbeef

Loading

joostjager Dec 23, 2021 •

edited

Loading

joostjager Dec 23, 2021 •

edited

Loading

joostjager Dec 23, 2021 •

edited

Loading

Current master (`ed511bb`)

joostjager commented Jan 13, 2022 •

edited

Loading

joostjager Jan 14, 2022 •

edited

Loading