trace: What level should spans default to?

[LucioFranco]

Description

Currently, spans default to a trace level, meaning if you'd like to log them at a debug or higher level you must manually set the level like so:

span!(level: Level::DEBUG, "my span");

This would allow you to filter it via app[my span]=debug, I initially found this to be something that I did not understand properly and was a source for confusion. I think that spans should default on an info level and then the user must lower this level based on expected verbosity.

cc @hawkw @carllerche

[hawkw]

I think @davidbarsky may also have an opinion on verbosity levels... :P

My primary motivation for making spans default to the trace level is that they typically will incur more overhead than events (although this depends on the subscriber implementation), since subscribers might want to store data associated with the span over the course of its lifetime.

With that said, it does mean that if you set the log level to DEBUG or INFO, you won't see any span data unless you have spans which override their verbosity level, which is not great. I'd be okay with changing the macro to default to the INFO level.

[LucioFranco]

My issue is that in my use case as far as I can see, I will want to filter between info, debug, and trace. This would require me then to have to set each span to INFO to get debug and info logs. Which to me sees like it might be pretty common. My question then is if I attempt to use tokio-trace-fmt like app[my span]=debug and that span is set to a trace level can the subscriber override that spans default level?

[carllerche]

Is there a reason why span! doesn't require a level to be specified? Then we have debug_span! etc... as short hands.

[hawkw]

@carllerche there's a reason, but I'm not convinced it's a good reason --- I had wanted to reserve the name debug_span! for a span that's only enabled in debug mode, which you suggested a while ago.

I'm open to changing the span macro API to work this way, though --- it would certainly be more consistent with the log macros.

[carllerche]

it seems like debug_span! and trace_span! would only be enabled in debug mode?

[hawkw]

(with that said, it's worth noting that @LucioFranco's issues around span filtering were actually due to a bug in the tokio-trace-fmt subscriber (tokio-rs/tracing#20))

[LucioFranco]

Yes, I actually am in favor of closing this now, I think it makes sense to default to trace and let the sub choose who to enable.

[hawkw]

@carllerche

it seems like debug_span! and trace_span! would only be enabled in debug mode?

I don't think that's the right thing to do, for several reasons:

1. It's inconsistent with the (current) behaviour of the trace! and debug! event macros,
2. It's surprising if creating a span with span!(level: Level::DEBUG, ...) and with debug_span!(...) have different behaviour --- the span! macro would still be enabled in release mode.
3. It's also inconsistent with the log crate's precedent --- its trace! and debug! macros are enabled in release mode. In fact, I believe the slog author has stated that disabling trace and debug logging in release mode by default was a mistake (presumably due to inconsistency with the log crate).
4. This is anecdotal, but from personal experience, I often find myself wanting to enable debug or trace logging from release-mode builds...

[hawkw]

Personally, I think the right thing to do is to make the span! macro require a level, and add error_span!, warn_span!, info_span!, debug_span! and trace_span! macros (and just let the hypothetical addition of a debug-mode-only span macro just sort out the naming problem later), but I can be convinced otherwise.

Even if we don't do this, I'm not convinced trace is the right level to default to for spans. I think info might be more correct. The decision to default to trace was made pretty arbitrarily, and after more practical experience instrumenting crates, I'm starting to question it.

[davidbarsky]

Bikeshedding! I think span! should default to Level::Info, but it can be overridden by end-users. In my experience with logging/tracing, I only really cared about info or error.

Regarding enabling trace! and debug! in release mode—following log's precedent as a default makes sense, but I can imagine a feature toggle that disables them in non-debug builds for folks that really want that toggle.

(My view is that sampling/downsizing volume should be handled by the service responsible for collecting instrumentation data and that applications shouldn't really be concerned with this problem—hence my opinion that only Level::Info and Level::Error matter.)

[carllerche]

log 100% used to automatically disable debug / log in release mode. I'm pretty surprised they don't.

That said, log allows the end user to configure the static filtering, which is pretty important.

We should definitely not end up in a matrix scenario where you have Span and DebugSpan types and each of those span types can log at any level.

[carllerche]

It should be possible to statically filter out at least trace & debug level spans when compiling with release mode.

[hawkw]

@carllerche I agree that it would probably be good to add some support for static filtering.

With that said, it's worth noting that log's static filtering doesn't actually result in any code not being compiled in, it just sets the value of a global static variable, which the log macros check. The per-callsite Interest cache in tokio-trace works pretty similarly (although it does a relaxed load on an atomic). If a subscriber returns Interest::never() in register_callsite, the performance of skipping that callsite in the future is likely equivalent to log's static level filtering.

[carllerche]

logs strategy results in LLVM optimizing the code out. tokio-trace does not have an equivalent. Especially with structs involved, there needs to be a way to reduce the struct to zero sized.

I don't think this would require tokio-trace-core so it probably can be punted.

[hawkw]

logs strategy results in LLVM optimizing the code out. tokio-trace does not have an equivalent.

Ah, yeah, good point. We should definitely have a static max level as well, then.

I don't think this would require tokio-trace-core so it probably can be punted.

Yup, this isn't blocking core 0.1.

[hawkw]

Now that PR #987 has added static level filtering for debug and release mode, I'm less concerned about reserving the name debug_span! for a debug-mode-only span macro. Thus, I'd be okay with moving forward by changing the span! macro to require a level, and adding error_span!, warn_span!, info_span!, debug_span! and trace_span! macros that behave similarly to the corresponding event macros. @LucioFranco is that acceptable to you?

Note that this would break any existing code using the tokio-trace macros...

[LucioFranco]

I'm not too sure, honestly, I would rather spans move away from the info, trace, debug setup. It seems wrong for me to create a span that I always want active as .instrument(error_span!(...)).

For example I have this code:

        self.send_body(buf.into())
            .instrument(span!(level: tokio_trace::Level::ERROR, "s3_request"))

I really dislike having to label this as error :(

[carllerche]

@LucioFranco Why is that not info level?

[LucioFranco]

@carllerche because I want that span active in every case. aka I want it to always be Interest::always.

[LucioFranco]

Its currently used for collecting s3 request duration metrics.

[carllerche]

@LucioFranco why are the two related? You should be able to have it as info AND have it always active?

[LucioFranco]

@carllerche right thats actually what my metrics subscriber does, I guess my issue was more around reading the code spans having levels has always kinda confused me. That said, it may just be my view of it, im totally fine with these macros and the breaking change 👍

[LucioFranco]

Okay, I've come around to this, I'm happy with this change and I am happy with keeping the terminology the same as log.

[hawkw]

@LucioFranco since it seems like we'll all in agreement now, I've opened #1013 for actually changing the macros.

[hawkw]

I think #959 and #1013 close this.