Introduce tokio-trace

Cargo.toml

@@ -38,6 +38,8 @@ members = [
   "tokio-timer",
   "tokio-tcp",
   "tokio-tls",
+  "tokio-trace",
+  "tokio-trace/tokio-trace-core",
   "tokio-udp",
   "tokio-uds",
 ]

tokio-trace/Cargo.toml

@@ -0,0 +1,27 @@
+[package]
+name = "tokio-trace"
+version = "0.0.1"
+authors = ["Eliza Weisman <eliza@buoyant.io>"]
+license = "MIT"
+repository = "https://github.com/tokio-rs/tokio"
+homepage = "https://tokio.rs"
+description = """
+A scoped, structured logging and diagnostics system.
+"""
+categories = ["development-tools::debugging", "asynchronous"]
+keywords = ["logging", "tracing"]
+
+[dependencies]
+tokio-trace-core = { path = "tokio-trace-core" }
+
+[dev-dependencies]
+ansi_term = "0.11"
+humantime = "1.1.1"
+futures = "0.1"
+log = "0.4"
+
+# These are used for the "basic" example from the tokio-trace-prototype repo,
+# which is currently not included as it used the `tokio-trace-log` crate, and
+# that crate is currently unstable.
+# env_logger = "0.5"
+# tokio-trace-log = { path = "../tokio-trace-log" }

tokio-trace/LICENSE

@@ -0,0 +1,25 @@
+Copyright (c) 2019 Tokio Contributors
+
+Permission is hereby granted, free of charge, to any
+person obtaining a copy of this software and associated
+documentation files (the "Software"), to deal in the
+Software without restriction, including without
+limitation the rights to use, copy, modify, merge,
+publish, distribute, sublicense, and/or sell copies of
+the Software, and to permit persons to whom the Software
+is furnished to do so, subject to the following
+conditions:
+
+The above copyright notice and this permission notice
+shall be included in all copies or substantial portions
+of the Software.
+
+THE SOFTWARE IS PROVIDED "AS IS", WITHOUT WARRANTY OF
+ANY KIND, EXPRESS OR IMPLIED, INCLUDING BUT NOT LIMITED
+TO THE WARRANTIES OF MERCHANTABILITY, FITNESS FOR A
+PARTICULAR PURPOSE AND NONINFRINGEMENT. IN NO EVENT
+SHALL THE AUTHORS OR COPYRIGHT HOLDERS BE LIABLE FOR ANY
+CLAIM, DAMAGES OR OTHER LIABILITY, WHETHER IN AN ACTION
+OF CONTRACT, TORT OR OTHERWISE, ARISING FROM, OUT OF OR
+IN CONNECTION WITH THE SOFTWARE OR THE USE OR OTHER
+DEALINGS IN THE SOFTWARE.

tokio-trace/README.md

