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)
- https://crates.parity.io/sp_tracing/index.html
- https://github.com/paritytech/substrate/blob/master/primitives/tracing/src/lib.rs#L61
- https://github.com/paritytech/substrate/blob/polkadot-v0.9.26/primitives/io/src/lib.rs#L1516
- https://github.com/paritytech/substrate/issues/11000
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 -ltrace:
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 PassingTracingSubscriber.
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.
