Add logging for each algorithm (#164)

Author: odow

Project.toml

@@ -1,11 +1,12 @@
 name = "MultiObjectiveAlgorithms"
 uuid = "0327d340-17cd-11ea-3e99-2fd5d98cecda"
-authors = ["Oscar Dowson <[email protected]>"]
 version = "1.7.0"
+authors = ["Oscar Dowson <[email protected]>"]
 
 [deps]
 Combinatorics = "861a8166-3701-5b0c-9a16-15d98fcdc6aa"
 MathOptInterface = "b8f27783-ece8-5eb3-8dc8-9495eed66fee"
+Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7"
 
 [weakdeps]
 Polyhedra = "67491407-f73d-577b-9b50-8179a7c68029"
@@ -20,15 +21,16 @@ Ipopt = "1"
 JSON = "1"
 MathOptInterface = "1.19"
 Polyhedra = "0.8"
+Printf = "1.10.0"
 Test = "1"
 julia = "1.10"
 
 [extras]
 HiGHS = "87dc4568-4c63-4d18-b0c0-bb2238e4078b"
 Ipopt = "b6b21f68-93f8-5de0-b562-5493be1d77c9"
 JSON = "682c06a0-de6a-54ab-a142-c8b1cf79cde6"
-Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
 Polyhedra = "67491407-f73d-577b-9b50-8179a7c68029"
+Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
 
 [targets]
 test = ["HiGHS", "Ipopt", "JSON", "Test", "Polyhedra"]

ext/MultiObjectiveAlgorithmsPolyhedraExt.jl

@@ -39,7 +39,6 @@ function MOA.minimize_multiobjective!(
     model::MOA.Optimizer,
 )
     @assert MOI.get(model.inner, MOI.ObjectiveSense()) == MOI.MIN_SENSE
-    start_time = time()
     solutions = Dict{Vector{Float64},Dict{MOI.VariableIndex,Float64}}()
     variables = MOI.get(model.inner, MOI.ListOfVariableIndices())
     n = MOI.output_dimension(model.f)
@@ -102,7 +101,7 @@ function MOA.minimize_multiobjective!(
     H = _halfspaces(IPS)
     count = 0
     while !isempty(H)
-        ret = MOA._check_premature_termination(model, start_time)
+        ret = MOA._check_premature_termination(model)
         if ret !== nothing
             status = ret
             break

src/MultiObjectiveAlgorithms.jl

@@ -7,6 +7,7 @@ module MultiObjectiveAlgorithms
 
 import Combinatorics
 import MathOptInterface as MOI
+import Printf
 
 """
     struct SolutionPoint
@@ -170,22 +171,30 @@ mutable struct Optimizer <: MOI.AbstractOptimizer
     f::Union{Nothing,MOI.AbstractVectorFunction}
     solutions::Vector{SolutionPoint}
     termination_status::MOI.TerminationStatusCode
+    silent::Bool
     time_limit_sec::Union{Nothing,Float64}
+    start_time::Float64
     solve_time::Float64
     ideal_point::Vector{Float64}
     compute_ideal_point::Bool
     subproblem_count::Int
     optimizer_factory::Any
 
     function Optimizer(optimizer_factory)
+        inner = MOI.instantiate(optimizer_factory; with_cache_type = Float64)
+        if MOI.supports(inner, MOI.Silent())
+            MOI.set(inner, MOI.Silent(), true)
+        end
         return new(
-            MOI.instantiate(optimizer_factory; with_cache_type = Float64),
+            inner,
             nothing,
             nothing,
             SolutionPoint[],
             MOI.OPTIMIZE_NOT_CALLED,
+            false,
             nothing,
             NaN,
+            NaN,
             Float64[],
             _default(ComputeIdealPoint()),
             0,
@@ -200,6 +209,7 @@ function MOI.empty!(model::Optimizer)
     empty!(model.solutions)
     model.termination_status = MOI.OPTIMIZE_NOT_CALLED
     model.solve_time = NaN
+    model.start_time = NaN
     empty!(model.ideal_point)
     model.subproblem_count = 0
     return
@@ -220,6 +230,17 @@ function MOI.copy_to(dest::Optimizer, src::MOI.ModelLike)
     return MOI.Utilities.default_copy_to(dest, src)
 end
 
+### Silent
+
+MOI.supports(::Optimizer, ::MOI.Silent) = true
+
+MOI.get(model::Optimizer, ::MOI.Silent) = model.silent
+
+function MOI.set(model::Optimizer, ::MOI.Silent, value::Bool)
+    model.silent = value
+    return
+end
+
 ### TimeLimitSec
 
 function MOI.supports(model::Optimizer, attr::MOI.TimeLimitSec)
@@ -646,9 +667,9 @@ function optimize_inner!(model::Optimizer)
     return
 end
 
-function _compute_ideal_point(model::Optimizer, start_time)
+function _compute_ideal_point(model::Optimizer)
     for (i, f) in enumerate(MOI.Utilities.eachscalar(model.f))
-        if _check_premature_termination(model, start_time) !== nothing
+        if _check_premature_termination(model) !== nothing
             return
         end
         if !isnan(model.ideal_point[i])
@@ -733,11 +754,11 @@ function _check_interrupt(f)
     end
 end
 
-function _check_premature_termination(model::Optimizer, start_time::Float64)
+function _check_premature_termination(model::Optimizer)
     return _check_interrupt() do
         time_limit = MOI.get(model, MOI.TimeLimitSec())
         if time_limit !== nothing
-            time_remaining = time_limit - (time() - start_time)
+            time_remaining = time_limit - (time() - model.start_time)
             if time_remaining <= 0
                 return MOI.TIME_LIMIT
             end
@@ -754,8 +775,82 @@ function MOI.optimize!(model::Optimizer)
     return
 end
 
+function _print_header(io::IO, model::Optimizer)
+    rule = "-"^(7 + 13 * (MOI.output_dimension(model.f) + 1))
+    println(io, rule)
+    println(io, "        MultiObjectiveAlgorithms.jl")
+    println(io, rule)
+    println(
+        io,
+        "Algorithm: ",
+        replace(
+            string(typeof(model.algorithm)),
+            "MultiObjectiveAlgorithms." => "",
+        ),
+    )
+    println(io, rule)
+    print(io, "solve #")
+    for i in 1:MOI.output_dimension(model.f)
+        print(io, lpad("Obj. $i  ", 13))
+    end
+    println(io, "     Time    ")
+    println(io, rule)
+    return
+end
+
+function _print_footer(io::IO, model::Optimizer)
+    rule = "-"^(7 + 13 * (MOI.output_dimension(model.f) + 1))
+    println(io, rule)
+    println(io, "TerminationStatus: ", model.termination_status)
+    println(io, "ResultCount: ", length(model.solutions))
+    println(io, rule)
+    return
+end
+
+"""
+    _log_subproblem_solve(model::Optimizer, variables::Vector{MOI.VariableIndex})
+
+Log the solution. We don't have a pre-computed point, so compute one from the
+variable values.
+"""
+function _log_subproblem_solve(model::Optimizer, arg)
+    if !model.silent
+        _log_subproblem_inner(model, arg)
+    end
+    return
+end
+
+# Variables; compute the associated Y
+function _log_subproblem_inner(model::Optimizer, x::Vector{MOI.VariableIndex})
+    _, Y = _compute_point(model, x, model.f)
+    _log_subproblem_solve(model, Y)
+    return
+end
+
+# We have a pre-computed point.
+function _log_subproblem_inner(model::Optimizer, Y::Vector)
+    print(_format(model.subproblem_count), "  ")
+    for y in Y
+        print(" ", _format(y))
+    end
+    println(" ", _format(time() - model.start_time))
+    return
+end
+
+# Assume the subproblem failed to solve.
+function _log_subproblem_inner(model::Optimizer, msg::String)
+    print(_format(model.subproblem_count), "  ")
+    print(rpad(msg, 13 * MOI.output_dimension(model.f)))
+    println(" ", _format(time() - model.start_time))
+    return
+end
+
+_format(x::Int) = Printf.@sprintf("%5d", x)
+
+_format(x::Float64) = Printf.@sprintf("% .5e", x)
+
 function _optimize!(model::Optimizer)
-    start_time = time()
+    model.start_time = time()
     empty!(model.solutions)
     model.termination_status = MOI.OPTIMIZE_NOT_CALLED
     model.subproblem_count = 0
@@ -764,6 +859,9 @@ function _optimize!(model::Optimizer)
         empty!(model.ideal_point)
         return
     end
+    if !model.silent
+        _print_header(stdout, model)
+    end
     # We need to clear the ideal point prior to starting the solve. Algorithms
     # may update this during the solve, otherwise we will update it at the end.
     model.ideal_point = fill(NaN, MOI.output_dimension(model.f))
@@ -774,13 +872,16 @@ function _optimize!(model::Optimizer)
         model.solutions = solutions
         _sort!(model.solutions, MOI.get(model, MOI.ObjectiveSense()))
     end
+    if !model.silent
+        _print_footer(stdout, model)
+    end
     if MOI.get(model, ComputeIdealPoint())
-        _compute_ideal_point(model, start_time)
+        _compute_ideal_point(model)
     end
     if MOI.supports(model.inner, MOI.TimeLimitSec())
         MOI.set(model.inner, MOI.TimeLimitSec(), nothing)
     end
-    model.solve_time = time() - start_time
+    model.solve_time = time() - model.start_time
     return
 end
 

src/algorithms/Chalmet.jl

@@ -38,18 +38,19 @@ function _solve_constrained_model(
     optimize_inner!(model)
     status = MOI.get(model.inner, MOI.TerminationStatus())
     if !_is_scalar_status_optimal(status)
+        _log_subproblem_solve(model, "subproblem not optimal")
         MOI.delete.(model, c)
         return status, nothing
     end
     variables = MOI.get(model.inner, MOI.ListOfVariableIndices())
     X, Y = _compute_point(model, variables, model.f)
+    _log_subproblem_solve(model, Y)
     MOI.delete.(model, c)
     return status, SolutionPoint(X, Y)
 end
 
 function minimize_multiobjective!(algorithm::Chalmet, model::Optimizer)
     @assert MOI.get(model.inner, MOI.ObjectiveSense()) == MOI.MIN_SENSE
-    start_time = time()
     if MOI.output_dimension(model.f) != 2
         error("Chalmet requires exactly two objectives")
     end
@@ -66,6 +67,7 @@ function minimize_multiobjective!(algorithm::Chalmet, model::Optimizer)
         return status, solutions
     end
     _, y1[2] = _compute_point(model, variables, f2)
+    _log_subproblem_solve(model, variables)
     MOI.set(model.inner, MOI.ObjectiveFunction{typeof(f1)}(), f1)
     y1_constraint = MOI.Utilities.normalize_and_add_constraint(
         model.inner,
@@ -78,6 +80,7 @@ function minimize_multiobjective!(algorithm::Chalmet, model::Optimizer)
         return status, solutions
     end
     x1, y1[1] = _compute_point(model, variables, f1)
+    _log_subproblem_solve(model, y1)
     MOI.delete(model.inner, y1_constraint)
     push!(solutions, SolutionPoint(x1, y1))
     MOI.set(model.inner, MOI.ObjectiveFunction{typeof(f1)}(), f1)
@@ -87,6 +90,7 @@ function minimize_multiobjective!(algorithm::Chalmet, model::Optimizer)
         return status, solutions
     end
     _, y2[1] = _compute_point(model, variables, f1)
+    _log_subproblem_solve(model, variables)
     if y2[1] ≈ solutions[1].y[1]
         return MOI.OPTIMAL, solutions
     end
@@ -102,12 +106,13 @@ function minimize_multiobjective!(algorithm::Chalmet, model::Optimizer)
         return status, solutions
     end
     x2, y2[2] = _compute_point(model, variables, f2)
+    _log_subproblem_solve(model, y2)
     MOI.delete(model.inner, y2_constraint)
     push!(solutions, SolutionPoint(x2, y2))
     push!(Q, (1, 2))
     t = 3
     while !isempty(Q)
-        if (ret = _check_premature_termination(model, start_time)) !== nothing
+        if (ret = _check_premature_termination(model)) !== nothing
             return ret, solutions
         end
         r, s = pop!(Q)

src/algorithms/Dichotomy.jl

@@ -74,16 +74,16 @@ function _solve_weighted_sum(
     end
     variables = MOI.get(model.inner, MOI.ListOfVariableIndices())
     X, Y = _compute_point(model, variables, model.f)
+    _log_subproblem_solve(model, Y)
     return status, SolutionPoint(X, Y)
 end
 
 function optimize_multiobjective!(algorithm::Dichotomy, model::Optimizer)
-    start_time = time()
     if MOI.output_dimension(model.f) > 2
         error("Only scalar or bi-objective problems supported.")
     end
     if MOI.output_dimension(model.f) == 1
-        if (ret = _check_premature_termination(model, start_time)) !== nothing
+        if (ret = _check_premature_termination(model)) !== nothing
             return ret, nothing
         end
         status, solution = _solve_weighted_sum(model, algorithm, [1.0])
@@ -106,7 +106,7 @@ function optimize_multiobjective!(algorithm::Dichotomy, model::Optimizer)
     limit = MOI.get(algorithm, SolutionLimit())
     status = MOI.OPTIMAL
     while length(queue) > 0 && length(solutions) < limit
-        if (ret = _check_premature_termination(model, start_time)) !== nothing
+        if (ret = _check_premature_termination(model)) !== nothing
             status = ret
             break
         end