Structured Logging

[Michael-F-Bryan]

For telemetry, we'd like a Rune to tell us when certain events happen (start of proc block X, etc.) so we can pass that on information to the user.

One way we can do this is by switching from the log crate to something that supports structured logging (e.g. tracing). Then we just need to set up "well-known" messages that the runtime can look out for and translate into telemetry events (e.g. by wrapping the call in a span). Then it's just a case of wiring up a Subscriber that passes these events to _debug().

cc: @jacekpie

[Michael-F-Bryan]

At the moment we generate a pipeline lambda like this:

let pipeline = move || {
    let _guard = hotg_runicos_base_wasm::PipelineGuard::default();
    log::debug!("Reading data from \"audio\"");
    let audio_0: Tensor<i16> = audio.generate();
    log::debug!("Executing \"fft\"");
    let fft_0: Tensor<u32> = fft.transform(audio_0.clone());
    log::debug!("Executing \"noise_filtering\"");
    let noise_filtering_0: Tensor<i8> = noise_filtering.transform(fft_0.clone());
    log::debug!("Executing \"model\"");
    let model_0: Tensor<i8> = model.transform(noise_filtering_0.clone());
    log::debug!("Executing \"most_confident\"");
    let most_confident_0: Tensor<u32> = most_confident.transform(model_0.clone());
    log::debug!("Executing \"label\"");
    let label_0: Tensor<alloc::borrow::Cow<'static, str>> =
        label.transform(most_confident_0.clone());
    log::debug!("Sending results to the \"serial\" output");
    serial.consume(label_0.clone());
};

Switching to structured logging would mean we generate this:

let pipeline = move || {
    let pipeline_span = tracing::span!(target: "pipeline").entered();

    let span = tracing::span!(target: "stage", Level::INFO, name = "audio", node_type = "capability").entered();
    let audio_0: Tensor<i16> = audio.generate();
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "fft", node_type = "proc-block").entered();
    let fft_0: Tensor<u32> = fft.transform(audio_0.clone());
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "noise_filtering", node_type = "proc-block").entered();
    let noise_filtering_0: Tensor<i8> = noise_filtering.transform(fft_0.clone());
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "model", node_type = "model").entered();
    let model_0: Tensor<i8> = model.transform(noise_filtering_0.clone());
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "most_confident", node_type = "proc-block").entered();
    let most_confident_0: Tensor<u32> = most_confident.transform(model_0.clone());
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "label", node_type = "proc-block").entered();
    let label_0: Tensor<alloc::borrow::Cow<'static, str>> = label.transform(most_confident_0.clone());
    drop(span);

    let span = tracing::span!(target: "stage", Level::INFO, name = "serial", node_type = "out").entered();
    serial.consume(label_0.clone());
    drop(span);
};

Note: We are notified whenever we enter/exit a Span, so that can be used to derive timing information.