add: example of integrating log (#148)

* chore: prefer to omit span name Signed-off-by: Andy Lok <andylokandy@hotmail.com> * add: example of integrating log Signed-off-by: Andy Lok <andylokandy@hotmail.com> * fix a false-alarm lint Signed-off-by: Andy Lok <andylokandy@hotmail.com> * fix a false-alarm lint again Signed-off-by: Andy Lok <andylokandy@hotmail.com> --------- Signed-off-by: Andy Lok <andylokandy@hotmail.com>
tikv · Jul 12, 2023 · c55e28e · c55e28e
1 parent 8af58da
commit c55e28e
Show file tree

Hide file tree

Showing 11 changed files with 99 additions and 29 deletions.
diff --git a/README.md b/README.md
@@ -69,7 +69,13 @@ There are some articles posted by the maintainer of minitrace:
 
 ### Why / What's the difference compared to 'X'?
 
-Most tracing libraries aims to provide more features, while minitrace always prioritize performance. Usually minitrace only provides basic and common tracing features.
+Most tracing libraries aims to provide more features, while minitrace always prioritize performance. 
+
+Rather than providing a full-featured tracing library, minitrace is designed to be simple, modular and extensible.
+You can easily compose your own tracing features on top of minitrace with minimal effort.
+
+For a practical illustration, refer to `examples/log.rs` to learn how to integrate the widely-used `log` library and
+its macros with minitrace in just 10 lines of code.
 
 ### Will you support OpenTelemetry feature 'X'?
 

diff --git a/minitrace-macro/README.md b/minitrace-macro/README.md
@@ -20,7 +20,7 @@ minitrace = "0.4" # minitrace-macro is within minitrace::prelude
 ```rust
 use minitrace::prelude::*;
 
-#[trace("foo")]
+#[trace]
 fn foo() {
     // function body
 }
@@ -40,7 +40,7 @@ fn foo() {
 ```rust
 use minitrace::prelude::*;
 
-#[trace("bar")]
+#[trace]
 async fn bar() {
     // function body
 }
@@ -55,7 +55,7 @@ async fn bar() {
 // }
 
 
-#[trace("qux", enter_on_poll = true)]
+#[trace(enter_on_poll = true)]
 async fn qux() {
     // function body
 }
@@ -77,10 +77,10 @@ A function instrumented by `trace` always require a local parent in the context.
 ```rust
 use minitrace::prelude::*;
 
-#[trace("foo")]
+#[trace]
 fn foo() {}
 
-#[trace("bar")]
+#[trace]
 async fn bar() {}
 
 let (root, collector) = Span::root("root");

diff --git a/minitrace/Cargo.toml b/minitrace/Cargo.toml
@@ -39,6 +39,8 @@ rand = "0.8"
 futures = "0.3"
 futures-timer = "3"
 mockall = "0.11"
+log = "0.4"
+env_logger = "0.10"
 
 [[bench]]
 name = "trace"

diff --git a/minitrace/benches/trace.rs b/minitrace/benches/trace.rs
@@ -5,15 +5,15 @@ use minitrace::local::LocalCollector;
 use minitrace::prelude::*;
 
 fn dummy_iter(i: usize) {
-    #[trace("")]
+    #[trace]
     fn dummy() {}
 
     for _ in 0..i {
         dummy();
     }
 }
 
-#[trace("")]
+#[trace]
 fn dummy_rec(i: usize) {
     if i > 1 {
         dummy_rec(i - 1);

diff --git a/minitrace/examples/asynchronous.rs b/minitrace/examples/asynchronous.rs
@@ -18,7 +18,7 @@ async fn iter_job(iter: u64) {
     other_job().await;
 }
 
-#[trace("other job", enter_on_poll = true)]
+#[trace(enter_on_poll = true)]
 async fn other_job() {
     for i in 0..20 {
         if i == 10 {

diff --git a/minitrace/examples/log.rs b/minitrace/examples/log.rs
@@ -0,0 +1,52 @@
+// Copyright 2023 TiKV Project Authors. Licensed under Apache-2.0.
+
+use std::io::Write;
+use std::net::SocketAddr;
+
+use futures::executor::block_on;
+use log::info;
+use minitrace::prelude::*;
+
+fn main() {
+    env_logger::Builder::from_default_env()
+        .format(|buf, record| {
+            // Add a local span to represent the log record
+            let mut span = LocalSpan::enter_with_local_parent(record.level().as_str());
+            span.add_property(|| ("message", record.args().to_string()));
+
+            // Output the log to stdout as usual
+            writeln!(buf, "[{}] {}", record.level(), record.args())
+        })
+        .filter_level(log::LevelFilter::Info)
+        .init();
+
+    let collector = {
+        let (root_span, collector) = Span::root("root");
+        let _span_guard = root_span.set_local_parent();
+
+        info!("event in root span");
+
+        let _local_span_guard = LocalSpan::enter_with_local_parent("child");
+
+        info!("event in child span");
+
+        collector
+    };
+
+    let spans = block_on(collector.collect());
+
+    const TRACE_ID: u64 = 42;
+    const SPAN_ID_PREFIX: u32 = 42;
+    const ROOT_PARENT_SPAN_ID: u64 = 0;
+    let bytes = minitrace_jaeger::encode(
+        String::from("service name"),
+        TRACE_ID,
+        ROOT_PARENT_SPAN_ID,
+        SPAN_ID_PREFIX,
+        &spans,
+    )
+    .expect("encode error");
+
+    let socket = SocketAddr::new("127.0.0.1".parse().unwrap(), 6831);
+    minitrace_jaeger::report_blocking(socket, &bytes).expect("report error");
+}
diff --git a/minitrace/examples/synchronous.rs b/minitrace/examples/synchronous.rs
@@ -9,7 +9,7 @@ fn func1(i: u64) {
     func2(i);
 }
 
-#[trace("func2")]
+#[trace]
 fn func2(i: u64) {
     std::thread::sleep(std::time::Duration::from_millis(i));
 }

diff --git a/minitrace/src/lib.rs b/minitrace/src/lib.rs
@@ -178,12 +178,12 @@
 //!   use minitrace::prelude::*;
 //!   use futures::executor::block_on;
 //!
-//!   #[trace("do_something")]
+//!   #[trace]
 //!   fn do_something(i: u64) {
 //!       std::thread::sleep(std::time::Duration::from_millis(i));
 //!   }
 //!
-//!   #[trace("do_something_async")]
+//!   #[trace]
 //!   async fn do_something_async(i: u64) {
 //!       futures_timer::Delay::new(std::time::Duration::from_millis(i)).await;
 //!   }
@@ -239,6 +239,11 @@
 //! [`Span::set_local_parent()`]: crate::Span::set_local_parent
 //! [`LocalSpan::enter_with_local_parent()`]: crate::local::LocalSpan::enter_with_local_parent
 
+// Suppress a false-positive lint from clippy
+// TODO: remove me once https://github.com/rust-lang/rust-clippy/issues/11076 is released
+#![allow(unknown_lints)]
+#![allow(clippy::arc_with_non_send_sync)]
+
 pub mod collector;
 pub mod future;
 pub mod local;
@@ -249,6 +254,8 @@ pub mod util;
 pub use crate::span::Span;
 /// An attribute-macro to help get rid of boilerplate.
 ///
+/// The span name is the function name by default. It can be customized by passing a string literal.
+///
 /// [`trace`] always require an local parent in the context. Make sure that the caller
 /// is within the scope of [`Span::set_local_parent()`].
 ///
@@ -257,12 +264,12 @@ pub use crate::span::Span;
 /// ```
 /// use minitrace::prelude::*;
 ///
-/// #[trace("foo")]
+/// #[trace]
 /// fn foo() {
 ///     // some work
 /// }
 ///
-/// #[trace("bar")]
+/// #[trace]
 /// async fn bar() {
 ///     // some work
 /// }

diff --git a/minitrace/src/local/local_span.rs b/minitrace/src/local/local_span.rs
@@ -42,9 +42,7 @@ impl LocalSpan {
             span_stack.add_properties(span_handle, properties);
         }
     }
-}
 
