Skip to content

Commit

Permalink
This commit does not belong to any branch on this repository, and may belong to a fork outside of the repository.
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.
@vtjnash
vtjnash committed Sep 1, 2020
1 parent 95d88fb commit 83fb63d
Showing 3 changed files with 131 additions and 61 deletions.
1 change: 1 addition & 0 deletions NEWS.md
View file
Original file line number Diff line number Diff line change
@@ -84,6 +84,7 @@ Standard library changes
* `push!(c::Channel, v)` now returns channel `c`. Previously, it returned the pushed value `v` ([#34202]).
* `RegexMatch` objects can now be probed for whether a named capture group exists within it through `haskey()` ([#36717]).
* A new standard library `TOML` has been added for parsing and printing [TOML files](https://toml.io) ([#37034]).
* Logging (such as `@warn`) no longer catches exceptions in the logger itself ([#36600]).

#### LinearAlgebra
* New method `LinearAlgebra.issuccess(::CholeskyPivoted)` for checking whether pivoted Cholesky factorization was successful ([#36002]).
160 changes: 112 additions & 48 deletions base/logging.jl
View file
Original file line number Diff line number Diff line change
@@ -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 === :(=) && ex.args[1] isa Symbol
k,v = ex.args
k, v = ex.args
if !(k isa Symbol)
throw(ArgumentError("Expected symbol for key in key value pair `$ex`"))
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
err = real ? catch_backtrace() : backtrace()
handle_message(
logger, Error, msg, _module, :logevent_error, id, filepath, line;
exception=err)
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"), " ",
31 changes: 18 additions & 13 deletions stdlib/Logging/src/ConsoleLogger.jl
View file
Original file line number Diff line number Diff line change
@@ -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) ? "│ " :

0 comments on commit 83fb63d

Please sign in to comment.