Use verbosity system

[jClugstor]

Checklist

• Appropriate tests were added
• Any code changes were done in a way that does not break public API
• All documentation related to code changes were updated
• The new code follows the
  contributor guidelines, in particular the SciML Style Guide and
  COLPRAC.
• Any new documentation only uses public API

Additional context

Uses the verbosity system from SciML/SciMLBase.jl#1049

[jClugstor]

Benchmarks: I benchmarked the runtime and compile time for a couple of different cases.

Note: when verbose = SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.Warn())) that means that when the LU factorization fails a warning message is emitted.

verbose = SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.None())) just toggles that one option off, so no message appears. It also skips over the part of the code where @logmsg appears, as can be seen in the definition of emit_message, because message_level for Verbosity.None() returns nothing.

When verbose = SciMLBase.LinearVerbosity(SciMLVerbosity.None()) it set's all of the individual toggles to None() and actually sets the type parameter of LinearVerbosity to false. This means that when emit_message is called with it, it actually goes to the empty version below. So that avoids things like compiling message_level and @logmsg.

function emit_message(message::String, verbose::V,
        option, group, file, line, _module) where {V <: AbstractVerbositySpecifier{true}}
    level = message_level(verbose, option, group)

    if !isnothing(level)
        Base.@logmsg level message _file=file _line=line _module=_module _group = group
    end
end

function emit_message(
        f, verbose::AbstractVerbositySpecifier{false}, option, group, file, line, _module)
end

using LinearSolve
using SciMLBase
using Test
using LinearAlgebra
using BenchmarkTools
using Distributed

# Runtime 
A = [1.0 0 0 0
    0 1 0 0
    0 0 1 0
    0 0 0 0]
b = rand(4)
prob = LinearProblem(A, b)

# With warning 
@btime sol = solve(prob, verbose = SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.Warn()))
 24.675 μs (260 allocations: 87.59 KiB)

# With the toggle set to none. This still goes through the `emit_message` function, but skips `logmsg`.
@btime sol = solve(prob, verbose = SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.None()))
  2.431 μs (54 allocations: 70.31 KiB)

# With the type parameter of `LinearVerbosity` set to `false`, so it uses the empty `emit_message`
@btime sol = solve(prob, verbose = SciMLBase.LinearVerbosity(SciMLBase.Verbosity.None()))
  2.345 μs (63 allocations: 70.73 KiB)


cache = init(prob, verbose = SciMLBase.LinearVerbosity(SciMLBase.Verbosity.None()))
@btime solve!(cache)
┌ Warning: LU factorization failed, falling back to QR factorization. `A` is potentially rank-deficient.
└ @ LinearSolve ~/Documents/Work/dev/LinearSolve/LinearSolve.jl/src/default.jl:367
  111.330 ns (1 allocation: 48 bytes)

cache = init(prob, verbose=SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.None()))
@btime solve!(cache)
 110.997 ns (1 allocation: 48 bytes)

cache = init(prob, verbose=SciMLBase.LinearVerbosity(default_lu_fallback=SciMLBase.Verbosity.Warn()))
@btime solve!(cache)
 111.038 ns (1 allocation: 48 bytes)

using Distributed
# This is just a cool thing I found on Discourse that can get the compile time without having to restart Julia every time
function time_compilation(expr; setup=nothing)
    ps = addprocs(1)
    (; compile_time, recompile_time) = remotecall_fetch(only(ps)) do
        @eval begin
            $setup
            @timed $expr
        end
    end
    rmprocs(ps)
    (; compile_time, recompile_time)
end

setup_warn = quote
    using LinearSolve
    using SciMLBase
    A = [1.0 0 0 0
        0 1 0 0
        0 0 1 0
        0 0 0 0]
    b = rand(4)
    prob = LinearProblem(A, b)

    cache = init(prob, verbose=SciMLBase.LinearVerbosity(default_lu_fallback=SciMLBase.Verbosity.Warn()))
end

time_compilation(:(solve!(cache)), setup=setup_warn)[:compile_time]
3.128760291

setup_other_none = quote
    using LinearSolve
    using SciMLBase
    A = [1.0 0 0 0
        0 1 0 0
        0 0 1 0
        0 0 0 0]
    b = rand(4)
    prob = LinearProblem(A, b)

    cache = init(prob, verbose=SciMLBase.LinearVerbosity(default_lu_fallback=SciMLBase.Verbosity.None()))
end

time_compilation(:(solve!(cache)), setup=setup_other_none)[:compile_time]
2.469369679

setup_none = quote
    using LinearSolve
    using SciMLBase
    A = [1.0 0 0 0
        0 1 0 0
        0 0 1 0
        0 0 0 0]
    b = rand(4)
    prob = LinearProblem(A, b)

    cache = init(prob, verbose=SciMLBase.LinearVerbosity(SciMLBase.Verbosity.None()))
end

time_compilation(:(solve!(cache)), setup=setup_none)[:compile_time]
2.349037369

