Feature: minitrace::Span::current()

[taqtiqa-mark]

I can't find clear documentation or examples showing the following Tracing functionality is possible in minitrace.

Specifically, in Tracing the tracing::Span::current() involves a thread local lookup, so you only want to do this once for all the record(...) actions within the function. Hence, you end up with something like the following:

fn span_setup(&span) {
    span.as_ref().unwrap()
}
fn mine() {
            let span: Option<_>;
            if cfg!(feature = "traceable") {
                span = Some(tracing::Span::current());
            } else {
                span = None;
            }
       //
       // Other coded logic here
       //
        #[cfg(feature = "traceable")]
        {
            let s = span_setup(&span);
            s.record(
                "http.status_code",
                &format!("{:?}", msg.head.subject).as_str(),
            );
            ...
        }
        // other coded logic
        // other `let s = span_setup(&span); s.record; ....` actions
}

In case it helps anyone else coming down this path...

As best I can tell, the minitrace workaround for not having minitrace::Span::current() is to use Cargo features and this function signature "trick" to pass the last parent span around.

This workaround is required, as best I know, when:

• you want to record within the function
• you want to spawn a thread and trace it under the span where it was spawned

The feature of this workaround is that it becomes redundant to use the #[trace(...)] attribute, because we have to create a child of the parent span that is passed in via the 'trick'

fn d(
    va: std::string::String,
    #[cfg(feature = "traceable")] span: &minitrace::Span,
) 
{
....
}

fn c(
    va: std::string::String,
    #[cfg(feature = "traceable")] span: &minitrace::Span,
) { 
    #[cfg(feature = "traceable")]
    let span = Span::enter_with_parent("A child span", span);

    #[cfg(feature = "debug")]
    let d = d(a,b, &span)

    #[cfg(not(feature = traceable))]
    let d = d(a,b)
    //
    // One could use if cfg!(...) { ... } else { ... }
    // However, that would leave a run-time footprint.
    ... 
}

Where the Cargo features in your crate are:

...

[features]
traceable = [
  "minitrace",
  "minitrace-jaeger",
  "rand"
]
trace = [
  "traceable",
  "debug",
  "error",
  "warn",
  "info",
]
debug = [
  "traceable",
  "error",
  "warn",
  "info",
]
error = [
  "traceable",
  "warn",
  "info",
]
warn = [
  "traceable",
  "info",
]
info = ["traceable"]

...

In fact thinking about it some more.... I'm beginning to wonder if this "workaround" is not where the end state might be?

I believe it will come down to the relative 'cost/expense' of mintrace::Span::current() compared to Span::enter_with_parent("A child span", &span);

Hopefully, mintrace::Span::current() is feasible, because the workaround does end up creating a child span just for the record actions.

Hopefully that makes sense?

[taqtiqa-mark]

Long story short, when you want to spawn threads, or record within a function/span, the ergonomics are not as great as they might be.

Ideally, one would like to land at this, assuming the user has adopted the Cargo features convention (or whatever they like):

#[cfg(feature = "debug")]
fn a(s: String){
    #[cfg(feature="traceable")]
    span= Span::current();

    #[cfg(feature="info")]
    span.record("some.useful", "information");

    #[cfg(feature="debug")]
    span.record("some.useful.data", timestamp);
    ...
}

[andylokandy]

According to my understanding of your example, your example is trying to filter the spans by static feature flag of logging levels (warn, info, debug, disable, etc).

If my understanding is right, minitrace already has some workaround to address the problem you've mentioned:

// record property by condition
let _g = LocalSpan::enter_with_local_parent();
#[cfg(feature="debug")]
_g.add_property("some.useful", "information");

// record span by condition
fn main() {
    let root = Span::root();
    let _g = root.set_local_parent();
    do_stuff();
}

fn do_stuff() {
    #[cfg(feature="debug")]
    let _g = LocalSpan::enter_with_local_parent();
}

// record span across threads by condition
fn main() {
    let root = Span::root();
    
    #[cfg(feature="debug")]
    let span = Span::enter_with_parent("spawn", &root);

    std::thread::spawn(move || {
        #[cfg(feature="debug")]
        let _g = span.set_local_parent();
        do_stuff()
    });
}

