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

Use Cow<'static, str> for Metadata strings #1020

Closed
wants to merge 29 commits into from

Conversation

dvdplm
Copy link
Contributor

@dvdplm dvdplm commented Oct 6, 2020

Allow Metadata to be dynamic (using Cow<'a, str>)

This experimental PR introduces Cow<'a, str> to be used instead of &'static str in Metadata as outlined in the 0.2 tracking ticket to allow the dynamic generation of Metadata.

We'd very much appreciate your feedback on this.

Rationale

When implementing tracing in Substrate (thanks and ❤️ for your great work here, it is an awesome project you are doing!), we ran into an issue with the current API.
In Substrate the innermost execution logic is compiled to Wasm and runs inside an executor, with its own memory. The Wasm runtime execution logic can change at any time which means we can't share or pre-emptively know the &'static str of a span from within the runtime and communicate with the outer infrastructure that implements the actual tracing (the inner just provides host functions). Thus we can't create the proper Metadata/Span and so forth for tracing.

We've resorted to pretty ugly hacks to at least provide this for levels, so the generic filters and alike work on that, but for target and name from traces within Wasm the existing filters don't work. For that we have to generate Metadata at runtime.

If we could provide a Cow to Metadata instead of &'static str, we could generate the entries on the fly and feed them into tracing. All tooling (like EnvFilter) would work just as before.

This PR is a first step to reach this goal.


Status:

  • switch tracing to store Cow<'a, str>
  • ensure nothing breaks
  • add API to provide dynamic Metadata
  • check for performance regression

Benchmarks comparing this branch and master as of October 20:

group                                     cow-oct-20                             master-oct21
-----                                     ----------                             ------------
dynamic/baseline_multithreaded            1.00      7.1±0.24µs        ? B/sec    1.00      7.1±0.27µs        ? B/sec
dynamic/baseline_single_threaded          1.00    171.1±0.79ns        ? B/sec    1.04    177.4±0.97ns        ? B/sec
dynamic/multithreaded                     1.00     12.3±0.39µs        ? B/sec    1.00     12.3±0.33µs        ? B/sec
dynamic/single_threaded                   1.00    610.0±6.30ns        ? B/sec    1.02    620.5±3.51ns        ? B/sec
event/root/multithreaded/1                1.00    42.6±11.16µs        ? B/sec    1.12    47.6±10.12µs        ? B/sec
event/root/multithreaded/10               1.04    65.7±11.18µs        ? B/sec    1.00    63.5±10.42µs        ? B/sec
event/root/multithreaded/50               1.03    126.5±8.81µs        ? B/sec    1.00    122.9±8.69µs        ? B/sec
event/root/single_threaded/1              1.06  1390.4±23.53ns        ? B/sec    1.00   1316.2±7.50ns        ? B/sec
event/root/single_threaded/10             1.04     13.8±0.11µs        ? B/sec    1.00     13.2±0.08µs        ? B/sec
event/root/single_threaded/50             1.04     69.0±0.58µs        ? B/sec    1.00     66.1±0.68µs        ? B/sec
event/shared_parent/multithreaded/1       1.00    39.2±12.28µs        ? B/sec    1.18    46.4±12.92µs        ? B/sec
event/shared_parent/multithreaded/10      1.09    70.1±11.94µs        ? B/sec    1.00    64.2±12.68µs        ? B/sec
event/shared_parent/multithreaded/50      1.04    184.6±8.97µs        ? B/sec    1.00    176.9±9.73µs        ? B/sec
event/unique_parent/multithreaded/1       1.05    39.3±10.76µs        ? B/sec    1.00    37.3±11.73µs        ? B/sec
event/unique_parent/multithreaded/10      1.16    72.9±11.95µs        ? B/sec    1.00    62.7±10.82µs        ? B/sec
event/unique_parent/multithreaded/50      1.00   165.7±10.63µs        ? B/sec    1.04    173.0±9.47µs        ? B/sec
event/unique_parent/single_threaded/1     1.02      2.2±0.02µs        ? B/sec    1.00      2.2±0.01µs        ? B/sec
event/unique_parent/single_threaded/10    1.01     21.7±0.20µs        ? B/sec    1.00     21.5±0.27µs        ? B/sec
event/unique_parent/single_threaded/50    1.01    108.9±1.48µs        ? B/sec    1.00    107.3±0.58µs        ? B/sec
log/dynamic/baseline_multithreaded        1.00      7.3±0.45µs        ? B/sec    1.01      7.4±0.27µs        ? B/sec
log/dynamic/baseline_single_threaded      1.01    407.5±2.39ns        ? B/sec    1.00    405.1±2.83ns        ? B/sec
log/dynamic/multithreaded                 1.00     12.1±0.35µs        ? B/sec    1.02     12.4±0.40µs        ? B/sec
log/dynamic/single_threaded               1.00    819.7±7.84ns        ? B/sec    1.00   816.1±11.16ns        ? B/sec
log/mixed/disabled                        1.04     86.5±0.39ns        ? B/sec    1.00     83.1±0.84ns        ? B/sec
log/mixed/disabled_by_level               1.11     36.8±0.19ns        ? B/sec    1.00     33.3±0.25ns        ? B/sec
log/static/baseline_multithreaded         1.00      7.1±0.28µs        ? B/sec    1.02      7.2±0.35µs        ? B/sec
log/static/baseline_single_threaded       1.00    310.9±1.67ns        ? B/sec    1.04    324.6±1.26ns        ? B/sec
log/static/disabled_level_many            1.11     37.0±0.28ns        ? B/sec    1.00     33.4±0.32ns        ? B/sec
log/static/disabled_level_one             1.08     36.0±0.27ns        ? B/sec    1.00     33.4±0.18ns        ? B/sec
log/static/disabled_many                  1.07     81.7±0.43ns        ? B/sec    1.00     76.7±1.81ns        ? B/sec
log/static/disabled_one                   1.06     52.1±0.82ns        ? B/sec    1.00     48.9±0.24ns        ? B/sec
log/static/enabled_many                   1.04    131.4±2.70ns        ? B/sec    1.00    126.8±0.56ns        ? B/sec
log/static/enabled_one                    1.03    131.1±0.91ns        ? B/sec    1.00    127.7±1.27ns        ? B/sec
log/static/multithreaded                  1.01      7.3±0.55µs        ? B/sec    1.00      7.2±0.24µs        ? B/sec
log/static/single_threaded                1.04    374.4±2.55ns        ? B/sec    1.00    360.5±1.70ns        ? B/sec
mixed/disabled                            1.02     64.3±0.57ns        ? B/sec    1.00     63.2±0.26ns        ? B/sec
mixed/disabled_by_level                   1.00      0.2±0.00ns        ? B/sec    1.00      0.2±0.00ns        ? B/sec
new_span/multithreaded/1                  1.00     44.7±8.63µs        ? B/sec    1.00    44.8±10.14µs        ? B/sec
new_span/multithreaded/10                 1.00    46.3±10.69µs        ? B/sec    1.17    54.4±11.18µs        ? B/sec
new_span/multithreaded/50                 1.02    69.5±10.71µs        ? B/sec    1.00    68.3±10.77µs        ? B/sec
new_span/single_thread/1                  1.00    447.9±1.63ns        ? B/sec    1.02   457.2±10.14ns        ? B/sec
new_span/single_thread/10                 1.00      4.5±0.03µs        ? B/sec    1.01      4.5±0.03µs        ? B/sec
new_span/single_thread/50                 1.00     22.5±0.11µs        ? B/sec    1.00     22.6±0.26µs        ? B/sec
static/baseline_multithreaded             1.00      6.9±0.31µs        ? B/sec    1.01      7.0±0.50µs        ? B/sec
static/baseline_single_threaded           1.00     96.1±0.53ns        ? B/sec    1.04    100.3±1.14ns        ? B/sec
static/disabled_level_many                1.00      0.2±0.00ns        ? B/sec    1.00      0.2±0.00ns        ? B/sec
static/disabled_level_one                 1.00      0.2±0.00ns        ? B/sec    1.00      0.2±0.00ns        ? B/sec
static/disabled_many                      1.00      0.6±0.01ns        ? B/sec    1.00      0.6±0.00ns        ? B/sec
static/disabled_one                       1.00      0.6±0.00ns        ? B/sec    1.00      0.6±0.00ns        ? B/sec
static/enabled_many                       1.00     28.8±0.14ns        ? B/sec    1.03     29.7±0.28ns        ? B/sec
static/enabled_one                        1.00     28.7±0.15ns        ? B/sec    1.04     29.7±0.16ns        ? B/sec
static/multithreaded                      1.00      6.7±0.34µs        ? B/sec    1.04      6.9±0.29µs        ? B/sec
static/single_threaded                    1.00     59.2±1.28ns        ? B/sec    1.02     60.2±0.30ns        ? B/sec

NOTE: requires changes in opentelemetry-rust as well
…e to just have `name` be a `Cow<'a, str>` instead for clarity.
* master:
  tracing: Instrument std::future::Future (tokio-rs#808)
  tracing: move `ValueSet` construction out of closures (tokio-rs#987)
Store Cows for name and target but return &str
Change test-only `CloseState` to use `String`
Undo a few changes that are no longer necessary
@dvdplm dvdplm requested review from hawkw and a team as code owners October 6, 2020 20:04
* upstream/master:
  subscriber: warn if trying to enable a statically disabled level (tokio-rs#990)
  subscriber: use macros for module declarations (tokio-rs#1009)
  chore: remove `stdlib.rs` (tokio-rs#1008)
  core: fix linked list tests reusing `Registration`s (tokio-rs#1016)
  subscriber: support dash in target names (tokio-rs#1012)
  docs: switch to intra-doc links in tracing-core (tokio-rs#1010)
  tracing-opentelemetry: implement additional record types (bool, i64, u64) (tokio-rs#1007)
  core: add intrusive linked list for callsite registry (tokio-rs#988)
  serde: allow tracing-serde to work on no_std. (tokio-rs#960)
  tracing: remove `Into<Option<Id>>` impl for `Span` (tokio-rs#1003)
  tracing: make `Entered` `!Send` (tokio-rs#1001)
  chore: fix nightly clippy warnings (tokio-rs#991)
  chore: bump all crate versions (tokio-rs#998)
  macros: fix the `tracing-macros` crate not compiling (tokio-rs#1000)
  tracing: prepare to release 0.1.21 (tokio-rs#997)
  core: prepare to release 0.1.17 (tokio-rs#996)
  subscriber: make `PartialOrd` & `Ord` impls more correct (tokio-rs#995)
  core, tracing: don't inline dispatcher::get_default (tokio-rs#994)
  core: make `Level` and `LevelFilter` `Copy` (tokio-rs#992)
@@ -122,7 +123,7 @@ impl<'a> Metadata<'a> {
/// Construct new metadata for a span or event, with a name, target, level, field
/// names, and optional source code location.
pub const fn new(

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

while with this we now have general support for dynamic creation, the current API, still won't allow for that. Probably want to add another fn dynamic_new where we can pass Cow<'a, str> into for dynamic dispatching.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I am afraid so ....

@dvdplm
Copy link
Contributor Author

dvdplm commented Oct 15, 2020

As it stands this PR uses if in a const fn which requires Rust 1.46. The project minimum rust version policy of guaranteed compatibility with three stable releases prior to the current means that this cannot be considered before Rust 1.49 is released, December 31 2020.

* upstream/master:
  opentelemetry: prepare for 0.8.0 release (tokio-rs#1036)
  docs: add favicon for extra pretty docs (tokio-rs#1033)
  subscriber: fix `reload` ergonomics (tokio-rs#1035)
  chore(deps): update crossbeam-channel requirement from 0.4.2 to 0.5.0 (tokio-rs#1031)
  opentelemetry: Assign default ids if missing (tokio-rs#1027)
  chore: remove deprecated add-path from CI (tokio-rs#1026)
  attributes:  fix `#[instrument(err)]` in case of early returns (tokio-rs#1006)
  core: remove mandatory liballoc dependency with no-std (tokio-rs#1017)
  chore(deps): update cfg-if requirement from 0.1.10 to 1.0.0 (tokio-rs#1023)
Copy link
Member

@hawkw hawkw left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thanks for working on this! Unfortunately, I think there are some changes we'll need to make to ensure that it works nicely with conditional support for liballoc. I left some comments detailing what we'll need to do in order to make that work.

tracing-log/src/lib.rs Outdated Show resolved Hide resolved
Comment on lines 64 to 80
name: Cow<'a, str>,

/// The part of the system that the span that this metadata describes
/// occurred in.
target: &'a str,
target: Cow<'a, str>,

/// The level of verbosity of the described span.
level: Level,

/// The name of the Rust module where the span occurred, or `None` if this
/// could not be determined.
module_path: Option<&'a str>,
module_path: Option<Cow<'a, str>>,

/// The name of the source code file where the span occurred, or `None` if
/// this could not be determined.
file: Option<&'a str>,
file: Option<Cow<'a, str>>,

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One fairly major issue with making this change: we've just changed tracing and tracing-core to support no-std platforms that don't have liballoc. Unfortunately, Cow is defined in liballoc. We'll need to change this to work gracefully on no_std platforms without alloc.

We now have an "alloc" feature flag for determining whether liballoc is supported, and APIs that depend on alloc can now require that feature. That should make it possible to conditionally support Cow only when alloc is availble, although it does make the API surface a little bit uglier.

Here's what I would recommend:

  1. Change the fields to something like this:

    /// ...
    #[cfg(feature = "alloc")]
    name: Cow<'a, str>,
    #[cfg(not(feature = "alloc"))]
    name: &'a str,
  2. We can't change the return type of API functions based on whether or not a feature flag is enabled, since this would make enabling the feature break code in crates that don't enable it. Therefore, we can't have methods like Metadata::file() and Metadata::line() return Option<&str> when alloc is disabled, and Option<Cow<'a, str>> when it is enabled. Instead, we'll need two separate APIs: one which is always available but only returns borrowed strings, and another which returns Cows and is only available when the "alloc" feature is enabled.

    I would expect the implementation to look something like this:

    impl<'a> Metadata<'a> {
        /// ...
        pub fn file(&'a self) -> Option<&'a str> {
            #[cfg(feature = "alloc")]
            self.file.as_ref().map(Cow::as_ref())
            #[cfg(not(feature = "alloc"))]
            self.file.as_ref()
        }
    
        /// ...
        #[cfg(feature = "alloc")]
        #[cfg_attr(docsrs, doc(cfg(feature = "alloc")))]
        pub fn file_cow(&self) -> Option<&Cow<'a, String>> {
            self.file.as_ref()
        }
    }

    (...and so on for the other fields).

    Note that I don't particularly care for the name file_cow (and target_cow etc), but I don't know if there are better options --- file_as_cow feels a little wordy? If you can think of a better naming scheme for these, we can go with that.

  3. Finally, I think we'll need two constructors. The const fn new will continue to take '&str's only, and always be available, regardless of features. We'll add a new constructor which takes Cows (or impl Into<Cow<'a, str>>s?), and have that constructor only be exposed when the "alloc" feature is enabled.

Unfortunately, this makes the API a little less pleasant to work with, but it's the only way to feature flag the use of Cow without making a non-additive feature that breaks code when it's enabled...

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Thank you for the detailed feedback, much appreciated!

I made the change as suggested under 1) and while a bit ugly it works fine.

As for your second point I don't think it's necessarily a problem: as long as we can build a Metadata with dynamic data, it's fine to keep returning &str. So for example we keep Metadata::file returning an Option<&str> regardless of how it was built. FWIW I started this work thinking we'd need to duplicate the API and have methods return Cows, but @gnunicorn suggested we just keep things as they were. Do you think there's a need for/value in having the *_cow() methods?

I also added a from_cow constructor for your third point, featured gated. Struggling a bit to come up with a sensible test for it though.

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

FWIW I started this work thinking we'd need to duplicate the API and have methods return Cows, but @gnunicorn suggested we just keep things as they were. Do you think there's a need for/value in having the *_cow() methods?

yeah, I really can't think of a good reason, why we'd need to expose the cow (in particular if non-mut) over just keeping the current expose functions.

Maybe re 2, I'd have the suggestion of just having two API-equivialent impl (and maybe even struct) blocks one for when the feature is activated and one without – and the earlier has the extra constructor for non-static-string. I think that would improve legibility quite a bit.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think that would improve legibility quite a bit.

I tried this and while the code does look better, I think I would need to duplicate the docs which increases the maintenance burden.

/// Lots of docs here to maintain
#[cfg(feature = "alloc")]
#[cfg_attr(docsrs, doc(cfg(any(feature = "std", feature = "alloc"))))]
pub struct Metadata<'a> {
}

/// Lots of docs here to maintain
#[cfg(not(feature = "alloc"))]
#[cfg_attr(docsrs, doc(cfg(not(any(feature = "std", feature = "alloc")))))]
pub struct Metadata<'a> {
}

#[cfg(not(feature = "alloc"))]
impl<'a> Metadata<'a> {
    /// Construct new metadata for a span or event, with a name, target, level, field
    /// names, and optional source code location.
    pub const fn new(}
}

#[cfg(feature = "alloc")]
impl<'a> Metadata<'a> {
    /// Construct new metadata for a span or event, with a name, target, level, field
    /// names, and optional source code location.
    pub const fn new()}

    /// Construct new metadata for a span or event, with a name, target, level, field
    /// names, and optional source code location using dynamically allocated data.
    pub fn from_cow() {}
}

impl<'a> Metadata<'a> {
    // common impls here
}

I think it's better to have an easier time maintaining the docs than more readable code in this case, but I'm easy and can do either.

@hawkw thoughts?

tracing-log/src/trace_logger.rs Show resolved Hide resolved
* upstream/master:
  chore(deps): update pin-project requirement from 0.4 to 1.0 (tokio-rs#1038)
  chore: remove duplicated section from tracing/README.md (tokio-rs#1046)
tracing-core/src/metadata.rs Outdated Show resolved Hide resolved
dvdplm and others added 5 commits October 20, 2020 09:30
* upstream/master:
  subscriber: remove TraceLogger (tokio-rs#1052)
  subscriber: make Registry::enter/exit much faster (tokio-rs#1058)
  chore(deps): update env_logger requirement from 0.7 to 0.8 (tokio-rs#1050)
* upstream/master:
  subscriber: update sharded-slab to 0.1, pool hashmap allocations (tokio-rs#1062)
  subscriber: remove deprecated type, structs, and methods tokio-rs#1030
  core: rename Subscriber to Collect (tokio-rs#1015)
  chore: fix rustdoc warning in tracing-subscriber (tokio-rs#1061)
@bryangarza
Copy link
Member

Seems that there probably still needed to be an additional round of code review on this right? Since this PR is pretty old, I'll close it, but feel free to open a new one :)

@bryangarza bryangarza closed this May 6, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

4 participants