Runtime upgrade to make use of wasm tracing #6401

mattrutherford · 2020-06-18T11:32:01Z

This PR brings the runtime changes that make use of the new host functions added in #6381 which provide the ability to profile/trace wasm execution. It is the second part of the split of #5826.

We should allow sufficient time for clients in the network to upgrade to a version incorporating #6381 before merging this PR.

Add --wasm-tracing CLI flag to enable tracing from wasm (disabled by default).
Used in conjunction with --tracing-targets (and optionally --tracing-receiver).
Add automatic tracing to decl_module functions in the runtime.

from wasm traces.

…ive types

Co-authored-by: Kian Paimani <[email protected]>

Co-authored-by: Bastian Köcher <[email protected]>

mattrutherford · 2020-06-18T11:32:58Z

target/release/substrate --dev --validator --alice --tracing-targets pallet=trace --execution wasm --wasm-execution compiled --tracing-enable-wasm
2020-06-18 12:17:47.021 main WARN sc_cli::commands::run_cmd  Running in --dev mode, RPC CORS has been disabled.
2020-06-18 12:17:47.021 main INFO sc_cli::runner  Substrate Node
2020-06-18 12:17:47.021 main INFO sc_cli::runner  ✌️  version 2.0.0-rc3-unknown-commit-x86_64-linux-gnu
2020-06-18 12:17:47.021 main INFO sc_cli::runner  ❤️  by Parity Technologies <[email protected]>, 2017-2020
2020-06-18 12:17:47.021 main INFO sc_cli::runner  📋 Chain specification: Development
2020-06-18 12:17:47.021 main INFO sc_cli::runner  🏷  Node name: Alice
2020-06-18 12:17:47.021 main INFO sc_cli::runner  👤 Role: AUTHORITY
2020-06-18 12:17:47.021 main INFO sc_cli::runner  💾 Database: RocksDb at /mnt/ramdisk/1/chains/dev/db
2020-06-18 12:17:47.021 main INFO sc_cli::runner  ⛓  Native runtime: node-253 (substrate-node-0.tx1.au10)
2020-06-18 12:17:47.069 main INFO staking  💸 new validator set of size 1 has been elected via ElectionCompute::OnChain for era 0
2020-06-18 12:17:47.074 main INFO sc_service::client::client  🔨 Initializing Genesis block/state (state: 0x2144…37fd, header-hash: 0xf043…d8a4)
2020-06-18 12:17:47.076 main INFO afg  👴 Loading GRANDPA authority set from genesis on what appears to be first startup.
2020-06-18 12:17:47.320 main INFO sc_consensus_slots  ⏱  Loaded block-time = BabeGenesisConfiguration { slot_duration: 3000, epoch_length: 200, c: (1, 4), genesis_authorities: [(Public(d43593c715fdd31c61141abd04a99fd6822c8558854ccde39a5684e7a56da27d (5GrwvaEF...)), 1)], randomness: [0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0], allowed_slots: AllowedSlots::PrimaryAndSecondaryPlainSlots } milliseconds from genesis on first-launch
2020-06-18 12:17:47.320 main INFO babe  👶 Creating empty BABE epoch changes on what appears to be first startup.
2020-06-18 12:17:47.338 main INFO sc_service::builder  📦 Highest known block at #0
2020-06-18 12:17:47.338 main WARN sc_service::builder  Using default protocol ID "sup" because none is configured in the chain specs
2020-06-18 12:17:47.338 main INFO sub-libp2p  🏷  Local node identity is: 12D3KooWKE5Y9orm344cBaACCtfEauWqhWSkfH4EeJempHw8vyFk (legacy representation: Qmev3nhkAsHjtEDYnLzbAT6ccpEfSpobXRx811UCrenjsv)
2020-06-18 12:17:47.363 tokio-runtime-worker INFO substrate_prometheus_endpoint::known_os  〽️ Prometheus server started at 127.0.0.1:9615
2020-06-18 12:17:47.364 main INFO babe  👶 Starting BABE Authorship worker
2020-06-18 12:17:48.008 tokio-runtime-worker INFO sc_basic_authorship::basic_authorship  🙌 Starting consensus session on top of parent 0xf04317ea2da9f656f55d4d981b613bc0fbb269e7c6e2d7aabf43e1c27846d8a4
2020-06-18 12:17:48.014 tokio-blocking-driver INFO sc_tracing  pallet_scheduler: on_initialize, time: 11860, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.014 tokio-blocking-driver INFO sc_tracing  pallet_society: on_initialize, time: 740, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.015 tokio-blocking-driver INFO sc_tracing  pallet_randomness_collective_flip: on_initialize, time: 15540, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.015 tokio-blocking-driver INFO sc_tracing  pallet_offences: on_initialize, time: 18380, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.015 tokio-blocking-driver INFO sc_tracing  pallet_treasury: on_initialize, time: 860, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.015 tokio-blocking-driver INFO sc_tracing  pallet_elections_phragmen: on_initialize, time: 400, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.015 tokio-blocking-driver INFO sc_tracing  pallet_democracy: on_initialize, time: 15050, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.016 tokio-blocking-driver INFO sc_tracing  pallet_session: on_initialize, time: 1204891, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.016 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_initialize, time: 20070, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.016 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_initialize, time: 61111, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.016 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_initialize, time: 300, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.016 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_initialize, time: 3320, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_scheduler: on_initialize, time: 6980, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_society: on_initialize, time: 390, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_randomness_collective_flip: on_initialize, time: 10430, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_offences: on_initialize, time: 13720, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_treasury: on_initialize, time: 400, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.023 tokio-blocking-driver INFO sc_tracing  pallet_elections_phragmen: on_initialize, time: 280, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_democracy: on_initialize, time: 11630, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_session: on_initialize, time: 10050, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_initialize, time: 15160, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_initialize, time: 39610, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_initialize, time: 290, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.024 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_initialize, time: 2971, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.031 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: set, time: 16260, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_grandpa: on_finalize, time: 11250, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_finality_tracker: on_finalize, time: 29200, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_finalize, time: 12680, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_transaction_payment: on_finalize, time: 17161, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_finalize, time: 3310, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_finalize, time: 3660, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.036 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_finalize, time: 22540, is_valid_trace=true, wasm=true
2020-06-18 12:17:48.037 tokio-blocking-driver INFO sc_basic_authorship::basic_authorship  🎁 Prepared block for proposing at 1 [hash: 0xe063a05a9ec4ec7e54910332b5b271e53ea3805e23eed885ab0be3c2ec6cda91; parent_hash: 0xf043…d8a4; extrinsics (1): [0x8599…4ba1]]
2020-06-18 12:17:48.039 tokio-runtime-worker INFO sc_consensus_slots  🔖 Pre-sealed block for proposal at 1. Hash now 0x79bc5f5e982336ba03b57c2f984ef3e77acabb5c7e4d07612a2719865141b5cb, previously 0xe063a05a9ec4ec7e54910332b5b271e53ea3805e23eed885ab0be3c2ec6cda91.
2020-06-18 12:17:48.039 tokio-runtime-worker INFO babe  👶 New epoch 0 launching at block 0x79bc…b5cb (block slot 530826356 >= start slot 530826356).
2020-06-18 12:17:48.039 tokio-runtime-worker INFO babe  👶 Next epoch starts at slot 530826556
2020-06-18 12:17:48.039 tokio-runtime-worker INFO substrate  ✨ Imported #1 (0x79bc…b5cb)
2020-06-18 12:17:51.002 tokio-runtime-worker INFO sc_basic_authorship::basic_authorship  🙌 Starting consensus session on top of parent 0x79bc5f5e982336ba03b57c2f984ef3e77acabb5c7e4d07612a2719865141b5cb
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_scheduler: on_initialize, time: 9450, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_society: on_initialize, time: 520, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_randomness_collective_flip: on_initialize, time: 12520, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_offences: on_initialize, time: 10041, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_treasury: on_initialize, time: 430, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_elections_phragmen: on_initialize, time: 380, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_democracy: on_initialize, time: 6910, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_session: on_initialize, time: 26720, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_initialize, time: 9170, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_initialize, time: 36771, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_initialize, time: 350, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_initialize, time: 3350, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_scheduler: on_initialize, time: 4880, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_society: on_initialize, time: 400, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_randomness_collective_flip: on_initialize, time: 11080, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_offences: on_initialize, time: 9450, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_treasury: on_initialize, time: 370, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_elections_phragmen: on_initialize, time: 360, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_democracy: on_initialize, time: 6440, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_session: on_initialize, time: 15380, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_initialize, time: 8750, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_initialize, time: 27451, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_initialize, time: 390, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_initialize, time: 3300, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: set, time: 10570, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_grandpa: on_finalize, time: 5110, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_finality_tracker: on_finalize, time: 20280, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_staking: on_finalize, time: 3580, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_transaction_payment: on_finalize, time: 15880, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_authorship: on_finalize, time: 3850, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_timestamp: on_finalize, time: 3870, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.002 tokio-blocking-driver INFO sc_tracing  pallet_babe: on_finalize, time: 5530, is_valid_trace=true, wasm=true
2020-06-18 12:17:51.003 tokio-blocking-driver INFO sc_basic_authorship::basic_authorship  🎁 Prepared block for proposing at 2 [hash: 0xbe4b4a0376b5e1e6cb6e1cdca345e45b6c663c8203c31a6dace6c441c7026463; parent_hash: 0x79bc…b5cb; extrinsics (1): [0x92a3…f0fd]]
2020-06-18 12:17:51.005 tokio-runtime-worker INFO sc_consensus_slots  🔖 Pre-sealed block for proposal at 2. Hash now 0xae660cc0dbe066cefef8b40a048a287580d59394d119bd4582d82b9f826ae7a6, previously 0xbe4b4a0376b5e1e6cb6e1cdca345e45b6c663c8203c31a6dace6c441c7026463.
2020-06-18 12:17:51.005 tokio-runtime-worker INFO substrate  ✨ Imported #2 (0xae66…e7a6)