fn do_stuff() {
    #[cfg(feature="debug")]
    let _g = LocalSpan::enter_with_local_parent();
}

[andylokandy]

Indeed, too many cfg is not ergonomic (maybe?). So here is my very initial thought about what minitrace can be modified to improve the experience:

// record property by condition
let _g = LocalSpan::enter_with_local_parent();
_g.add_property::<DEBUG>::("some.useful", "information");

// record span by condition
fn main() {
    let root = Span::root();
    let _g = root.set_local_parent();
    do_stuff();
}

fn do_stuff() {
    let _g = LocalSpan::<DEBUG>::enter_with_local_parent();
}

// record span across threads by condition
fn main() {
    let root = Span::root();
    
    let span = Span::enter_with_parent::<DEBUG>::("spawn", &root);

    std::thread::spawn(move || {
        let _g = span.set_local_parent();
        do_stuff()
    });
}

fn do_stuff() {
    let _g = LocalSpan::enter_with_local_parent::<DEBUG>::();
}

and then specify the logging level in Cargo.toml like:

minitrace = { version = "0.4", features = [ "debug" ] }

[taqtiqa-mark]

Thanks for the feedback. Initially I'd also thought about Span::enter_with_parent::<DEBUG>::("spawn", &root);. However, after a while the use of switchable levels in minitrace seemed unnecessary, and possibly out of minitrace scope?

Also, we are in the Rust community, and the "empowering everyone" goal resonates with me. Generics, etc in user facing code makes it look more complicated than, IMO, it needs to be.

One of the reasons I'm switching from Tracing is because minitrace is so elegant/simple in addition to the performance (simplicity/elegance, I think, is related to maintaining that performance). I was able to better trace some code in a couple of hours than I'd been able to after days of reading and wrestling with tracing, opentelemetry, tracing-opentelemetry and tracing-jaeger (is I have remebered all the crates correctly)

First the unnecessary:
Cargo already offers a way provide switchable levels already so this feature is complete, IMO.
True Cargo could do things a little better. But I see no reason to clutter minitrace logic with levels. Also directing users to use Cargo and #[cfg(features=...)] gives them more power - then can define the level how they wish. Example: debuggable, non-english, etc.

Next the out of scope: Is related to the last point - how a user names their levels, and even how many they have is out out scope of mintrace. Leave users free do do what they need. If levels: debug, verbose, all-the-things make sense in their context, lets leave them free to do that?

In terms of ergonomics, given the power and flexibility using Cargo provides I don't think this is too high a price to pay:

#[cfg(features = "verbose")]
span.record(...)

Compared to being told. no we won't implement ALLTHETHINGS in:

LocalSpan::enter_with_local_parent::<ALLTHETHINGS>::();

Hopefully I haven't mis-understood.

But I think "separation of concerns" suggest how I name them and how many levels of trace output I need is not relevant to producing traceoutput in the most efficient way possible.

If I want to be able to compile-out all tracing, I have to use cfg and cfg_attr attributes. So this seems to me to be preferred route.

I need to think a little more about the examples you've given. I'm leaning towards closing this or changing to a documentation/examples issue.

[taqtiqa-mark]

OK, I think I understand things a little better.

Parking workarounds, and levels, because neither is strictly the subject of this feature request - I'll open a separate issue for level functionality.

I'll take your three use cases as a starting point - thanks for drawing them up, they are useful. I'll open a separate issue to address ergonomics of managing spans, and I'll address the three use-case you identify there.

IIUC, you accept there is a need for mintrace::Span::current() and that it shouldn't incur enough of a penalty to justify advising users to pass spans via their function arguments?

[andylokandy]

IIUC, you accept there is a need for mintrace::Span::current() and that it shouldn't incur enough of a penalty to justify advising users to pass spans via their function arguments?

My only question is: what will the user do with the span returned from mintrace::Span::current()? If the only use case is to spawn a new span, we can use enter_with_local_parent().

[taqtiqa-mark]

My only question is: what will the user do with the span returned from mintrace::Span::current()?

