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
vtjnash committed Jul 20, 2020
1 parent e1ff924 commit 68aad67
Show file tree
Hide file tree
Showing 3 changed files with 117 additions and 47 deletions.
1 change: 1 addition & 0 deletions NEWS.md
View file
Original file line number Diff line number Diff line change
Expand Up @@ -73,6 +73,7 @@ Standard library changes
* `first` and `last` functions now accept an integer as second argument to get that many
leading or trailing elements of any iterable ([#34868]).
* `intersect` on `CartesianIndices` now returns `CartesianIndices` instead of `Vector{<:CartesianIndex}` ([#36643]).
* 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]).
Expand Down
132 changes: 98 additions & 34 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,10 +275,78 @@ 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
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
level = $level
std_level = convert(LogLevel, level)
if std_level >= getindex(_min_enabled_level)
Expand All @@ -291,15 +360,10 @@ function logmsg_code(_module, file, line, level, message, exs...)
if _invoked_shouldlog(logger, level, _module, group, id)
file = $(log_data._file)
line = $(log_data._line)
try
msg = $(esc(message))
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)
end
local msg, kwargs
$(logrecord) && handle_message(
logger, level, msg, _module, group, id, file, line;
kwargs...)
end
end
end
Expand All @@ -308,12 +372,13 @@ function logmsg_code(_module, file, line, level, message, exs...)
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
Expand Down Expand Up @@ -350,6 +415,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 @@ -359,39 +425,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.
Expand Down Expand Up @@ -572,8 +633,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 @@ -587,6 +650,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)
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)
color, prefix, suffix = logger.meta_formatter(level, _module, group, id, filepath, line)
color = convert(Symbol, color)::Symbol
prefix, suffix = convert(String, prefix)::String, convert(String, suffix)::String
minsuffixpad = 2
Expand All @@ -138,11 +143,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

0 comments on commit 68aad67

Please sign in to comment.