# Contrived examples because none of the LinearSolve messages use a function for the message
# the code in `SciMLMessage_expand` is just the @macroexpand of @SciMLMessage, needs to be this way to work with the compilation time measuring
SciMLMessage_expand = quote
    SciMLBase.emit_message((()->begin
              #= /home/jadonclugston/Documents/Work/dev/Verbosity/LinearVerbosityBenchmarks/linear_verbosity_benchmarks.jl:111 =#
              x + y
          end), verb, :default_lu_fallback, :error_control, "/home/jadonclugston/Documents/Work/dev/Verbosity/LinearVerbosityBenchmarks/linear_verbosity_benchmarks.jl", 110, Main)
end


setup_warn = quote
    using SciMLBase: SciMLBase
    x = 100.0
    y = 300.0
    verb = SciMLBase.LinearVerbosity(default_lu_fallback=SciMLBase.Verbosity.Warn())
end

time_compilation(func_thing, setup=setup_warn)[:compile_time]
0.723105174

setup_other_none = quote
    using SciMLBase: SciMLBase
    x = 1.0
    y = 2.0
    verb = SciMLBase.LinearVerbosity(default_lu_fallback = SciMLBase.Verbosity.None())
end

time_compilation(func_thing, setup=setup_other_none)[:compile_time]
0.021709223

setup_none = quote
    using SciMLBase
    verb = SciMLBase.LinearVerbosity(SciMLBase.Verbosity.None())
    x = 1.0
    y = 2.0
end

time_compilation(func_thing, setup=setup_none)[:compile_time]
5.4921e-5

So it looks like it does add quite a bit of compile time when compiled with log messages emitted. That makes sense because it has to compile everything to do with @logmsg. With just the toggle switched off it add some, but not as much, probably because it still compiles message_level. Then with the type parameter of LinearVerbosity set to false it has the lowest compile time, because it avoids compiling the full emit_message.

Comparing to a version without the verbosity system: I added just a warning (cache.verbose && @warn(...) in the same spot to compare. It looks like the compile times with and without the messages are pretty comparable. It looks like most of the compile time is related to the log message system being compiled, rather than anything new I introduced, (3.128760291 for new verbosity system with message, vs. 3.038604046 for just using @warn).

# Without Verbosity system

using Distributed

function time_compilation(expr; setup=nothing)
    ps = addprocs(1)
    (; compile_time, recompile_time) = remotecall_fetch(only(ps)) do
        @eval begin
            $setup
            @timed $expr
        end
    end
    rmprocs(ps)
    (; compile_time, recompile_time)
end

setup_warn = quote
    using LinearSolve
    using SciMLBase
    A = [1.0 0 0 0
        0 1 0 0
        0 0 1 0
        0 0 0 0]
    b = rand(4)
    prob = LinearProblem(A, b)

    cache = init(prob, verbose=false)
end

time_compilation(:(solve!(cache)), setup=setup_warn)[:compile_time]
2.448936614

setup_other_none = quote
    using LinearSolve
    using SciMLBase
    A = [1.0 0 0 0
        0 1 0 0
        0 0 1 0
        0 0 0 0]
    b = rand(4)
    prob = LinearProblem(A, b)

    cache = init(prob, verbose=true)
end

time_compilation(:(solve!(cache)), setup=setup_other_none)[:compile_time]
3.038604046

[jClugstor]

Todo:

• Make sure that verbose = Bool is deprecated properly

[ChrisRackauckas]

I think it looks great! Lets get this ready to merge.

[jClugstor]

Last thing seems to be figuring out why the OrdinaryDiffEq integration test is failing.

[jClugstor]

The problem is just that OrdinaryDiffEqDifferentiation has

for alg in [...
    LinearSolve.KLUFactorization,
    ...]
    @eval function LinearSolve.init_cacheval(alg::$alg, A::WOperator, b, u, Pl, Pr,
            maxiters::Int, abstol, reltol, verbose::Bool,
            assumptions::OperatorAssumptions)
        LinearSolve.init_cacheval(alg, A.J, b, u, Pl, Pr,
            maxiters::Int, abstol, reltol, verbose::Bool,
            assumptions::OperatorAssumptions)
    end
end

so when verbose isa LinearVerbosity it doesn't hit this dispatch.

[jClugstor]

@ChrisRackauckas is there a reason the type annotation needs to be there? If not I can submit a PR to remove the ::Bool. That should get this to pass.

[ChrisRackauckas]

There needs to be a type annotation IIRC due to some ambiguity issues. But you should change it to the new one.

[jClugstor]

@ChrisRackauckas this needs to be the first one, since NonlinearSolve and OrdinaryDiffEq will pass a LinearVerbosity, so those won't work until this is in place.

I have the verbosity for NonlinearSolve up: SciML/NonlinearSolve.jl#647, there will be some failures related to LinearSolve until this gets merged / tagged.

I have OrdinaryDiffEq like 90% done, just need to add some tests etc.

[ChrisRackauckas]

When will it be ready to review?

[jClugstor]

Now. I added tests and docs, and made sure that it's backwards compatible so that Bool verbose still works.

I had all tests passing besides the ODE stuff just recently, I just had to rebase and the CI is taking a while.

[ChrisRackauckas]

Precompile failures, rebase it

[ChrisRackauckas]

Test failures

[jClugstor]

Should be fixed up now. I'm not sure what's going on with the windows NoPre tests, looks like a CI issue.