bkchr · 2020-07-07T08:03:40Z

Can you merge master? I think we should now be safe to merge this.

mattrutherford · 2020-09-09T08:54:28Z

Closing this, as it is now superseded by #6916

mattrutherford and others added 30 commits April 27, 2020 07:51

Add span recording to tracing implementation

62f4df9

Add tracing proxy

e5aa529

switch to rustc_hash::FxHashMap

e71eb09

Replace lazy_static and hashmap with thread_local and vec.

db69268

fix marking valid span as invalid while removing invalid spans

b43015f

refactor, add wasm_tracing module in support

dba7d55

update registered spans

5e86ef6

tidy up

35706ca

typos

1388002

refactor

41964e7

update flag name to signal lost trace - is_valid_trace

ad81d3b

update flag name to signal lost trace - is_valid_trace

2cb66bf

update docs

03b7b6e

update docs

16b018c

Use tracing Field recording to store the actual name and target

d2af83d

from wasm traces.

fix debug log in subscriber + small refactor

9f8baf2

add tests

1199f36

handle misuse in case trying to exit span not held

0c61f79

Implement filter for wasm traces, simplify field recording for primit…

8061da5

…ive types

remove superfluous warning

2097aca

update docs

1ef18e6

Merge branch 'master' into mr-sp-tracing

