How to time spans in Wasm/web assembly?

[sick sky]

I'm trying to measure how long function's decorated with tracing::instrument but
in wasm I can't get timing from the FmtSpan::CLOSE event. It triggers a panic because it uses std::time::Instant which is not available in wasm land.

I tried creating a web_time::Instant::now() in a custom Layer in the on_enter method. Then setting it to a field in on_exitand on_close like:

fn on_enter(..) {
  ...    
  span.extensions_mut().insert(Instant::now());
}
fn on_exit(..) { // also `on_close`
   if let Some(start_time) = span.extensions().get::<StartTime>() {
     let elapsed = start_time.0.elapsed();
     let duration_ms = elapsed.as_secs_f64() * 1000.0;
     drop(span.extensions()); // Release the borrow
     tracing::Span::current().reecord("duration_ms", duration_ms)
   }
}

But this didn't work. In fact I never see the fields added when I do Span::current().record(..) in on_exit or on_record.
So any suggestions would be greatly appreciated. Thanks!

[patent wraith]

you already have access to the span, why are you using Span::current()?

[sick sky]

Then span I get from ctx.span(id) is a SpanRef which doesn't have the .record() method. The span from Span::current() is a real Span which does. Are they the same? How can I use the SpanRef?

[patent wraith]

also, .record cannot add additional fields. It records values for fields the span already knows about (span fields are static metadata), so unless your span has a duration_ms field, this won't do anything

[sick sky]

The functions does have a #[instrument(fields(duration_ms2)] on it. Isn't that sufficient?

[patent wraith]

I'm not sure actually, let me check. duration_ms = tracing::field::Empty should definitely work

Okay yeah, you're right, that should work

[sick sky]

I'll try that. but #[instrument(fields(duration_ms))] pattern works for other fields i set in custom Layers but in on_enter

[patent wraith]

Are they the same?
not necessarily, and especially in on_close they won't be, because the span you actually want to target has already been closed

tracing_subscriber::fmt emits events for each of these, and those events include timing data

I don't think the span contains any timing information?

[sick sky]

I only see timing data in FmtSpan::CLOSE but creating a subscriber which listens for that in wasm causes a panic

[patent wraith]

FmtSpan is used to configure tracing-subscriber to emit events from the span lifecycle callbacks

you are looking at events with their own fields which contain the timing information

if you want the same functionality, you need to emit events from your layer, and you can store the timing data in the event fields

[sick sky]

Ah so I'd need to do something like tracing::info!("duration_ms = {}", star.elapsed()) in on_exit or on_close? I was hoping I could just attach the data to the span

[patent wraith]

you can see it here: https://docs.rs/tracing-subscriber/0.3.19/src/tracing_subscriber/fmt/fmt_layer.rs.html#928-963

in lines 947-948 they specify the fields

[sick sky]

Ah thank you

[patent wraith]

I don't know if you can

you could also open an issue and ask if, on wasm, tracing-subscriber could use web_time instead of std

[sick sky]

I have a plan that might work. I will crate a custom impl tracing::Value for Wrapper(web_time::Instant) and in the fn record(..) {..} I will have the visitor "record" self.0.elapsed(). I think this would show the field with the time elapsed in the EXIT event.. maybe

[patent wraith]

tracing::Value is sealed. You cannot implement it yourself.

[sick sky]

ahh I just ran into that

[patent wraith]

elapsed() should return a Duration, which implements Debug, so you can use it as a field value with tracing::field::debug(…) or the ? shorthand syntax if you're using the macros