Selective high frequency println

In the following, main, needle, foo, bar, blah, boo, hff are functions. ... represents arbitrary # of stack frames, and hff is a high frequency function, i.e. called thousands of times / frame, and 60fps.

Within a single frame, if we take snapshots of the stackframe, we might get:

main, ..., needle, ..., hff
main, ..., foo, ..., hff
main, ..., bar, ..., hff
main, ..., blah, ..., hff
main, ..., boo, ..., hff

Now, if I just add a println! into hff, what's going to happen is that it is going to flood my console.log / println.

I want to have a "selective" println, where it says: hey, look at the stack frames, if it's from needle, do println, if it's from foo, bar, blah, boo, don't do println.

One way to do this is to change fn hff(args) to fn hff(stack_info: Stack_Info,, args) but this is intrusive -- this 'stack_info: Stack_Info`(1) needs to be threaded everywhere and (2) useless outside of debugging.

Is there a cleaner way to solve this problem ?

You can try to use the backtrace crate to capture and analyze the stacktrace at runtime. You'll probably need debug info enabled and readable in order to actually get the function names.

Note that you'll certainly won't want to use the basic println for that, even with some calls filtered out. Printing to stdout requires a mutex lock, which will make it too slow to do hundreds of thousands times per second. In fact, even if you don't take the lock, instead writing directly to the file descriptor, I think you'll get a significant slowdown, even if you write into a file. Thus you'll probably want a separate logging thread, with your println calls cheaply sending data to that thread via channels, and the thread doing the slow work of writing the data.

It's likely that one of the logger implementations out there can already do all that stuff out of the box.

You could use a thread-local. Perhaps even a scoped one (even though the main point of that crate is to be able to store data with lifetimes, it's also an easy way to ensure you properly set and unset thread local state).

for example...
use scoped_tls::scoped_thread_local;

scoped_thread_local!(static NEEDLE: ());

fn needle() {
    NEEDLE.set(&(), || {
        f();
    });
}

fn f() {
    hff()
}

fn hff() {
    if NEEDLE.is_set() {
        println!("hff from needle");
    }
}

fn foo() {
    f()
}

fn bar() {
    f()
}

fn main() {
    foo();
    needle();
    bar();
}

(run on rustexplorer)

2 Likes

Not sure if this is exactly what you are asking for but the tracing crate can do something like this:

main.rs:

fn main() {
    tracing_subscriber::fmt()
        .with_env_filter(tracing_subscriber::filter::EnvFilter::from_default_env())
        .init();
    println!("Hello, world!");
    entry_point();
}

fn entry_point() {
    a();
    b();
    c();
}

fn hff() {
    tracing::trace!("foo");
}

fn a() {
    hff();
}

#[tracing::instrument]
fn b() {
    hff();
}

fn c() {
    hff();
}

If you run this program with environment variable RUST_LOG=trace you will observe:

$ RUST_LOG=trace cargo r
    Finished dev [unoptimized + debuginfo] target(s) in 0.03s
     Running `target/debug/tracing-sandbox`
Hello, world!
2024-01-16T21:28:02.676954Z TRACE tracing_sandbox: foo
2024-01-16T21:28:02.677090Z TRACE b: tracing_sandbox: foo
2024-01-16T21:28:02.677158Z TRACE tracing_sandbox: foo

But with RUST_LOG='[b]=trace':

$ RUST_LOG='[b]=trace' cargo r
    Finished dev [unoptimized + debuginfo] target(s) in 0.02s
     Running `target/debug/tracing-sandbox`
Hello, world!
2024-01-16T21:28:40.118720Z TRACE b: tracing_sandbox: foo
3 Likes