Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

tracing::enabled!() macro for testing if events might be enabled given a static subset of event data #1668

Closed
lilyball opened this issue Oct 21, 2021 · 0 comments · Fixed by #1821
Labels
crate/tracing Related to the `tracing` crate kind/feature New feature or request

Comments

@lilyball
Copy link
Contributor

Feature Request

Crates

tracing-core
tracing
tracing-subscriber and other crates that implement subscribers

Motivation

I want to be able to test if an event is known to be disabled before doing an expensive computation required just for the event. In some cases I can do the computation as an argument of the event, but in others I cannot, such as when I'm emitting multiple events (e.g. iterating over a collection and emitting an event for each item).

Proposal

Add a new tracing::enabled!() macro. Standard usage would look like if tracing::enabled!(Level::INFO) { … }. This macro would allow false positives, but guarantee no false negatives (assuming correctly-implemented subscribers). The macro is testing for events specifically, not spans, as with spans you can create the span and check if it's disabled prior to using it (or filling in field values).

tracing::enabled!() would require a level argument, an optional target: argument, and then an optional set of fields. If the fields are not provided, they are considered unknown. In the interests of matching the event!() macro as closely as possible, this might look like tracing::enabled!(target: "foo", Level::INFO, message, request) if we know the fields, or tracing::enabled!(target: "foo", Level::INFO) if we don't.

From an implementation perspective, this would construct a Callsite and Metadata just like event!(), register the callsite, test the Interest, and possibly call Subscriber::enabled() as well. The metadata::Kind field would have a new variant HINT that indicates this is an enabled!() call. Additionally, the line field would have the value None (as the enabled call is unlikely to be the same line as the event). Subscribers must be aware of HINT if they care about fields or line, such that they treat line: None as representing any potential line, and they treat an empty FieldSet as meaning the fields are unknown. register_callsite can also use HINT to determine that no events will be logged against this callsite and thus avoid doing things like preallocating storage for it; the call here is only to get an Interest, not to prepare for emitting events.

We should also note that enabled!() should be called from within the same file and module as the event!() call(s) it guards, as that info is in the metadata and therefore available to filters.

Because this imposes additional requirements on subscribers, this likely needs to be considered a breaking change, as existing subscribers that care about line or field names may produce false negatives from enabled!(). We could also put this in as a minor change where it just tests against LevelFilter::current(), and adds the more precise support after a breaking change; if we do this we should still accept target: and field names and just document that they are ignored for now but will be used in a future update.

Alternatives

The name tracing::enabled!() doesn't necessarily convey that false positives are possible. Of course, even delaying your computation to an event argument doesn't guarantee it's logged if the subscriber filters on field values. In any case, we could call this tracing::disabled!() since we do guarantee that part but users then have to write if !tracing::disabled(…) { which is awkward. tracing::maybe_enabled!(), tracing::possibly_enabled(), tracing::not_disabled!(), none of these alternatives I can think of roll off the tongue. The imprecision of tracing::enabled!() is probably worth tolerating for the convenient and searchable name.

It would be conceptually cool if we could do something like tracing::if_enabled { body containing events } that parses the body, identifies all the events, hoists the callsite and metadata generation for the events to the top (but retaining the correct lines), registers the callsites, and tests the interests, before entering the body. The Subscriber::enabled() check itself would still be at the point of the event, to allow temporal filtering to work as normal. I don't know if that's even possible to do (e.g. reliably identifying a macro invocation as being a tracing event), but even if so it sounds very impractical to implement and might be confusing to users.

Or we could just continue to not support this. But it seems a shame to do all this performant tracing but not have a good way for users to avoid unnecessary expensive computations when the tracing is dynamically disabled.

If we don't do this, we could at least have tracing::static_is_enabled!(level) that's basically just level < tracing::level_filters::STATIC_MAX_LEVEL, to provide an easily-discoverable way to do that check. Or maybe doing level < tracing::level_filters::LevelFilter::current(), though I don't know what to call that as it's not static anymore.

@hawkw hawkw added crate/tracing Related to the `tracing` crate kind/feature New feature or request labels Jan 6, 2022
hawkw added a commit that referenced this issue Jan 28, 2022
## Motivation

Closes: #1668

My usecase is different than the referenced "avoid doing something
expensive to log": I want to guard turning on `debug` mode for an ffi'd
library, based on some `target` that represents the "module" we care
about.

## Solution

The macro is very similar to `event!`, but adds a few simplistic cases,
and generates ever so slightly different code (to return the correct
value always. It also skips anything to do with `tracing-log`. I
considered (and tried), to share the impl between `event!` and
`enabled!`, but must confess I am not good at macros and got stuck. I
think they are sufficiently different, where copied impls, is easier to
read. We already manage 

Also, my project is on the crates.io version, so this would need to be
backported to 0.1, I can help with that with guidance.

Co-authored-by: Eliza Weisman <[email protected]>
Co-authored-by: David Barsky <[email protected]>
guswynn added a commit to guswynn/tracing that referenced this issue Feb 1, 2022
## Motivation

Closes: tokio-rs#1668

My usecase is different than the referenced "avoid doing something
expensive to log": I want to guard turning on `debug` mode for an ffi'd
library, based on some `target` that represents the "module" we care
about.

## Solution

The macro is very similar to `event!`, but adds a few simplistic cases,
and generates ever so slightly different code (to return the correct
value always. It also skips anything to do with `tracing-log`. I
considered (and tried), to share the impl between `event!` and
`enabled!`, but must confess I am not good at macros and got stuck. I
think they are sufficiently different, where copied impls, is easier to
read. We already manage 

Also, my project is on the crates.io version, so this would need to be
backported to 0.1, I can help with that with guidance.

Co-authored-by: Eliza Weisman <[email protected]>
Co-authored-by: David Barsky <[email protected]>
hawkw added a commit that referenced this issue Feb 2, 2022
Backports #1821 to `v0.1.x`.

## Motivation

Closes: #1668

My usecase is different than the referenced "avoid doing something
expensive to log": I want to guard turning on `debug` mode for an ffi'd
library, based on some `target` that represents the "module" we care
about.

## Solution

The macro is very similar to `event!`, but adds a few simplistic cases,
and generates ever so slightly different code (to return the correct
value always. It also skips anything to do with `tracing-log`. I
considered (and tried), to share the impl between `event!` and
`enabled!`, but must confess I am not good at macros and got stuck. I
think they are sufficiently different, where copied impls, is easier to
read. We already manage 

Co-authored-by: Eliza Weisman <[email protected]>
Co-authored-by: David Barsky <[email protected]>
kaffarell pushed a commit to kaffarell/tracing that referenced this issue May 22, 2024
Backports tokio-rs#1821 to `v0.1.x`.

## Motivation

Closes: tokio-rs#1668

My usecase is different than the referenced "avoid doing something
expensive to log": I want to guard turning on `debug` mode for an ffi'd
library, based on some `target` that represents the "module" we care
about.

## Solution

The macro is very similar to `event!`, but adds a few simplistic cases,
and generates ever so slightly different code (to return the correct
value always. It also skips anything to do with `tracing-log`. I
considered (and tried), to share the impl between `event!` and
`enabled!`, but must confess I am not good at macros and got stuck. I
think they are sufficiently different, where copied impls, is easier to
read. We already manage 

Co-authored-by: Eliza Weisman <[email protected]>
Co-authored-by: David Barsky <[email protected]>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
crate/tracing Related to the `tracing` crate kind/feature New feature or request
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants