How to use FnValue?

[dvtomas]

What is the proper way to use FnValue? If I understand it's purpose, it's the right way to avoid potentially expensive serialization when a logging statement doesn't actually log, a typical example being a debug! statement when a LevelFilter is set to reject anything below INFO level.

However, the FnValue documentation doesn't help much, all it tells us is: "Explicit lazy-closure Value". Digging into the examples reveals this: FnValue(|_ : &Record| slow_fib(40)));, so I tried my variation on that:

#[macro_use]
extern crate slog;
extern crate slog_async;
extern crate slog_term;

use std::fmt;
use slog::{Drain, FnValue, Level, Record};

struct Foo {
    value: &'static str
}

impl fmt::Debug for Foo {
    fn fmt(&self, f: &mut fmt::Formatter) -> Result<(), fmt::Error> {
        eprintln!("Foo::fmt = {:?}", self.value);
        write!(f, "{}", self.value)
    }
}


fn main() {
    let decorator = slog_term::TermDecorator::new().build();
    let drain = slog_term::FullFormat::new(decorator)
        .use_original_order()
        .build()
        .filter_level(Level::Debug)
        .fuse();
    let drain = slog_async::Async::new(drain).build().fuse();

    let log = slog::Logger::root(drain, o!("logger" => "root"));

    info!(log, "info"; "foo" => ?Foo{value: "info"});
    trace!(log, "trace"; "FnValue" => FnValue(|_ : &Record| format!("{:?}", Foo {value: "lazy trace"})));
}

Inside the impl fmt::Debug for Foo I perform a side-effecting println to see when it is evaluated. I would expect it doesn't get evaluated on the last trace! call that is rejected by the LevelFilter, but it actually gets called! When I run the program, I get this:

Foo::fmt = "info"
Foo::fmt = "lazy trace"
Sep 19 21:14:36.071 INFO info, logger: root, foo: info

What is going on? How can I avoid doing any work when the logging statement doesn't actually log?

[dpc]

The issue is a combination of Async and filtering.

All the values in immediate logging statements are borrowed, so can't be sent to a different thread as-is. Async will resolve them in-place before sending. So only owned values (ones associated with a logger, and internally Arced) will be cheaply sent to a different thread without evaluating.

If you had used filter before async, it would also work.

Right now you have:

log statement -> Async == to another thread => filter -> term

what you probably want is:

log statement -> filter -> Async == to another thread => term

Async is not free, so generally, you want to filter as much as possible, before spending ~120ns sending something to another thread.

[dvtomas]

Cool. I've changed the relevant building procedure to

    let drain = slog_term::FullFormat::new(decorator)
        .use_original_order()
        .build()
        .fuse();
    let drain = slog_async::Async::new(drain)
        .build()
        .filter_level(Level::Debug)
        .fuse();

and now it works as expected, thank you. This Async behavior seems to be pretty important, perhaps it would be nice to document it in the Async docs?