Add timing tree

[mcalancea]

Fixes #655.

Integrates tracing-forest for its nice timing-tree summary.
In addition, I added a trick to control "granularity": spans have a profiling_{LEVEL} field which one can prune from the command line. For example, compare:

cargo run --release --package ceno_zkvm --bin e2e -- --profiling=1 --max-steps=10000 --platform=sp1 ceno_zkvm/examples/fibonacci.elf 

INFO     ZKVM_create_proof [ 790ms | 0.00% / 100.00% ]
INFO     ┝━ commit_to_fixed_commit [ 129µs | 0.02% ] profiling_1: true
INFO     ┝━ commit_to_traces [ 147ms | 18.62% ] profiling_1: true
INFO     ┕━ main_proofs [ 643ms | 81.36% ] profiling_1: true

to

cargo run --release --package ceno_zkvm --bin e2e -- --profiling=2 --max-steps=10000 --platform=sp1 ceno_zkvm/examples/fibonacci.elf 

INFO     ZKVM_create_proof [ 1.10s | 0.00% / 100.00% ]
INFO     ┝━ commit_to_fixed_commit [ 162µs | 0.01% ] profiling_1: true
INFO     ┝━ commit_to_traces [ 151ms | 0.02% / 13.78% ] profiling_1: true
INFO     │  ┝━ commit to iteration [ 7.66ms | 0.70% ] circuit_name: "ADD" | profiling_2: true
INFO     │  ┝━ commit to iteration [ 4.17ms | 0.38% ] circuit_name: "ADDI" | profiling_2: true
INFO     │  ┝━ commit to iteration [ 163ns | 0.00% ] circuit_name: "AND" | profiling_2: true
INFO     │  ┝━ commit to iteration [ 297µs | 0.03% ] circuit_name: "ANDI" | profiling_2: true
INFO     │  ┝━ commit to iteration [ 201µs | 0.02% ] circuit_name: "AUIPC" | profiling_2: true
[... more lines follow]

I haven't gone too far in assigning adequate levels to spans, I'm not sure what's relevant.

[matthiasgoergens]

I think you might want to control log verbosity and profiling information independently?

(It's reasonable to default log verbosity to silent, if you turn on profiling, though.)

[mcalancea]

Ideally you would, but the only way to keep the profiling data readable is to filter out some of the spans. And filtering out some of the spans has an unclear impact (to me at least) on the general logging context. I think it's simpler and not that inconvenient to keep them separate.

[matthiasgoergens]

Looks mostly good. Please see comments.

[matthiasgoergens]

The parens look a bit confusing here?

Btw, instead of is_some().then_some() you can probably just use .map(|_| filter_by_profiling_level)?

[mcalancea]

Removed parens. .map() is terser, but not as readable in this case I'd say.

[matthiasgoergens]

Instead of pairs of and entered_span and exit_span like this

let span = entered_span(some_name);
// [... some code ...]
exit_span!(span);

in most cases we can probably use a less error-prone mechanism:

with_span!(some_name) {
  // [... some code ...]
}

(That requires to quickly write a with_span macro. The exact syntax is only a suggestion.)

[mcalancea]

I get your point, but I dislike the effect on indentation. Often, [... some code...] is not an expression, but a very large block. Because it's not a clear-cut decision, I would defer it to a separate issue/PR.

[matthiasgoergens]

Btw, does this produce wallclock time or report CPU seconds spent? Both can be useful, depending on what you want to investigate.

See https://docs.rs/cpu-time/latest/cpu_time/index.html for the latter.

[mcalancea]

It's wall time. It uses https://doc.rust-lang.org/std/time/struct.Instant.html and elapsed.