The use case is: The span is created by #[trace(...)] and some recording occurs within the function. IIUC the enter_with_* would result in one additional, unnecessary, span being created. Correct?

Example:

#[cfg_attr(feature = "debug", trace("example"))]
fn a(s: String){
    #[cfg(feature="debug")]
    {
    span= Span::current();
    span.record("some.useful", "information");
    }
    ...
}

[taqtiqa-mark]

Apologies, @andylokandy I overlooked this:

If the only use case is to spawn a new span...

The use case is to avoid spawning a new span. Rather, it returns the span created by #[trace(...)]

[andylokandy]

Considering property recording, we may be able to solve it in another way:

#[cfg_attr(feature = "debug", trace("example"))]
fn a(s: String){
    #[cfg(feature="debug")]
    minitrace::event("some.useful", "information");  // a new API which, internally, adds property to the local parent
    ...
}

[taqtiqa-mark]

Without knowing the impl details I assume the performance impact/cost of implementing Span::current() will be the same as the Tracing crate.

One idea that might eliminate any performance impact is to add a parameter to the proc-macro-attribute: #[trace( "my-trace", recorder=spanr)], with that the following would just work:

#[trace("my-trace", recorder=my_spanr)]
fn a(s: String){
    my_spanr.record("key","value");
}

Thoughts?
Would that likely allow one to incur a lower performance-cost than implementing Span::current() or minitrace::event(...)?

If so, I would amend the feature to be a change to the proc-macro-attribute - this is the only use case I am aware of.

[andylokandy]

Currently, LocalSpan only has two functionalities: to end a span on drop() and to add_property(). The latter is more ergonomic to be refactored into minitrace::event(), I think.

And my concern of Span::current() is not all about performance but is the fact that it may create an alias of a LocalSpan and then two drops will be recorded.

[andylokandy]

One idea that might eliminate any performance impact is to add a parameter to the proc-macro-attribute: #[trace( "my-trace", recorder=spanr)], with that the following would just work:

I am not sure whether introducing a local variable to the generated span is a good design. @zhongzc What do you think?

[taqtiqa-mark]

My reservation with minitrace::event() is related to OpenTelemetry. My understanding is that the add_property() ( or record in tracing) stashes data in Tags (or what show up as Tags in Jaeger). While event data I believe shows up as Log entries.

I could be wrong but I think the OTel specs would need to be checked.

Per my previous comments, possibly in another issue, so I'll note them here:
I'm not persuaded there are grounds to introduce events/log-entries into minitracing. Instead the user should be encouraged to adopt the new-function tracing idiom/pattern I've described elsewhere.

[taqtiqa-mark]

I am not sure whether introducing a local variable to the generated span is a good design.

Ack the concern, that did make me think a little harder, and you'd probably want to actually do this:

#[trace("this-span", recorder_target = "other-span", recorder=my_spanr)]
fn a(s: String){
    my_spanr.record("key","value")
}

//OR 

#[trace("this-span", recorder_target = "this-span", recorder=my_spanr)]
fn a(s: String){
    my_spanr.record("key","value")
}

where recorder_target = "this-span" would be the default if the parameter recorder_target is not given. Likewise recorder=span seems a sane default that would mean for 80% of cases no extra parameter would need to be given.

[taqtiqa-mark]

@andylokandy not sure I understand your thread workaround example here. As best I can tell it is not possible to move the thread::spawn() inside do_stuff(). Correct?

[andylokandy]

not sure I understand your thread workaround example #117 (comment). As best I can tell it is not possible to move the thread::spawn() inside do_stuff(). Correct?

Do you want this:

fn main() {
    let root = Span::root();
    
    let span = Span::enter_with_parent("spawn", &root);
    std::thread::spawn(move || {
        let _g = span.set_local_parent();
        do_stuff()
    });
}

fn do_stuff() {
    let span = enter_with_local_parent("spawn in spwan");
    std::thread::spawn(move || {
        let _g = span.set_local_parent();
        do_stuff2();
        ....
    });
}

[andylokandy]

SpanContext is added for sending the information of current span to remote server in #153