@@ -0,0 +1,163 @@
+# tokio-trace
+
+A scoped, structured logging and diagnostics system.
+
+## Overview
+
+`tokio-trace` is a framework for instrumenting Rust programs to collect
+structured, event-based diagnostic information.
+
+In asynchronous systems like Tokio, interpreting traditional log messages can
+often be quite challenging. Since individual tasks are multiplexed on the same
+thread, associated events and log lines are intermixed making it difficult to
+trace the logic flow. `tokio-trace` expands upon logging-style diagnostics by
+allowing libraries and applications to record structured events with additional
+information about *temporality* and *causality* — unlike a log message, a span
+in `tokio-trace` has a beginning and end time, may be entered and exited by the
+flow of execution, and may exist within a nested tree of similar spans. In
+addition, `tokio-trace` spans are *structured*, with the ability to record typed
+data as well as textual messages.
+
+The `tokio-trace` crate provides the APIs necessary for instrumenting libraries
+and applications to emit trace data.
+
+## Usage
+
+First, add this to your `Cargo.toml`:
+
+```toml
+[dependencies]
+tokio-trace = { git = "https://github.com/tokio-rs/tokio" }
+```
+
+Next, add this to your crate:
+
+```rust
+#[macro_use]
+extern crate tokio_trace;
+```
+
+This crate provides macros for creating `Span`s and `Event`s, which represent
+periods of time and momentary events within the execution of a program,
+respectively.
+
+As a rule of thumb, _spans_ should be used to represent discrete units of work
+(e.g., a given request's lifetime in a server) or periods of time spent in a
+given context (e.g., time spent interacting with an instance of an external
+system, such as a database). In contrast, _events_ should be used to represent
+points in time within a span — a request returned with a given status code,
+_n_ new items were taken from a queue, and so on.
+
+`Span`s are constructed using the `span!` macro, and then _entered_
+to indicate that some code takes place within the context of that `Span`:
+
+```rust
+// Construct a new span named "my span".
+let mut span = span!("my span");
+span.enter(|| {
+    // Any trace events in this closure or code called by it will occur within
+    // the span.
+});
+// Dropping the span will close it, indicating that it has ended.
+```
+
+The `Event` type represent an event that occurs instantaneously, and is
+essentially a `Span` that cannot be entered. They are created using the `event!`
+macro:
+
+```rust
+use tokio_trace::Level;
+event!(Level::INFO, "something has happened!");
+```
+
+Users of the [`log`] crate should note that `tokio-trace` exposes a set of macros for
+creating `Event`s (`trace!`, `debug!`, `info!`, `warn!`, and `error!`) which may
+be invoked with the same syntax as the similarly-named macros from the `log`
+crate. Often, the process of converting a project to use `tokio-trace` can begin
+with a simple drop-in replacement.
+
+Let's consider the `log` crate's yak-shaving example:
+
+```rust
+#[macro_use]
+extern crate tokio_trace;
+use tokio_trace::field;
+
+pub fn shave_the_yak(yak: &mut Yak) {
+    // Create a new span for this invocation of `shave_the_yak`, annotated
+    // with  the yak being shaved as a *field* on the span.
+    span!("shave_the_yak", yak = field::debug(&yak)).enter(|| {
+        // Since the span is annotated with the yak, it is part of the context
+        // for everything happening inside the span. Therefore, we don't need
+        // to add it to the message for this event, as the `log` crate does.
+        info!(target: "yak_events", "Commencing yak shaving");
+
+        loop {
+            match find_a_razor() {
+                Ok(razor) => {
+                    // We can add the razor as a field rather than formatting it
+                    // as part of the message, allowing subscribers to consume it
+                    // in a more structured manner:
+                    info!({ razor = field::display(razor) }, "Razor located");
+                    yak.shave(razor);
+                    break;
+                }
+                Err(err) => {
+                    // However, we can also create events with formatted messages,
+                    // just as we would for log records.
+                    warn!("Unable to locate a razor: {}, retrying", err);
+                }
+            }
+        }
+    })
+}
+```
+
+You can find examples showing how to use this crate in the examples directory.
+
+### In libraries
+
+Libraries should link only to the `tokio-trace` crate, and use the provided
+macros to record whatever information will be useful to downstream consumers.
+
+### In executables
+
+In order to record trace events, executables have to use a `Subscriber`
+implementation compatible with `tokio-trace`. A `Subscriber` implements a way of
+collecting trace data, such as by logging it to standard output.
+
+Unlike the `log` crate, `tokio-trace` does *not* use a global `Subscriber` which
+is initialized once. Instead, it follows the `tokio` pattern of executing code
+in a context. For example:
+
+```rust
+#[macro_use]
+extern crate tokio_trace;
+
+let my_subscriber = FooSubscriber::new();
+
+tokio_trace::subscriber::with_default(subscriber, || {
+    // Any trace events generated in this closure or by functions it calls
+    // will be collected by `my_subscriber`.
+})
+```
+
+This approach allows trace data to be collected by multiple subscribers within
+different contexts in the program. Alternatively, a single subscriber may be
+constructed by the `main` function and all subsequent code executed with that
+subscriber as the default. Any trace events generated outside the context of a
+subscriber will not be collected.
+
+The executable itself may use the `tokio-trace` crate to instrument itself as well.
+
+[`log`]: https://docs.rs/log/0.4.6/log/
+
+## License
+
+This project is licensed under the [MIT license](LICENSE).
+
+### Contribution
+
+Unless you explicitly state otherwise, any contribution intentionally submitted
+for inclusion in Tokio by you, shall be licensed as MIT, without any additional
+terms or conditions.

tokio-trace/benches/no_subscriber.rs

@@ -0,0 +1,44 @@
+#![feature(test)]
+#[macro_use]
+extern crate tokio_trace;
+#[macro_use]
+extern crate log;
+extern crate test;
+use test::Bencher;
+
+#[bench]
+fn bench_span_no_subscriber(b: &mut Bencher) {
+    b.iter(|| {
+        span!("span");
+    });
+}
+
+#[bench]
+fn bench_log_no_logger(b: &mut Bencher) {
+    b.iter(|| {
+        log!(log::Level::Info, "log");
+    });
+}
+
+#[bench]
+fn bench_costly_field_no_subscriber(b: &mut Bencher) {
+    b.iter(|| {
+        span!(
+            "span",
+            foo = tokio_trace::field::display(format!("bar {:?}", 2))
+        );
+    });
+}
+
+#[bench]
+fn bench_no_span_no_subscriber(b: &mut Bencher) {
+    b.iter(|| {});
+}
+
+#[bench]
+fn bench_1_atomic_load(b: &mut Bencher) {
+    // This is just included as a baseline.
+    use std::sync::atomic::{AtomicUsize, Ordering};
+    let foo = AtomicUsize::new(1);
+    b.iter(|| foo.load(Ordering::Relaxed));
+}

tokio-trace/benches/subscriber.rs

@@ -0,0 +1,121 @@
+#![feature(test)]
+
+#[macro_use]
+extern crate tokio_trace;
+extern crate test;
+use test::Bencher;
+
+use std::sync::Mutex;
+use tokio_trace::{field, span, Id, Metadata};
+
+/// A subscriber that is enabled but otherwise does nothing.
+struct EnabledSubscriber;
+
+impl tokio_trace::Subscriber for EnabledSubscriber {
+    fn new_span(&self, span: &Metadata) -> Id {
+        let _ = span;
+        Id::from_u64(0)
+    }
+
+    fn record_debug(&self, span: &Id, field: &field::Field, value: &::std::fmt::Debug) {
+        let _ = (span, field, value);
+    }
+
+    fn add_follows_from(&self, span: &Id, follows: Id) {
+        let _ = (span, follows);
+    }
+
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        let _ = metadata;
+        true
+    }
+
+    fn enter(&self, span: &Id) {
+        let _ = span;
+    }
+
+    fn exit(&self, span: &Id) {
+        let _ = span;
+    }
+}
+
+/// Simulates a subscriber that records span data.
+struct Record(Mutex<Option<String>>);
+
+impl tokio_trace::Subscriber for Record {
+    fn new_span(&self, span: &Metadata) -> Id {
+        *self.0.lock().unwrap() = Some(span.name().to_string());
+        Id::from_u64(0)
+    }
+
+    fn record_debug(&self, _span: &Id, _field: &field::Field, value: &::std::fmt::Debug) {
+        *self.0.lock().unwrap() = Some(format!("{:?}", value));
+    }
+
+    fn add_follows_from(&self, span: &Id, follows: Id) {
+        let _ = (span, follows);
+    }
+
+    fn enabled(&self, metadata: &Metadata) -> bool {
+        let _ = metadata;
+        true
+    }
+
+    fn enter(&self, span: &Id) {
+        let _ = span;
+    }
+
+    fn exit(&self, span: &Id) {
+        let _ = span;
+    }
+}
+
+const N_SPANS: usize = 100;
+
+#[bench]
+fn span_no_fields(b: &mut Bencher) {
+    tokio_trace::subscriber::with_default(EnabledSubscriber, || b.iter(|| span!("span")));
+}
+
+#[bench]
+fn span_repeatedly(b: &mut Bencher) {
+    #[inline]
+    fn mk_span(i: u64) -> tokio_trace::Span<'static> {
+        span!("span", i = i)
+    }
+
+    let n = test::black_box(N_SPANS);
+    tokio_trace::subscriber::with_default(EnabledSubscriber, || {
+        b.iter(|| (0..n).fold(mk_span(0), |_, i| mk_span(i as u64)))
+    });
+}
+
+#[bench]
+fn span_with_fields(b: &mut Bencher) {
+    tokio_trace::subscriber::with_default(EnabledSubscriber, || {
+        b.iter(|| {
+            span!(
+                "span",
+                foo = "foo",
+                bar = "bar",
+                baz = 3,
+                quuux = tokio_trace::field::debug(0.99)
+            )
+        })
+    });
+}
+
+#[bench]
+fn span_with_fields_record(b: &mut Bencher) {
+    tokio_trace::subscriber::with_default(Record(Mutex::new(None)), || {
+        b.iter(|| {
+            span!(
+                "span",
+                foo = "foo",
+                bar = "bar",
+                baz = 3,
+                quuux = tokio_trace::field::debug(0.99)
+            )
+        })
+    });
+}