Can logging macros call code hidden behind a function?

[ChrisRackauckas]

I was wondering if we could move the code for logging behind a function. For example, the try/catch in @warn causes issues with the code generation in Zygote. Even if that did get fixed in Zygote, the process would have to churn through less code if @warn was calling a function, and that function was given an adjoint definition that told it to ignore the code in there. So something as some as macro warn(args...) = _warn(@__MODULE__,args...) or the like would allow defining hooks on _warn that fix the issue.

@c42f @MikeInnes

[JeffBezanson]

Yes, this would be great since it could significantly reduce code size and compiler burden. The best practice is for a macro to emit the minimal possible code that can't be done with a function, and put everything else in a function.

[ChrisRackauckas]

it could significantly reduce code size and compiler burden. The best practice is for a macro to emit the minimal possible code that can't be done with a function, and put everything else in a function.

Should this almost word for word be added to the Julia style guide in the docs?

[KristofferC]

The logging system is also designed (IIRC) to do as little work as possible in case the log msg is not emitted.

[tkf]

I think hiding logging behind a function is possible but we need to create a closure to defer the log record creation.

[c42f]

This is a duplicate of #36174, but happy to continue the discussion here.

we need to create a closure to defer the log record creation

Exactly! The original implementation did this, but I changed it in #25922 to use try/catch because there were some worries about creating a lot of closures, and practical inefficiency due to the closure capture boxing problem (see logging bug report #25909).

Regardless of those implementation problems I prefer lazy generation of the log information and I think it would improve the logging system as a whole. So I'm definitely open to changing this back to the original version — perhaps with an improved version of the FastClosures "let trick" to avoid #25909.

[c42f]

For the original implementation which included closures see https://github.com/c42f/julia/blob/1845bdb3ccacfea4e7256b2af3541629eac66536/base/logging.jl#L314

[c42f]

@JeffBezanson I know you were originally somewhat against having closures here (#25909 (comment)), but the tradeoff is creating a closure vs emitting rather a lot of code from the macro.

We could make it less bad though: detect whether the user code contains any nontrivial expressions; if not emit a standard LogRecordWrapper which just contains the log record and returns it when called. In the general case, emit a closure. I think it's logical to force const bindings within the closure as the choice of whether or not to run logging code should ideally never have local side effects anyway. That should avoid reintroducing #25909.

[JeffBezanson]

That sounds good.

I acknowledge the contradiction: inlining the code is hard on the compiler; moving it to a function is also hard on the compiler. The compiler would like to be left alone to nap, thank you very much 😂

[vtjnash]

I don't think you have a contradiction there. Outlining code for one user is worse on the compiler than using the same code inline. Better is to not have the code, by ensuring duplicated sections are in a function. But, from working on this in the past, we already put the non-duplicated work inside functions, and expose a minimal surface area to the compiler.

[c42f]

Better is to not have the code

Agreed, having code just causes trouble 😂 Actually I think we could probably delete the try-catch completely from the frontend and push it into the individual logger backends if we make log record computation lazy. I feel like this would be a semantic improvement anyway.

So, the plan as I see it:

• Detect trivial logging expressions and emit a StaticLogData functor which captures keys and values. Can consider how much type information we want here (should keys and values be in an ImmutableDict-like object?)
• For nontrivial logging expressions emit a closure which returns the log record
• For intermediate cases involving formatting a string it might be handy to have Keno's LazyString Create a LazyString type, for places (like errors) which we would prefer to defer the actual work #33711
• Remove the try-catch guff. (If possible, also move the whole shouldlog block into a function, keeping only the bare bones min_enabled_level stuff inlined into the caller. I wonder whether this might give us the opportunity to merge shouldlog and handle_message in the future. Having them as hard coded requirements generated by the macro isn't great.)
• Benchmark with respect to runtime + invalidations. Some of these internal changes affect the API we can expose in the future.

[tkf]

log record computation lazy

I wonder whether this might give us the opportunity to merge shouldlog and handle_message in the future.

👍 I think this is a nice direction. I think this helps us merging them because the lazy log record can be materialized at the bottom of the logging pipeline (or actually anywhere; though we need to be a bit careful with the fan-out type logging pipeline combinators to avoid materializing records multiple times). This lets us create transducer-like composable logging pipeline (something like JuliaLogging/LoggingExtras.jl#23 (comment)). Making this backward-compatible might be tricky, though.

[c42f]

This lets us create transducer-like composable logging pipeline (something like JuliaLogging/LoggingExtras.jl#23 (comment)). Making this backward-compatible might be tricky, though.

Right 👍 Also a single entry point is cleaner if logging ends up going via an effect system.

I'm not worried about compatibility at all — I think we just use a new name (handlelog / log! / recordlog / logmsg / logmessage?) for the single entry point and make the default implementation call into shouldlog and handle_message.

To see whether that all works out it would be nice to combine these ideas into a new Logging2.jl library with a big overhaul of composable log routing machinery and some declarative configuration along the lines of LogCompose.jl. At such time as stdlibs can be versioned separately from Base we could put the good parts into Logging.jl.

[tkf]

Yes, I agree this can/should be done by adding new names. I wasn't sure how difficult it would be but maybe I was over-estimating it.

But I guess it's safer to just add the closure-based logging macro implementation without touching the API at all, to ship this within the 1.6 time-frame. The macro could be structured in such a way that it is easy to do the experiment outside Base/stdlib, though. (@c42f maybe that was your original point)

[c42f]

maybe that was your original point

Yes that's the idea — get the internal rearrangements in and make sure the performance can be acceptable.

Another benefit of merging shouldlog and handle_message is that (I hope) we can achieve a single dynamic dispatch to enter the logging filter chain.

[tkf]

Yes! I'm thinking that, too. Minimizing dynamic dispatch and pay it only once sounds like a good strategy. I wonder if it makes the inference of the caller easier (rather than just run-time performance of the callee).

[c42f]

I wonder if it makes the inference of the caller easier

Yes and if we ensure the entry point doesn't get inlined and also ensure that the return type is always nothing there should be no need for method invalidations due to installing new loggers.

(Edit: the return type of the public API may not be nothing, so there may need to be a tiny shim. But that's ok.)