Structured Logging

[Michael-F-Bryan]

Structured Logging

[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.