-impl LocalSpan {
     #[inline]
     pub(crate) fn enter_with_stack(
         event: &'static str,
@@ -112,6 +110,12 @@ span1 []
         );
     }
 
+    #[test]
+    fn local_span_noop() {
+        let mut span1 = LocalSpan::enter_with_local_parent("span1");
+        span1.add_property(|| ("k1", "v1".to_string()));
+    }
+
     #[test]
     #[should_panic]
     fn drop_out_of_order() {

diff --git a/minitrace/src/local/local_span_stack.rs b/minitrace/src/local/local_span_stack.rs
@@ -83,11 +83,6 @@ impl LocalSpanStack {
         span_line.collect(span_line_handle.span_line_epoch)
     }
 
-    pub fn current_collect_token(&mut self) -> Option<CollectToken> {
-        let span_line = self.current_span_line()?;
-        span_line.current_collect_token()
-    }
-
     #[inline]
     pub fn add_properties<I, F>(&mut self, local_span_handle: &LocalSpanHandle, properties: F)
     where
@@ -104,6 +99,11 @@ impl LocalSpanStack {
         }
     }
 
+    pub fn current_collect_token(&mut self) -> Option<CollectToken> {
+        let span_line = self.current_span_line()?;
+        span_line.current_collect_token()
+    }
+
     #[inline]
     fn current_span_line(&mut self) -> Option<&mut SpanLine> {
         self.span_lines.last_mut()

diff --git a/minitrace/tests/lib.rs b/minitrace/tests/lib.rs
@@ -171,8 +171,7 @@ fn multiple_threads_multiple_spans() {
             let local_collector = LocalCollector::start();
 
             for _ in 0..4 {
-                let merged =
-                    Span::enter_with_parents("merged", vec![&root_span1, &root_span2].into_iter());
+                let merged = Span::enter_with_parents("merged", vec![&root_span1, &root_span2]);
                 let _g = merged.set_local_parent();
                 let _local = LocalSpan::enter_with_local_parent("local");
                 scope.spawn(move |_| {
@@ -310,7 +309,7 @@ fn test_macro() {
         }
     }
 
-    #[trace("work", enter_on_poll = true)]
+    #[trace(enter_on_poll = true)]
     async fn work(millis: &u64) {
         let _g = Span::enter_with_local_parent("work-inner");
         tokio::time::sleep(std::time::Duration::from_millis(*millis))
@@ -319,7 +318,7 @@ fn test_macro() {
     }
 
     impl Bar {
-        #[trace("work2")]
+        #[trace]
         async fn work2(&self, millis: &u64) {
             let _g = Span::enter_with_local_parent("work-inner");
             tokio::time::sleep(std::time::Duration::from_millis(*millis))
@@ -328,7 +327,7 @@ fn test_macro() {
         }
     }
 
-    #[trace("work3")]
+    #[trace]
     async fn work3<'a>(millis1: &'a u64, millis2: &u64) {
         let _g = Span::enter_with_local_parent("work-inner");
         tokio::time::sleep(std::time::Duration::from_millis(*millis1))
@@ -383,12 +382,12 @@ root []
 
 #[test]
 fn macro_example() {
-    #[trace("do_something")]
+    #[trace]
     fn do_something(i: u64) {
         std::thread::sleep(std::time::Duration::from_millis(i));
     }
 
-    #[trace("do_something_async")]
+    #[trace]
     async fn do_something_async(i: u64) {
         futures_timer::Delay::new(std::time::Duration::from_millis(i)).await;
     }
@@ -469,7 +468,7 @@ fn max_span_count() {
         block_on(collector.collect());
     }
 
-    #[trace("recursive")]
+    #[trace]
     fn recursive(n: usize) {
         if n > 1 {
             recursive(n - 1);