Skip to content

Commit

Permalink
logging: avoid try/catch when the message is a simple
Browse files Browse the repository at this point in the history 
This should avoid the try/catch in some cases, where the message is
simply a constant value or simple variable. It also tries to slightly
reduce required specialization in some other cases too.
  • Loading branch information
@vtjnash @c42f
vtjnash authored and c42f committed Sep 23, 2020
1 parent b77f400 commit f7adc9e
Show file tree
Hide file tree
Showing 5 changed files with 151 additions and 65 deletions.
1 change: 1 addition & 0 deletions NEWS.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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])
Expand Down
160 changes: 112 additions & 48 deletions base/logging.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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.
Expand All @@ -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
Expand Down Expand Up @@ -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
Expand All @@ -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.
Expand Down Expand Up @@ -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
Expand All @@ -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"), " ",
Expand Down
31 changes: 18 additions & 13 deletions stdlib/Logging/src/ConsoleLogger.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 = ""
Expand Down Expand Up @@ -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)
Expand All @@ -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) ? "│ " :
Expand Down
4 changes: 2 additions & 2 deletions test/choosetests.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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 = []
Expand Down
20 changes: 18 additions & 2 deletions test/logging.jl → test/corelogging.jl
View file
Original file line number Diff line number Diff line change
Expand Up @@ -88,12 +88,28 @@ end

@testset "Log message exception handling" begin
# Exceptions in message creation are caught by default
@test_logs (Error,Test.Ignored(),Test.Ignored(),:logevent_error) catch_exceptions=true @info "foo $(1÷0)"
@test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true @info "foo $(1÷0)"
# Exceptions propagate if explicitly disabled for the logger (by default
# for the test logger)
@test_throws DivideError collect_test_logs() do
@info "foo $(1÷0)"
end
# trivial expressions create the errors explicitly instead of throwing them (to avoid try/catch)
for i in 1:2
local msg, x, y
logmsg = (function() @info msg x=y end,
function() @info msg x=y z=1+1 end)[i]
@test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true logmsg()
@test_throws UndefVarError(:msg) collect_test_logs(logmsg)
@test (only(collect_test_logs(logmsg, catch_exceptions=true)[1]).kwargs[:exception]::Tuple{UndefVarError, Vector})[1] === UndefVarError(:msg)
msg = "the msg"
@test_logs (Error, Test.Ignored(), Test.Ignored(), :logevent_error) catch_exceptions=true logmsg()
@test_throws UndefVarError(:y) collect_test_logs(logmsg)
@test (only(collect_test_logs(logmsg, catch_exceptions=true)[1]).kwargs[:exception]::Tuple{UndefVarError, Vector})[1] === UndefVarError(:y)
y = "the y"
@test_logs (Info,"the msg") logmsg()
@test only(collect_test_logs(logmsg)[1]).kwargs[:x] === "the y"
end
end

@testset "Special keywords" begin
Expand Down Expand Up @@ -390,7 +406,7 @@ end
(record,), _ = collect_test_logs() do
@info "test"
end
@test record.group == :logging # name of this file
@test record.group == :corelogging # name of this file
end

end

0 comments on commit f7adc9e

Please sign in to comment.