Investigate busiest tasks per tokio-console

[conradoplg]

Motivation

tokio-console, for which we added support in #4519, is reporting a bunch of busy tasks but it's not clear what they are. We should investigate it.

On a syncing-pre-checkpoint node, it's looking like this in my machine:

The target is tokio::task::blocking and fields are

│fn=tokio::runtime::thread_pool::worker::Launch::launch::{{closure}}                                                                                                                                              │
│kind=blocking                                                                                                                                                                                                    │
│task.id=2                                                                                                                                                                                                        │
│spawn.location=<cargo>/tokio-1.18.2/src/runtime/thread_pool/worker.rs:358:13 

CPU usage seems to be at 200% which does not seem to reflect that. There are 24 of those tasks and my CPU has 24 cores, so it feels like CPU usage should be much higher? Not sure.

Specifications

Investigations

• Investigate if it's possible to make tokio-console report what exactly are those tasks, or find out what they are
• Investigate if the reported results make sense with the expected behaviour, and open tickets if any issues are found
• Check what function is actually running at the top of each thread's stack:
  • https://unix.stackexchange.com/questions/166541/how-to-know-where-a-program-is-stuck-in-linux
  • https://fasterthanli.me/articles/when-rustc-explodes#profiling-with-not-perf-nperf (or the perf section)

Missing tokio-console features

• Tasks that might be blocking: warnings: warning for potentially blocking tasks tokio-rs/console#150
• Tasks that run for a long time: Report when a task doesn't / hasn't yielded in a while. tokio-rs/console#203

Related Work

[oxarbitrage]

CPU usage seems to be at 200% which does not seem to reflect that. There are 24 of those tasks and my CPU has 24 cores, so it feels like CPU usage should be much higher? Not sure.

There is a typo and this should say 20% ?

[conradoplg]

CPU usage seems to be at 200% which does not seem to reflect that. There are 24 of those tasks and my CPU has 24 cores, so it feels like CPU usage should be much higher? Not sure.

There is a typo and this should say 20% ?

In top (or htop), 200% means 2 cores at 100%

BTW, this seems to have changed. Now I get ~1000% CPU usage near the tip, and the sync seems to get stuck or take a super long time. Still no idea what's happening.

[teor2345]

Currently we've seen these blocking tasks:

• state writes (CommitBlock and CommitFinalizedBlock), waiting on file access, needs to be put in tokio::spawn_blocking()
  • this might also have some CPU-bound tasks in it

[teor2345]

CPU profiles seem to show these functions are the busiest.
(I listed functions with CPU over 10%, including children, in approximate order.)

This CPU-bound work shouldn't be running in tokio futures. It needs to be moved to the rayon CPU thread pool, inside blocking tokio threads.

We mainly saw issues with jubjub cryptography, but the same issue can happen with Orchard-heavy blocks and pallas.

Deserialization (in zebra-network or zebra-state):

• sapling::output::OutputPrefixInTransactionV5::zcash_deserialize() (Move network transaction deserialization to a dedicated blocking and CPU-heavy thread #4787)
  • sapling::committment::ValueCommitment::try_from::<[u8; 32]>()
  • bellman::groth16::Proof::read()
  • jubjub::AffinePoint::from_bytes_inner()
  • bls12_381::scalar::square()
  • bls12_381::scalar::sqrt()
• finalized_state::ZebraDb::block() (Move database block and transaction fetches to a dedicated blocking and CPU-heavy thread #4788)
  • partially fixed by 1. fix(state): when sending headers to peers, only deserialize the header data from disk #4792

Verification (in zebra-consensus):

• groth16::DescriptionWrapper::try_from() (Move CPU-heavy proof preparation into the batch cryptography thread #4789)
  • transaction::Verifier::verify_v5_transaction()

Note commitment tree updates (in zebra-state, either finalized or non-finalized):

• Note commitment tree append and root (Move note commitment tree updates to a dedicated blocking and CPU-heavy thread #4790)
  • non_finalized_state::chain::UpdateWith
  • sapling::tree::merkle_crh_sapling()
  • sapling::commitment::pedersen_hashes::pedersen_hash()
  • sapling::commitment::pedersen_hashes::pedersen_hash_to_point()
  • incrementalmerkletree::bridgetree::Frontier::append()
• feat(state): Send treestate from non-finalized state to finalized state #4721 should also help with non-finalized blocks

Example code for rayon in tokio blocking threads:

zebra/zebra-consensus/src/primitives/ed25519.rs

Lines 121 to 134 in 81727d7

	/// Flush the batch using a thread pool, and return the result via the channel.
	/// This function returns a future that becomes ready when the batch is completed.
	fn flush_spawning(batch: BatchVerifier, tx: Sender) -> impl Future<Output = ()> {
	// Correctness: Do CPU-intensive work on a dedicated thread, to avoid blocking other futures.
	tokio::task::spawn_blocking(|| {
	// TODO:
	// - spawn batches so rayon executes them in FIFO order
	// possible implementation: return a closure in a Future,
	// then run it using scope_fifo() in the worker task,
	// limiting the number of concurrent batches to the number of rayon threads
	rayon::scope_fifo(|s| s.spawn_fifo(|_s| Self::verify(batch, tx)))
	})
	.map(|join_result| join_result.expect("panic in ed25519 batch verifier"))
	}

CPU usage data:

[dconnolly]

CPU profiles seem to show these functions are the busiest. (I listed functions with CPU over 10%, including children, in approximate order.)

This CPU-bound work shouldn't be running in tokio futures. It needs to be moved to the rayon CPU thread pool, inside blocking tokio threads.

Verification (in zebra-consensus):

• groth16::DescriptionWrapper::try_from()

We can probably wrap up this call by doing the batch.queue() in a rayon thread, as I think that's the thing that requires groth16::DescriptionWrapper::try_from():

zebra/zebra-consensus/src/primitives/groth16.rs

Line 484 in 81727d7

self.batch.queue(item);

Note commitment tree updates (in zebra-state, either finalized or non-finalized):

• Note commitment tree append and root

  • incrementalmerkletree::bridgetree::Frontier::append()

Yep we probably can wrap up all write calls to the Frontier in a blocking rayon thread call

[teor2345]

It's more efficient to wrap the highest-level call that includes all the CPU-heavy code.

And every rayon thread needs to be wrapped in a tokio::spawn_blocking() thread - it's often easier to do them together.

[teor2345]

We've done enough on this for now, it's the note commitment trees.