I am trying to achieve logging of extrinsic execution time traces on parachain nodes i run myself during block import. I'm doing this through tracing instead of by weights so that I can collect data on long-term trends in actual execution times on the actual mainnet TXN composition instead of benchmarking's worst-case assumption.
Looking through the docs, most references to in-runtime tracing are 12months or older.
I have found
- https://github.com/paritytech/substrate/blob/polkadot-v0.9.26/client/rpc-api/src/state/mod.rs#L128 & https://github.com/paritytech/substrate/pull/7780 (rpc to re-execute historic blocks, N/A here)
My runtime forwards block building calls directly to executive, which runs
init_tracing https://github.com/paritytech/substrate/blob/polkadot-v0.9.26/frame/executive/src/lib.rs#L435 so as long as
sp-io is built
with-tracing I get the
PassingTracingSubscriber and should see log output of recorded spans from what I gather reading these docs.
I have tried RT cargo.toml
with-tracing = [ "sp-tracing/with-tracing", "polkadot-runtime-metrics/runtime-metrics", "frame-executive/with-tracing", "sp-io/with-tracing" ]
cargo b --release --features=with-tracing
But I cannot get any trace output to show up in the logs. Client-side Trace-level logs show normally when the bin is run with
2022-12-02 11:09:42.063 TRACE tokio-runtime-worker executor: [Parachain] Executing function method=BlockBuilder_apply_extrinsic 2022-12-02 11:09:42.069 TRACE tokio-runtime-worker executor: [Parachain] Executing function method=BlockBuilder_apply_extrinsic
I would expect these to be interspersed with the recorded spans from apply_extrinsic produced here.
Is sp-tracing still supported and am I missing something?
e.g. some client-side configuration to receive/enable the traces from the
I did find reference in the docs to having to call
set_tracing_subscriber somewhere in the RT, but 0.9.26 substrate code does not seem to have this fn anymore.
One caveat with this chain (in case it's relevant) is that I do not have to option of using the native runtime as we force WASM execution even in the case of matching versions.