reduce some codegen costs

NEWS.md

@@ -109,6 +109,7 @@ Standard library changes
 * The `Pkg.BinaryPlatforms` module has been moved into `Base` as `Base.BinaryPlatforms` and heavily reworked.
   Applications that want to be compatible with the old API should continue to import `Pkg.BinaryPlatforms`,
   however new users should use `Base.BinaryPlatforms` directly. ([#37320])
+* Logging (such as `@warn`) no longer catches exceptions in the logger itself ([#36600]).
 * The `Pkg.Artifacts` module has been imported as a separate standard library.  It is still available as
   `Pkg.Artifacts`, however starting from Julia v1.6+, packages may import simply `Artifacts` without importing
   all of `Pkg` alongside. ([#37320])

base/compiler/optimize.jl

@@ -258,7 +258,7 @@ function optimize(opt::OptimizationState, params::OptimizationParams, @nospecial
             # obey @inline declaration if a dispatch barrier would not help
         else
             bonus = 0
-            if result ⊑ Tuple && !isbitstype(widenconst(result))
+            if result ⊑ Tuple && !isconcretetype(widenconst(result))
                 bonus = params.inline_tupleret_bonus
             end
             if opt.src.inlineable

base/compiler/tfuncs.jl

@@ -592,7 +592,7 @@ function isa_tfunc(@nospecialize(v), @nospecialize(tt))
     # TODO: handle non-leaftype(t) by testing against lower and upper bounds
     return Bool
 end
-add_tfunc(isa, 2, 2, isa_tfunc, 0)
+add_tfunc(isa, 2, 2, isa_tfunc, 1)
 
 function subtype_tfunc(@nospecialize(a), @nospecialize(b))
     a, isexact_a = instanceof_tfunc(a)
@@ -610,7 +610,7 @@ function subtype_tfunc(@nospecialize(a), @nospecialize(b))
     end
     return Bool
 end
-add_tfunc(<:, 2, 2, subtype_tfunc, 0)
+add_tfunc(<:, 2, 2, subtype_tfunc, 10)
 
 is_dt_const_field(fld::Int) = (
      fld == DATATYPE_NAME_FIELDINDEX ||

base/compiler/types.jl

@@ -44,7 +44,7 @@ struct OptimizationParams
     inlining::Bool              # whether inlining is enabled
     inline_cost_threshold::Int  # number of CPU cycles beyond which it's not worth inlining
     inline_nonleaf_penalty::Int # penalty for dynamic dispatch
-    inline_tupleret_bonus::Int  # extra willingness for non-isbits tuple return types
+    inline_tupleret_bonus::Int  # extra inlining willingness for non-concrete tuple return types (in hopes of splitting it up)
     inline_error_path_cost::Int # cost of (un-optimized) calls in blocks that throw
 
     # Duplicating for now because optimizer inlining requires it.
@@ -59,7 +59,7 @@ struct OptimizationParams
             inlining::Bool = inlining_enabled(),
             inline_cost_threshold::Int = 100,
             inline_nonleaf_penalty::Int = 1000,
-            inline_tupleret_bonus::Int = 400,
+            inline_tupleret_bonus::Int = 250,
             inline_error_path_cost::Int = 20,
             max_methods::Int = 3,
             tuple_splat::Int = 32,

base/logging.jl

@@ -254,6 +254,7 @@ _log_record_ids = Set{Symbol}()
 # across versions of the originating module, provided the log generating
 # statement itself doesn't change.
 function log_record_id(_module, level, message, log_kws)
+    @nospecialize
     modname = _module === nothing ?  "" : join(fullname(_module), "_")
     # Use an arbitrarily chosen eight hex digits here. TODO: Figure out how to
     # make the id exactly the same on 32 and 64 bit systems.
@@ -274,48 +275,112 @@ end
 
 default_group(file) = Symbol(splitext(basename(file))[1])
 
+function issimple(@nospecialize val)
+    val isa String && return true
+    val isa Symbol && return true
+    val isa QuoteNode && return true
+    val isa Number && return true
+    val isa Char && return true
+    if val isa Expr
+        val.head === :quote && issimple(val[1]) && return true
+        val.head === :inert && return true
+    end
+    return false
+end
+function issimplekw(@nospecialize val)
+    if val isa Expr
+        if val.head === :kw
+            val = val.args[2]
+            if val isa Expr && val.head === :escape
+                issimple(val.args[1]) && return true
+            end
+        end
+    end
+    return false
+end
+
 # Generate code for logging macros
 function logmsg_code(_module, file, line, level, message, exs...)
+    @nospecialize
     log_data = process_logmsg_exs(_module, file, line, level, message, exs...)
-    quote
-    let
-        level = $level
-        std_level = convert(LogLevel, level)
-        if std_level >= getindex(_min_enabled_level)
-            group = $(log_data._group)
-            _module = $(log_data._module)
-            logger = current_logger_for_env(std_level, group, _module)
-            if !(logger === nothing)
-                id = $(log_data._id)
-                # Second chance at an early bail-out (before computing the message),
-                # based on arbitrary logger-specific logic.
-                if _invoked_shouldlog(logger, level, _module, group, id)
-                    file = $(log_data._file)
-                    line = $(log_data._line)
-                    try
-                        msg = $(esc(message))
-                        handle_message(
+    if !isa(message, Symbol) && issimple(message) && isempty(log_data.kwargs)
+        logrecord = quote
+            msg = $(message)
+            kwargs = (;)
+            true
+        end
+    elseif issimple(message) && all(issimplekw, log_data.kwargs)
+        # if message and kwargs are just values and variables, we can avoid try/catch
+        # complexity by adding the code for testing the UndefVarError by hand
+        checkerrors = nothing
+        for kwarg in reverse(log_data.kwargs)
+            if isa(kwarg.args[2].args[1], Symbol)
+                checkerrors = Expr(:if, Expr(:isdefined, kwarg.args[2]), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(kwarg.args[2].args[1])))
+            end
+        end
+        if isa(message, Symbol)
+            message = esc(message)
+            checkerrors = Expr(:if, Expr(:isdefined, message), checkerrors, Expr(:call, Expr(:core, :UndefVarError), QuoteNode(message.args[1])))
+        end
+        logrecord = quote
+            let err = $checkerrors
+                if err === nothing
+                    msg = $(message)
+                    kwargs = (;$(log_data.kwargs...))
+                    true
+                else
+                    logging_error(logger, level, _module, group, id, file, line, err, false)
+                    false
+                end
+            end
+        end
+    else
+        logrecord = quote
+            try
+                msg = $(esc(message))
+                kwargs = (;$(log_data.kwargs...))
+                true
+            catch err
+                logging_error(logger, level, _module, group, id, file, line, err, true)
+                false
+            end
+        end
+    end
+    return quote
+        let
+            level = $level
+            std_level = convert(LogLevel, level)
+            if std_level >= getindex(_min_enabled_level)
+                group = $(log_data._group)
+                _module = $(log_data._module)
+                logger = current_logger_for_env(std_level, group, _module)
+                if !(logger === nothing)
+                    id = $(log_data._id)
+                    # Second chance at an early bail-out (before computing the message),
+                    # based on arbitrary logger-specific logic.
+                    if _invoked_shouldlog(logger, level, _module, group, id)
+                        file = $(log_data._file)
+                        line = $(log_data._line)
+                        local msg, kwargs
+                        $(logrecord) && handle_message(
                             logger, level, msg, _module, group, id, file, line;
-                            $(log_data.kwargs...)
-                        )
-                    catch err
-                        logging_error(logger, level, _module, group, id, file, line, err)
+                            kwargs...)
                     end
                 end
             end
+            nothing
         end
-        nothing
-    end
     end
 end
 
 function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
+    @nospecialize
     local _group, _id
     _module = _orig_module
     kwargs = Any[]
     for ex in exs
         if ex isa Expr && ex.head === :(=)
-            k,v = ex.args
+            k, v = ex.args
             if !(k isa Symbol)
                 k = Symbol(k)
             end
@@ -352,6 +417,7 @@ function process_logmsg_exs(_orig_module, _file, _line, level, message, exs...)
 end
 
 function default_group_code(file)
+    @nospecialize
     if file isa String && isdefined(Base, :basename)
         QuoteNode(default_group(file))  # precompute if we can
     else
@@ -361,39 +427,34 @@ function default_group_code(file)
 end
 
 
-# Report an error in log message creation (or in the logger itself).
+# Report an error in log message creation
 @noinline function logging_error(logger, level, _module, group, id,
-                                 filepath, line, @nospecialize(err))
+                                 filepath, line, @nospecialize(err), real::Bool)
+    @nospecialize
     if !_invoked_catch_exceptions(logger)
-        rethrow(err)
-    end
-    try
-        msg = "Exception while generating log record in module $_module at $filepath:$line"
-        handle_message(
-            logger, Error, msg, _module, :logevent_error, id, filepath, line;
-            exception=(err,catch_backtrace())
-        )
-    catch err2
-        try
-            # Give up and write to stderr, in three independent calls to
-            # increase the odds of it getting through.
-            print(stderr, "Exception handling log message: ")
-            println(stderr, err)
-            println(stderr, "  module=$_module  file=$filepath  line=$line")
-            println(stderr, "  Second exception: ", err2)
-        catch
-        end
+        real ? rethrow(err) : throw(err)
     end
+    msg = try
+              "Exception while generating log record in module $_module at $filepath:$line"
+          catch ex
+              "Exception handling log message: $ex"
+          end
+    bt = real ? catch_backtrace() : backtrace()
+    handle_message(
+        logger, Error, msg, _module, :logevent_error, id, filepath, line;
+        exception=(err,bt))
     nothing
 end
 
 # Log a message. Called from the julia C code; kwargs is in the format
 # Any[key1,val1, ...] for simplicity in construction on the C side.
 function logmsg_shim(level, message, _module, group, id, file, line, kwargs)
-    real_kws = Any[(kwargs[i],kwargs[i+1]) for i in 1:2:length(kwargs)]
+    @nospecialize
+    real_kws = Any[(kwargs[i], kwargs[i+1]) for i in 1:2:length(kwargs)]
     @logmsg(convert(LogLevel, level), message,
             _module=_module, _id=id, _group=group,
             _file=String(file), _line=line, real_kws...)
+    nothing
 end
 
 # Global log limiting mechanism for super fast but inflexible global log limiting.
@@ -574,8 +635,10 @@ min_enabled_level(logger::SimpleLogger) = logger.min_level
 catch_exceptions(logger::SimpleLogger) = false
 
 function handle_message(logger::SimpleLogger, level, message, _module, group, id,
-                        filepath, line; maxlog=nothing, kwargs...)
-    if maxlog !== nothing && maxlog isa Integer
+                        filepath, line; kwargs...)
+    @nospecialize
+    maxlog = get(kwargs, :maxlog, nothing)
+    if maxlog isa Integer
         remaining = get!(logger.message_limits, id, maxlog)
         logger.message_limits[id] = remaining - 1
         remaining > 0 || return
@@ -589,6 +652,7 @@ function handle_message(logger::SimpleLogger, level, message, _module, group, id
         println(iob, "│ ", msglines[i])
     end
     for (key, val) in kwargs
+        key === :maxlog && continue
         println(iob, "│   ", key, " = ", val)
     end
     println(iob, "└ @ ", something(_module, "nothing"), " ",

stdlib/Logging/src/ConsoleLogger.jl

@@ -58,6 +58,7 @@ function default_logcolor(level)
 end
 
 function default_metafmt(level, _module, group, id, file, line)
+    @nospecialize
     color = default_logcolor(level)
     prefix = (level == Warn ? "Warning" : string(level))*':'
     suffix = ""
@@ -96,38 +97,42 @@ function termlength(str)
 end
 
 function handle_message(logger::ConsoleLogger, level, message, _module, group, id,
-                        filepath, line; maxlog=nothing, kwargs...)
-    if maxlog !== nothing && maxlog isa Integer
+                        filepath, line; kwargs...)
+    @nospecialize
+    hasmaxlog = haskey(kwargs, :maxlog) ? 1 : 0
+    maxlog = get(kwargs, :maxlog, nothing)
+    if maxlog isa Integer
         remaining = get!(logger.message_limits, id, maxlog)
         logger.message_limits[id] = remaining - 1
         remaining > 0 || return
     end
 
     # Generate a text representation of the message and all key value pairs,
     # split into lines.
-    msglines = [(indent=0,msg=l) for l in split(chomp(string(message)), '\n')]
+    msglines = [(indent=0, msg=l) for l in split(chomp(string(message)), '\n')]
     dsize = displaysize(logger.stream)::Tuple{Int,Int}
-    if !isempty(kwargs)
+    if length(kwargs) > hasmaxlog
         valbuf = IOBuffer()
-        rows_per_value = max(1, dsize[1]÷(length(kwargs)+1))
+        rows_per_value = max(1, dsize[1] ÷ (length(kwargs) + 1 - hasmaxlog))
         valio = IOContext(IOContext(valbuf, logger.stream),
-                          :displaysize => (rows_per_value,dsize[2]-5),
+                          :displaysize => (rows_per_value, dsize[2] - 5),
                           :limit => logger.show_limited)
-        for (key,val) in pairs(kwargs)
+        for (key, val) in kwargs
+            key === :maxlog && continue
             showvalue(valio, val)
             vallines = split(String(take!(valbuf)), '\n')
             if length(vallines) == 1
-                push!(msglines, (indent=2,msg=SubString("$key = $(vallines[1])")))
+                push!(msglines, (indent=2, msg=SubString("$key = $(vallines[1])")))
             else
-                push!(msglines, (indent=2,msg=SubString("$key =")))
-                append!(msglines, ((indent=3,msg=line) for line in vallines))
+                push!(msglines, (indent=2, msg=SubString("$key =")))
+                append!(msglines, ((indent=3, msg=line) for line in vallines))
             end
         end
     end
 
     # Format lines as text with appropriate indentation and with a box
     # decoration on the left.
-    color,prefix,suffix = logger.meta_formatter(level, _module, group, id, filepath, line)::Tuple{Union{Symbol,Int},String,String}
+    color, prefix, suffix = logger.meta_formatter(level, _module, group, id, filepath, line)::Tuple{Union{Symbol,Int},String,String}
     minsuffixpad = 2
     buf = IOBuffer()
     iob = IOContext(buf, logger.stream)
@@ -136,11 +141,11 @@ function handle_message(logger::ConsoleLogger, level, message, _module, group, i
                   (isempty(suffix) ? 0 : length(suffix)+minsuffixpad)
     justify_width = min(logger.right_justify, dsize[2])
     if nonpadwidth > justify_width && !isempty(suffix)
-        push!(msglines, (indent=0,msg=SubString("")))
+        push!(msglines, (indent=0, msg=SubString("")))
         minsuffixpad = 0
         nonpadwidth = 2 + length(suffix)
     end
-    for (i,(indent,msg)) in enumerate(msglines)
+    for (i, (indent, msg)) in enumerate(msglines)
         boxstr = length(msglines) == 1 ? "[ " :
                  i == 1                ? "┌ " :
                  i < length(msglines)  ? "│ " :

test/choosetests.jl

@@ -49,12 +49,12 @@ function choosetests(choices = [])
         "euler", "show", "client",
         "errorshow", "sets", "goto", "llvmcall", "llvmcall2", "ryu",
         "some", "meta", "stacktraces", "docs",
-        "misc", "threads", "stress", "binaryplatforms",
+        "misc", "threads", "stress", "binaryplatforms", "atexit",
         "enums", "cmdlineargs", "int", "interpreter",
         "checked", "bitset", "floatfuncs", "precompile",
         "boundscheck", "error", "ambiguous", "cartesian", "osutils",
         "channels", "iostream", "secretbuffer", "specificity",
-        "reinterpretarray", "syntax", "logging", "missing", "asyncmap", "atexit"
+        "reinterpretarray", "syntax", "corelogging", "missing", "asyncmap"
     ]
 
     tests = []