Skip to content

Commit

Permalink
Tracing for wasm with bridging to native (paritytech#6916)
Browse files Browse the repository at this point in the history
* implement events handling, implement parent_id for spans & events

* add events to sp_io::storage

* update test

* add tests

* adjust limit

* let tracing crate handle parent_ids

* re-enable current-id tracking

* add test for threads with CurrentSpan

* fix log level

* remove redundant check for non wasm traces

* remove duplicate definition in test

* Adding conditional events API

* prefer explicit parent_id over current,

enhance test

* limit changes to client::tracing event implementation

* remove From impl due to fallback required on parent_id

* make tracing codecable

* replace with global tracing

* new tracing interface

* impl TracingSubscriber in client

* implement access to global TracingSubscriber from primitives

* span for wasm

* increment towards Wasm Tracing Subscriber implementation

* increment, remove sp-tracing from runtime-interface

* increment, it compiles

* attained original functionality with new mechanism

* implement remaining TracingSubscriber functions

* remove spans from decl_module

* add handling for encoded values

* Revert "replace with global tracing"

This reverts commit 8824a60.

* Wasm Side Tracing

* tracing on wasm

* enable tracing wasm on node-runtime

* export all the macros in std

* tracing subscriber on wasm-side only

* pass spans and events over and record them

* reactivate previous code and  cleanup

* further cleaning up

* extend the span macros, activate through executive

* tracking the actual extrinsic, too

* style

* fixing tests

* spaces -> tabs

* attempting to reactivate params

* activate our tests in CI

* some passing

* tests passing

* with core lazy

* global tracer for wasm side with pass over

* fixing metadata referencing

* remove const_fn feature requirement

* reenable dispatch traces

* reset client tracing

* further cleaning up

* fixing runtime-test

* move tracing-build setup into runtime-test

* Merge DebugWriter from tracing and frame-support, move to sp-std

* remove dangling fixme

* Docs for tracing primitives

* cleaning up a bit more

* Wasm interface docs

* optimise docs.rs setup

* adding tracing flags to uncomment

* remove brace

* fixing imports

* fixing broken syntax

* add required modules

* nicer formatting

* better target management

* adding low level storage tracing events into frame

* add custom Debug impl for WasmMetadata

* cloning profiler

* adding info about cloning profiler

* using in-scope for within calls

* proper time tracing, cleaning up println

* allow to disable tracing on runtime_interface-macro

* disable tracing for wasm-tracing-interface

* simplify wasm-tracing-api

* update client to new interface

* fixing docs and tests for sp-tracing

* update integration tests

* re-activating enter_span

* dropping FIXME, it's documented

* fix formatting

* fix formatting

* fix imports

* more debug info

* inform wasm about it being disabled by returning 1

* only one tracer, but enabled multi-all support

* make trait pub again for tests

* Apply suggestions from code review

Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>

* fixing wasm doc tests for proper usage

* remove unnecessary import

* fixing formatting

* minor style fixes

* downgrading wabt

* update error message for UI

* Fix interface test

* next attempt to fix macros

* geee

* revert tracing on hashed for future PR

* remove local macros, use originals

* we are able to convert to static items

* implement more WasmValue types

* adding support to convert str, debug and encoded values

* more minor fixes

* revert unsafe 'static making

* fix indentation

* remove commented lines

* bump all them tracing versions

* cleaning up docs and info

* document new flag

* the new layered system handles span cloning better

* Apply suggestions from code review

Co-authored-by: David <dvdplm@gmail.com>

Co-authored-by: Matt Rutherford <mattrutherford@users.noreply.github.com>
Co-authored-by: Niklas Adolfsson <niklasadolfsson1@gmail.com>
Co-authored-by: David <dvdplm@gmail.com>
  • Loading branch information
4 people authored and Andrew Plaza committed Nov 5, 2020
1 parent 91f49cf commit 6c32865
Show file tree
Hide file tree
Showing 34 changed files with 1,214 additions and 442 deletions.
3 changes: 3 additions & 0 deletions .gitlab-ci.yml
Original file line number Diff line number Diff line change
Expand Up @@ -336,6 +336,9 @@ check-web-wasm:
- time cargo build --target=wasm32-unknown-unknown -p sc-telemetry
# Note: the command below is a bit weird because several Cargo issues prevent us from compiling the node in a more straight-forward way.
- time cargo +nightly build --manifest-path=bin/node/cli/Cargo.toml --no-default-features --features browser --target=wasm32-unknown-unknown -Z features=itarget
# with-tracing must be explicitly activated, we run a test to ensure this works as expected in both cases
- time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features
- time cargo +nightly test --manifest-path primitives/tracing/Cargo.toml --no-default-features --features=with-tracing
- sccache -s

test-full-crypto-feature:
Expand Down
42 changes: 14 additions & 28 deletions Cargo.lock

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

2 changes: 1 addition & 1 deletion bin/node/cli/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -43,7 +43,7 @@ jsonrpc-pubsub = "14.2.0"
log = "0.4.8"
rand = "0.7.2"
structopt = { version = "0.3.8", optional = true }
tracing = "0.1.18"
tracing = "0.1.19"
parking_lot = "0.10.0"

# primitives
Expand Down
1 change: 1 addition & 0 deletions bin/node/runtime/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -88,6 +88,7 @@ sp-io = { version = "2.0.0-rc6", path = "../../../primitives/io" }

[features]
default = ["std"]
with-tracing = [ "frame-executive/with-tracing" ]
std = [
"sp-authority-discovery/std",
"pallet-authority-discovery/std",
Expand Down
2 changes: 1 addition & 1 deletion client/executor/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -46,7 +46,7 @@ test-case = "0.3.3"
sp-runtime = { version = "2.0.0-rc6", path = "../../primitives/runtime" }
sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
sc-tracing = { version = "2.0.0-rc6", path = "../tracing" }
tracing = "0.1.18"
tracing = "0.1.19"
tracing-subscriber = "0.2.10"

[features]
Expand Down
2 changes: 2 additions & 0 deletions client/executor/runtime-test/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -29,5 +29,7 @@ std = [
"sp-io/std",
"sp-sandbox/std",
"sp-std/std",
"sp-core/std",
"sp-runtime/std",
"sp-allocator/std",
]
13 changes: 12 additions & 1 deletion client/executor/runtime-test/build.rs
Original file line number Diff line number Diff line change
Expand Up @@ -17,10 +17,21 @@
use wasm_builder_runner::WasmBuilder;

fn main() {
// regular build
WasmBuilder::new()
.with_current_project()
.with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder")
.export_heap_base()
.import_memory()
.build()
.build();

// and building with tracing activated
WasmBuilder::new()
.with_current_project()
.with_wasm_builder_from_crates_or_path("2.0.0", "../../../utils/wasm-builder")
.export_heap_base()
.import_memory()
.set_file_name("wasm_binary_with_tracing.rs")
.append_to_rust_flags("--cfg feature=\\\"with-tracing\\\"")
.build();
}
4 changes: 2 additions & 2 deletions client/executor/runtime-test/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -254,11 +254,11 @@ sp_core::wasm_export_functions! {
}

fn test_enter_span() -> u64 {
wasm_tracing::enter_span("integration_test_span_target", "integration_test_span_name")
wasm_tracing::enter_span(Default::default())
}

fn test_exit_span(span_id: u64) {
wasm_tracing::exit_span(span_id)
wasm_tracing::exit(span_id)
}

fn returns_mutable_static() -> u64 {
Expand Down
49 changes: 4 additions & 45 deletions client/executor/src/integration_tests/mod.rs
Original file line number Diff line number Diff line change
Expand Up @@ -681,7 +681,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {
// Create subscriber with wasm_tracing disabled
let test_subscriber = tracing_subscriber::fmt().finish().with(
sc_tracing::ProfilingLayer::new_with_handler(
Box::new(handler), "integration_test_span_target"
Box::new(handler), "default"
)
);

Expand All @@ -690,49 +690,9 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {
let mut ext = TestExternalities::default();
let mut ext = ext.ext();

// Test tracing disabled
assert!(!sp_tracing::wasm_tracing_enabled());

let span_id = call_in_wasm(
"test_enter_span",
&[],
wasm_method,
&mut ext,
).unwrap();

assert_eq!(
0u64.encode(),
span_id
);
// Repeat to check span id always 0 when deactivated
let span_id = call_in_wasm(
"test_enter_span",
&[],
wasm_method,
&mut ext,
).unwrap();

assert_eq!(
0u64.encode(),
span_id
);

call_in_wasm(
"test_exit_span",
&span_id.encode(),
wasm_method,
&mut ext,
).unwrap();
// Check span has not been recorded
let len = traces.lock().unwrap().len();
assert_eq!(len, 0);

// Test tracing enabled
sp_tracing::set_wasm_tracing(true);

let span_id = call_in_wasm(
"test_enter_span",
&[],
Default::default(),
wasm_method,
&mut ext,
).unwrap();
Expand All @@ -756,8 +716,7 @@ fn wasm_tracing_should_work(wasm_method: WasmExecutionMethod) {

let span_datum = traces.lock().unwrap().pop().unwrap();
let values = span_datum.values;
assert_eq!(span_datum.target, "integration_test_span_target");
assert_eq!(span_datum.name, "integration_test_span_name");
assert_eq!(span_datum.target, "default");
assert_eq!(span_datum.name, "");
assert_eq!(values.bool_values.get("wasm").unwrap(), &true);
assert_eq!(values.bool_values.get("is_valid_trace").unwrap(), &true);
}
3 changes: 2 additions & 1 deletion client/service/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -73,7 +73,8 @@ sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" }
sc-offchain = { version = "2.0.0-rc6", path = "../offchain" }
prometheus-endpoint = { package = "substrate-prometheus-endpoint", path = "../../utils/prometheus", version = "0.8.0-rc6"}
sc-tracing = { version = "2.0.0-rc6", path = "../tracing" }
tracing = "0.1.18"
sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
tracing = "0.1.19"
parity-util-mem = { version = "0.7.0", default-features = false, features = ["primitive-types"] }

[target.'cfg(not(target_os = "unknown"))'.dependencies]
Expand Down
3 changes: 2 additions & 1 deletion client/tracing/Cargo.toml
Original file line number Diff line number Diff line change
Expand Up @@ -19,7 +19,8 @@ rustc-hash = "1.1.0"
serde = "1.0.101"
serde_json = "1.0.41"
slog = { version = "2.5.2", features = ["nested-values"] }
tracing = "0.1.18"
tracing = "0.1.19"
tracing-core = "0.1.13"
tracing-subscriber = "0.2.10"
sp-tracing = { version = "2.0.0-rc6", path = "../../primitives/tracing" }
sc-telemetry = { version = "2.0.0-rc6", path = "../telemetry" }
22 changes: 7 additions & 15 deletions client/tracing/src/lib.rs
Original file line number Diff line number Diff line change
Expand Up @@ -40,8 +40,7 @@ use tracing::{
use tracing_subscriber::{CurrentSpan, layer::{Layer, Context}};

use sc_telemetry::{telemetry, SUBSTRATE_INFO};
use sp_tracing::proxy::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};

use sp_tracing::{WASM_NAME_KEY, WASM_TARGET_KEY, WASM_TRACE_IDENTIFIER};
const ZERO_DURATION: Duration = Duration::from_nanos(0);

/// Responsible for assigning ids to new spans, which are not re-used.
Expand Down Expand Up @@ -275,12 +274,6 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
fn new_span(&self, attrs: &Attributes<'_>, id: &Id, _ctx: Context<S>) {
let mut values = Values::default();
attrs.record(&mut values);
// If this is a wasm trace, check if target/level is enabled
if let Some(wasm_target) = values.string_values.get(WASM_TARGET_KEY) {
if !self.check_target(wasm_target, attrs.metadata().level()) {
return
}
}
let span_datum = SpanDatum {
id: id.clone(),
parent_id: attrs.parent().cloned().or_else(|| self.current_span.id()),
Expand Down Expand Up @@ -327,18 +320,13 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
fn on_exit(&self, span: &Id, _ctx: Context<S>) {
self.current_span.exit();
let end_time = Instant::now();
let mut span_data = self.span_data.lock();
if let Some(mut s) = span_data.get_mut(&span) {
s.overall_time = end_time - s.start_time + s.overall_time;
}
}

fn on_close(&self, span: Id, _ctx: Context<S>) {
let span_datum = {
let mut span_data = self.span_data.lock();
span_data.remove(&span)
};

if let Some(mut span_datum) = span_datum {
span_datum.overall_time += end_time - span_datum.start_time;
if span_datum.name == WASM_TRACE_IDENTIFIER {
span_datum.values.bool_values.insert("wasm".to_owned(), true);
if let Some(n) = span_datum.values.string_values.remove(WASM_NAME_KEY) {
Expand All @@ -355,6 +343,10 @@ impl<S: Subscriber> Layer<S> for ProfilingLayer {
}
};
}

fn on_close(&self, span: Id, ctx: Context<S>) {
self.on_exit(&span, ctx)
}
}

/// TraceHandler for sending span data to the logger
Expand Down
39 changes: 22 additions & 17 deletions client/transaction-pool/src/api.rs
Original file line number Diff line number Diff line change
Expand Up @@ -168,23 +168,28 @@ where
Client::Api: TaggedTransactionQueue<Block>,
sp_api::ApiErrorFor<Client, Block>: Send + std::fmt::Display,
{
sp_tracing::enter_span!("validate_transaction");
let runtime_api = client.runtime_api();
let has_v2 = sp_tracing::tracing_span! { "check_version";
runtime_api
.has_api_with::<dyn TaggedTransactionQueue<Block, Error=()>, _>(&at, |v| v >= 2)
.unwrap_or_default()
};

sp_tracing::enter_span!("runtime::validate_transaction");
let res = if has_v2 {
runtime_api.validate_transaction(&at, source, uxt)
} else {
#[allow(deprecated)] // old validate_transaction
runtime_api.validate_transaction_before_version_2(&at, uxt)
};

res.map_err(|e| Error::RuntimeApi(e.to_string()))
sp_tracing::within_span!(sp_tracing::Level::TRACE, "validate_transaction";
{
let runtime_api = client.runtime_api();
let has_v2 = sp_tracing::within_span! { sp_tracing::Level::TRACE, "check_version";
runtime_api
.has_api_with::<dyn TaggedTransactionQueue<Block, Error=()>, _>(&at, |v| v >= 2)
.unwrap_or_default()
};

let res = sp_tracing::within_span!(
sp_tracing::Level::TRACE, "runtime::validate_transaction";
{
if has_v2 {
runtime_api.validate_transaction(&at, source, uxt)
} else {
#[allow(deprecated)] // old validate_transaction
runtime_api.validate_transaction_before_version_2(&at, uxt)
}
});

res.map_err(|e| Error::RuntimeApi(e.to_string()))
})
}

impl<Client, Block> FullChainApi<Client, Block>
Expand Down
Loading

0 comments on commit 6c32865

Please sign in to comment.