gossip: bloated network graph, slow to prune

[phlip9]

To set the stage, our LSP (running v0.1.3) was getting progressively more and more unhealthy. After investigating some issues with high CPU from gossip, it turns out our NetworkGraph was not actually getting pruned--or not quickly enough. The LSP accumulated a 185MiB NetworkGraph with 47k nodes and 309k channels, over 3.5x the live network graph size.

For context, we've been using utxo_lookup: None for P2PGossipSync. I think when the code was written, there was no async UtxoLookup. We've been relying on NetworkGraph::remove_stale_channels_and_tracking to prune the network graph.

There might also be something degenerate going on when our user nodes pull their graph from the LSP and then proceed to P2PGossipSync with the LSP. Or when the LSP tries to gossip it's ancient, bloated graph with other peers. Turning off user node gossip sync is definitely a priority, since it seems to be causing problems.

Curious what was going on, I pulled the raw network graph off the node and poked around (lexe-lsp.network_graph.20250912.bin.zip if you're curious). 250k channels already had their channel updates pruned (i.e., both one_to_two: None and two_to_one: None), but the announcement_received_timestamp's were still not prunable.

Of these channels with pruned updates but a fresh announcement_recevied_timestamp, there was kind of a weird distribution where the most channels last received an announcement around the same time, 8 days ago. Not sure what that's about...

Anyway, desperate to get prod healthy again, I cooked this up: graph: reduce time-to-prune for chans w/ no recent announce to 5d. The LSP is also now forced to prune immediately at startup. The diff is hacky, but it at least got the LSP healthy again. The first prune took quite a while, with later prunes going much faster:

Pruned network graph in (161.474806812 s) nodes=18373 pruned_nodes=28540 channels=57560 pruned_channels=251810
Pruned network graph in (39.365067000 ms) nodes=18381 pruned_nodes=0 channels=57578 pruned_channels=2

If anyone has any thoughts on what might be causing the graph to get so bloated, that would be appreciated. If necessary, we can also impl UtxoLookup now that it's async. The 160s prune also looks worth optimizing.

[TheBlueMatt]

there was kind of a weird distribution where the most channels last received an announcement around the same time, 8 days ago. Not sure what that's about...

Is it possible this was the last time you restarted? On restart we may fetch things from peers which would be pruned later but which we don't yet have enough information to know that we can prune them (yay lightning...). It's also very possible that some nodes are sending you not only stale crap (which is the default on some other/older nodes) but closed crap as well, we've had reports of that in the past.

As for the performance issues of it, that's somewhat surprising. We shouldn't have any problem with 3x the normal graph size. Can you clarify somewhat the issues you saw?

[phlip9]

Is it possible this was the last time you restarted?

The LSP's been restarting more frequently the last few weeks, crashing every ~12 hours. Though one potentially confounding issue here is that past a certain size our network graph persists were timing out, until we fixed that.

Maybe some more context:

A few weeks ago, the LSP was similarly unhealthy, effectively crashing a few minutes after startup. We bumped the available memory by 1.5 GiB and that at least got it semi-healthy, though still crashing about every 12 hours or so. It got progressively more unhealthy until Friday. A user node connecting would cause the LSP CPU usage to spike to 100-110% for a few minutes, then it would lock up and our watchdog would kill it.

After landing the fix to properly prune the network graph, the LSP has been perfectly stable; zero crashes since then.

As for the perf issues, I wish I had some harder numbers to share. At least for the non-Lexe related weirdness, we still had high CPU usage when running the LSP with Lexe user nodes disabled. Right after startup, LSP CPU usage would spike to 30-40% for ~30 min, with no clear activity other than maybe gossiping with external peers. Then it would settle down to 2-5% CPU. After pruning the graph the LSP is just consistently 2-5% CPU, even after startup.

The LSP lock up might've also been caused by the ~161s it took to prune the graph, which maybe starved other tasks or deadlocked with some gossip logic.

[TheBlueMatt]

Hmm, yea, I mean that sadly doesn't really fully explain the performance cost here. Taking the graph you provided I can run remove_stale_channels_and_tracking in 1 second in an unoptimized test build and 300ms in a --release test build (which should do strictly more work than you would have done at the time you pulled it, as things are now older).

One thing that remove_stale_channels_and_tracking will do, however, is write a lot of logs at GOSSIP level. If your logger is fairly slow its probably pretty easy to rack up a lot of time there.

It does, however, spend nearly all its time while pruning shifting a rather large Vec down after removing items in the middle of it. The resulting memory access bottlenecks are why there's only a ~3x difference between unoptimized and optimized builds, are SGX memory accesses that much more expensive than normal? It shouldn't result in any page faults cause its just shifting memory down that the process already owned.

[phlip9]

Thanks for testing it out. Maybe we're just hitting some nasty edge case in the rust-sgx runtime/platform for the pruning perf issue.

One thing that remove_stale_channels_and_tracking will do, however, is write a lot of logs at GOSSIP level. If your logger is fairly slow its probably pretty easy to rack up a lot of time there.

I don't think that should cause issues, since GOSSIP or TRACE level logs aren't enabled. I don't think our LDK->tracing log adapter should be doing any meaningful work if the log level is disabled: https://github.com/lexe-app/lexe-public/blob/master/lexe-ln/src/logger.rs#L218. Though if something is calling Instant::now() even in the disabled log path, that would be a problem for us. Don't see it though.

It does, however, spend nearly all its time while pruning shifting a rather large Vec down after removing items in the middle of it.

Hmm, maybe we're hitting a degenerate case in the slow/minimalist SpinMutex<Dlmalloc> allocator that ships in rust-sgx by default. The spin-lock is it's own problem, but the pruning is done early in startup, before there should be any contention I believe.

The resulting memory access bottlenecks are why there's only a ~3x difference between unoptimized and optimized builds, are SGX memory accesses that much more expensive than normal? It shouldn't result in any page faults cause its just shifting memory down that the process already owned.

There's definitely an extra cost, but I don't think it should be that high. Sounds like I need to do some perf experiments though...

[tnull]

@phlip9 I assume it's entirely unnecessary to ask this, but just to confirm: are you building your LSP node with --release? Asking as on debug mode we're running / used to run a lot of additional sanity checks on the network graph that could be CPU/memory intensive.

[TheBlueMatt]

Though if something is calling Instant::now() even in the disabled log path, that would be a problem for us. Don't see it though.

If you build LDK without the std feature (which you should be, I think!), LDK will never call Instant::now.

Hmm, maybe we're hitting a degenerate case in the slow/minimalist SpinMutex allocator that ships in rust-sgx by default. The spin-lock is it's own problem, but the pruning is done early in startup, before there should be any contention I believe.

It shouldn't be hitting the allocator for this - Vec::remove should never re-allocate, only shift elements down retaining the existing capacity :/.

[phlip9]

I assume it's entirely unnecessary to ask this, but just to confirm: are you building your LSP node with --release

Yep, we definitely use a release profile https://github.com/lexe-app/lexe/blob/7939b3b448f7c451b2c70af25bf54ae3c59a12bf/public/Cargo.toml#L343. It doesn't seem like -O2 is an issue here either.

If you build LDK without the std feature (which you should be, I think!)

I believe we do use the std feature since we enable default features for the lightning crate.

It shouldn't be hitting the allocator for this - Vec::remove should never re-allocate

Yeah it doesn't look like either HashMap or Vec removes will try to shrink. Seems less likely, but maybe the nodes/channels getting dropped themselves drop some Vecs inside, which cause lots of small deallocs...

[TheBlueMatt]

I believe we do use the std feature since we enable default features for the lightning crate.

Oh interesting. I thought time-fetching std functions were an issue in SGX? FWIW, the lightning crate without std doesn't really disable anything except time.

Yeah it doesn't look like either HashMap or Vec removes will try to shrink. Seems less likely, but maybe the nodes/channels getting dropped themselves drop some Vecs inside, which cause lots of small deallocs...

Hmm, maybe? This does sound like it needs some profiling inside SGX :/

[phlip9]

Hmm, yea, I mean that sadly doesn't really fully explain the performance cost here. Taking the graph you provided I can run remove_stale_channels_and_tracking in 1 second in an unoptimized test build and 300ms in a --release test build (which should do strictly more work than you would have done at the time you pulled it, as things are now older).

Quick sanity check, do you know if this actually pruned the big block of channels? I think you may need to set the current timestamp into the future

[TheBlueMatt]

🤦 #4080

[phlip9]

HUGE, 22x faster should solve our problem <3