Solver Logger (what do we want)

[abelsiqueira]

Hi everyone. This discussion is related to the Solver refactor. What do we want from the logger?
I'm imagining something like this:

# inside solver
logger = SolverLogger(...)
@info header(solver)
@info solver(values...)

What should the constructor be and what should the values be?
Checklist:

• Simple
• Flexible
• Allows custom format ("%8.1e", "%04d") etc
• Efficient (can't be too slow)
• Accept missing

Some initial thought:

• SolverTools(key => value, ...), where key has to a String but value can be
  • String for formatting strings, e.g. "%8.1e"
  • Type for default types, e.g., Int
  • Symbol for specific formats, e.g. :Rplus for positive real (?)
• solver(value, ...) in order
• solver(key => value, ...) and default to missing whatever is not there.

[dpo]

Some initial ideas: we could imagine something in this vein to define the headers and rows at the same time:

columns = Dict(
  :name => Dict(:header => "name", :format => "%8s"),
  :time => Dict(:header => "time", :format => "%6.2f"),
  :objective => Dict(:header => "objective", :format => "%9.2e"),
  :kkt => Dict(:header => "kkt", :format => "%7.1e"),
  # ... etc ...
)

I see two improvements that should be relatively easy:

1. we should have at least some sane default formats:
   • objective-function-like values can be printed with a few extra digits: "%9.3e", "%10.4e", or similar;
   • residual-like functions don't need many digits and are always positive, so "%7.1e" is good
   • other real numbers than can be negative can be "%8.2e";
   • time-like values can be "%.2f" though it's annoying in cases times are large and need lots of places, so I'm tempted to also go with "%7.1e";
2. the format string should take into account the length of the header. For instance, above, "objective" needs 9 characters, so "%8.2e" wouldn't work.

Regarding 1, we should be able to override default formats and write something like

columns = Dict(
  :name => Dict(:header => "name", :format => DEFAULT_STRING_FMT),
  :time => Dict(:header => "time", :format => DEFAULT_TIME_FMT),
  :objective => Dict(:header => "objective", :format => OBJECTIVE_FMT),
  :kkt => Dict(:header => "kkt", :format => RESIDUAL_FMT),
  :solver_specific_value => Dict(:header => "whatever", :format => "%5d"),  # override default formats
  # ... etc ...
)

[abelsiqueira]

I agree with your points, but I think that's too verbose. I was thinking something like this:

logger = SolverLogger("iter" => "%5d", "f" => "%+9.1e", "g" => "%8.1e", "status" => "%10s")
@info header(logger)
@info logger(0, 1.0, 1e2, "initial")
for k = 1:10
  status = rand() < 0.5 ? "ok" : "oh no"
  @info logger(k, randn(), rand(), status)
end
@info logger(missing, -1.0, 0, "End")

returning

[ Info:  iter         f        g     status
[ Info:     0  +1.0e+00  1.0e+02    initial
[ Info:     1  -4.4e-01  2.9e-01         ok
[ Info:     2  +1.4e+00  8.7e-01      oh no
[ Info:     3  +5.5e-01  5.8e-01         ok
[ Info:     4  +2.3e-04  4.2e-01         ok
[ Info:     5  -9.0e-01  2.8e-01         ok
[ Info:     6  -9.1e-02  5.4e-01         ok
[ Info:     7  +1.9e+00  6.1e-01      oh no
[ Info:     8  +5.7e-02  2.0e-01         ok
[ Info:     9  -2.1e-01  7.6e-02      oh no
[ Info:    10  +1.3e+00  4.6e-03         ok
[ Info:     -  -1.0e+00  0.0e+00        End

[abelsiqueira]

The column length is obtained from the formatting string, by the way

[dpo]

Also, what's the connection between the headers printed during the solve and the data collected in the stats at the end of the solve? Shouldn't there be one?

[abelsiqueira]

There is some intersection, but I don't think there should be some connection. I imagine much of the number information is of interest to be collected (f, dual norm, primal norm, etc.), but not the vectors (x and y). On the other hand, we'll frequently print some information that might be useful for debugging but not for the output, such as regularization parameters and internal statuses.

[abelsiqueira]

Should this be an independent package? Looks like there is nothing restricting the logger to either NLPModels and stats

[tmigot]

It is true that loggers are somewhat independent, but if we move them to a new package, won't SolverCore become too thin? Because, only the stats will be left there.

[abelsiqueira]

SolverCore will have the stats and the solver definition. But that's not an issue, there's no problem with it being too thin.
The advantage of the logger being external is that it can be used outside of JSO.

[tmigot]

If the too thin issue is not a problem, then I think this is a good idea.

[tmigot]

It could also be great to have the SolverLogger structure as a kwargs of the solver, and only initialize the header inside the solver.
This way the "user" could even select the printed columns.

[abelsiqueira]

This seems hard, it needs a stronger interaction than is currently planned. The current idea is to call

logger(iter, f, norm(dual))

for instance. So this needs to change before the logger is an argument. Any suggestion?

[tmigot]

My idea was to have a "copy" of the column's header corresponding to what is actually printed, and this copy could be fine-tuned.

For instance:

logger = SolverLogger("iter" => ("%5d", true), "f" => ("%+9.1e", true), "g" => ("%8.1e", false), "status" => ("%10s", true))
@info header(logger)
@info logger(0, 1.0, 1e2, "initial")

would not print the columns corresponding to g. The different booleans could be modified via an optional input in the function call.

I get that it is making things a bit too complicated, but this is kind of cool.

[abelsiqueira]

Oh, I see. That's more feasible. Since the solver is the owner of the logger, we can add a hide_logger_columns or show_logger_columns, and create something in the logger to hide (or show) these columns.
Alternatively, we can plug the logger inside the Solver structure apply the hiding there. Like hide_columns!(solver.logger, columns...).

[dpo]

Just a link to keep track of when discussing this: https://github.com/bjack205/SolverLogging.jl

[chenpeizhi]

Hi all, as a user, I wonder whether there is a way to customize the formats ("%8.1e", "%04d", etc) within the current version of the logger in SolverCore.jl?

[tmigot]

Hi @chenpeizhi ! Very sorry for the late reply. It is indeed possible.

julia> using Printf, SolverCore

The defaults formats are defined in

julia> SolverCore.formats
Dict{DataType, String} with 6 entries:
  AbstractFloat  => "%8.1e"
  AbstractString => "%15s"
  Symbol         => "%15s"
  Char           => "%c"
  Signed         => "%6d"
  Missing        => "%15s"

The usual way to use SolverCore logger is as follows:

julia> @info log_header([:iter, :fx, :lx], [Int, Float64, Float32])
[ Info:   iter        fx        lx  

julia> @info log_row(Any[0, fx, lx])
[ Info:      0   1.0e+00   2.0e+00

julia> @info log_row(Any[0, fx, lx])
[ Info:      0   1.0e+00            start

Now, if you want to modify the formatting, say, for instance, we only want to print the integer part of Float32, then we would have to use Julia's multiple dispatch on the function row_formatter.

julia> SolverCore.row_formatter(x::Float32) = @sprintf("%8d", x)

julia> @info log_row(Any[0, fx, lx])
[ Info:      0   1.0e+00         2

The function log_row actually call the function row_formatter on each element and then concatenate the results.

This is not much documented. I will add issues on SolverCore.jl to do it. Let us know if you are interested in more details or a more concrete example.

[chenpeizhi]

Hi @tmigot, thank you very much for your kind reply! I really appreciate it.

I think there is still a minor issue with the row_formatter solution. That is, once the formatting of the data is modified, the formatting of the headers does not change accordingly. I looked into the source code in SolverCore.jl/src/logger.jl and found that it's possible to modify header_formatter manually. But it would be ideal if header_formatter is automatically updated according to row_formatter.

[tmigot]

Yes, I think you are perfectly right. Would you mind opening a pull request to fix this?