60e0b60

Merge branch 'master' into mr-sp-tracing

cd8bed8

Update primitives/tracing/src/proxy.rs

460d24d

Co-authored-by: Kian Paimani <[email protected]>

Apply suggestions from code review

85bdbe0

Co-authored-by: Bastian Köcher <[email protected]>

update docs, apply suggestions

b9d1fdf

move Proxy from thread_local to Extension, rename macro

b66bb33

fix test

afa511d

unify native & wasm span macro calls

93a03a8

implement wasm tracing control facility in primitives and frame

2126d8e

mattrutherford added the D6-newhostfunctions label Jun 18, 2020

mattrutherford requested review from cecton, kianenigma and pepyakin as code owners June 18, 2020 11:32

github-actions bot added the A0-please_review Pull request needs code review. label Jun 18, 2020

mattrutherford removed request for pepyakin, cecton and kianenigma June 18, 2020 11:34

mattrutherford added the B7-runtimenoteworthy label Jun 18, 2020

mattrutherford changed the title ~~[ONICE] Wasm tracing runtime~~ [ONICE] Runtime upgrade to make use of wasm tracing Jun 18, 2020

mattrutherford added C1-low PR touches the given topic and has a low impact on builders. and removed A0-please_review Pull request needs code review. labels Jun 18, 2020

gnunicorn added the A1-onice label Jun 18, 2020

bkchr mentioned this pull request Jul 3, 2020

State tracing in runtime #6572

Closed

Your Name added 2 commits July 7, 2020 12:31

Merge branch 'master' into wasm-tracing-runtime

f8bcb58

bump impl_version

e0f1712

mattrutherford changed the title ~~[ONICE] Runtime upgrade to make use of wasm tracing~~ Runtime upgrade to make use of wasm tracing Jul 7, 2020

gnunicorn added A0-please_review Pull request needs code review. and removed A1-onice labels Jul 7, 2020

gnunicorn requested review from bkchr and gnunicorn and removed request for bkchr July 7, 2020 15:49

This was referenced Jul 15, 2020

[WIP] Tracing events / refactor proxy / state traces #6658

Closed

Implement tracing::Event handling & parent_id for spans and events #6672

Merged

gnunicorn added A1-onice and removed A0-please_review Pull request needs code review. labels Sep 9, 2020

mattrutherford closed this Sep 9, 2020

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Runtime upgrade to make use of wasm tracing #6401

Runtime upgrade to make use of wasm tracing #6401

mattrutherford commented Jun 18, 2020 •

edited

Loading

mattrutherford commented Jun 18, 2020

bkchr commented Jul 7, 2020

mattrutherford commented Sep 9, 2020

Runtime upgrade to make use of wasm tracing #6401

Runtime upgrade to make use of wasm tracing #6401

Conversation

mattrutherford commented Jun 18, 2020 • edited Loading

mattrutherford commented Jun 18, 2020

bkchr commented Jul 7, 2020

mattrutherford commented Sep 9, 2020

mattrutherford commented Jun 18, 2020 •

edited

Loading