Logging macros generated code quality

[maleadt]

I noticed some badly inferred generated code after switching from info to @info, and wondered whether this is known/expected.

Repro:

function bar(a)
    @assert a == 0

    x = rand(UInt32)
    if x == 0
        throw(1)
    else
        info("$x")
        # or
        @info "$x"
    end

    return nothing
end

code_warntype(bar, Tuple{Int})

With info, this generates code with two Union{} return paths, and otherwise no badly typed values (ie. nothing red in code_warntype).

Using @info, there's now a Core.Box, an abstract Base.CoreLogging.AbstractLogger, and an Any from Base.CoreLogging.shouldlog. Performance is bad too, increased from ~3ns to ~45ns (tested on latest master).

Part of this issue relies on the exact structure of bar, eg. removing the @assert removes the box and restores performance, but keeps the Base.CoreLogging.AbstractLogger. So there's probably something more subtle going on here.

cc @c42f

EDIT: changed from error to info, I was confused about the behavior of @error.

[KristofferC]

If you take the else path with the @error then you just call the error logging macro which will print a logging message and then continue? Otherwise, using the error function, all code paths throw. Inference seems to do its job?

julia> function foo(x)
           @error "1"
           @error "2"
           return x
       end
foo (generic function with 1 method)

julia> foo(2)
┌ Error: 1
└ @ Main REPL[15]:2
┌ Error: 2
└ @ Main REPL[15]:3
2

[StefanKarpinski]

Perhaps we should rename @error to @logerr since it's currently quite confusing.

[maleadt]

Ha, yeah, I should've executed this code instead of only staring at lowered code.

Anyhow, most of the issue still remains. Instead comparing info and @info, neither of which throw, still exhibits the same performance issue, and still introduces badly typed code. I'll update the top post.

[maleadt]

This lowers to:

import Base.CoreLogging

function bar(a)
    @assert a == 0

    x = rand(UInt32)
    if x == 0
        throw(1)
    elseif x == 1
        level = CoreLogging.Info
        std_level = CoreLogging.convert(CoreLogging.LogLevel, level)
        if std_level >= CoreLogging._min_enabled_level[]
            logstate = CoreLogging.current_logstate()
            if std_level >= logstate.min_enabled_level
                logger = logstate.logger
                _module = Main
                id = :Main_5106d4ea
                group = Symbol("REPL[1]")
                if CoreLogging.shouldlog(logger, level, _module, group, id)
                    create_msg = (logger, level, _module, group, id, file, line) -> begin
                        msg = "$x"
                        CoreLogging.handle_message(logger, level, msg, _module, group, id, file, line; )
                    end
                    file = "REPL[1]"
                    line = 10
                    CoreLogging.dispatch_message(logger, level, _module, group, id, file, line, create_msg)
                end
            end
        end
        CoreLogging.nothing
      end

      return nothing
end

Or, simplified (but exhibiting the same issue):

function bar(a)
    @assert a == 0

    x = rand(UInt32)
    if x == 0
        throw(1)
    elseif x == 1
        level = CoreLogging.Info
        logstate = CoreLogging.current_logstate()
        logger = logstate.logger
        create_msg = (logger, level, _module, group, id, file, line) -> begin
            msg = "$x"
            CoreLogging.handle_message(logger, level, msg, _module, group, id, file, line)
        end
        create_msg(logger, level, Main, Symbol("REPL[1]"), :Main_5106d4ea, "REPL", 10)
      end

      return nothing
end

At this point, it looks like a closure capture issue. And indeed, passing the message as an additional argument to create_message restores performance, and gets rids of both boxes. But defeats the purpose of that delayed create_message scheme.

So this is just another dup of #15276. Sorry for the noise.

[martinholters]

So does

let x=x
    @info "$x"
end

give better code?

[maleadt]

Yeah. But that's hard to generate from within the logging macro's.
EDIT: I posted a fully reduced example in #15276.

[JeffBezanson]

It would be really nice if every logging call did not introduce a new anonymous function.

[c42f]

Ah, I thought this might fall afoul of #15276, I was hoping that you'd wave your magic compiler wand Jeff, and make that one go away before 0.7 ;-)

At the moment closure creation is actually optional as the public logging API didn't end up depending on it. So I think we can simply lift the try/catch out of dispatch_message and avoid creating a closure completely.

At the moment I don't have a good mental model of the cost in creating a closure vs inlining the extra try/catch stuff at every logging call site. I suppose inlining it with the macro is strictly easier on the compiler.

I'll make a PR for this.

[c42f]

But that's hard to generate from within the logging macro

As a side note, generating the let can be done with https://github.com/c42f/FastClosures.jl, but I removed this for the Base version of logging because it seemed a bit terrible ;-)

[JeffBezanson]

I'm not too worried about #15276 here; creating large numbers of functions is just generally hard on the compiler and takes up a lot of space.