How to print debug output

Ronny Bergmann

This tutorial aims to illustrate how to perform debug output. For that we consider an example that includes a sub solver, to also consider their debug capabilities.

The problem itself is hence not the main focus. We consider a nonnegative PCA which we can write as a constraint problem on the Sphere.

Let’s first load the necessary packages.

using Manopt, Manifolds, Random, LinearAlgebraRandom.seed!(42);

d = 4M = Sphere(d - 1)v0 = project(M, [ones(2)..., zeros(d - 2)...])Z = v0 * v0'#Cost and gradientf(M, p) = -tr(transpose(p) * Z * p) / 2grad_f(M, p) = project(M, p, -transpose(Z) * p / 2 - Z * p / 2)# Constraintsg(M, p) = -p # now p ≥ 0mI = -Matrix{Float64}(I, d, d)# Vector of gradients of the constraint componentsgrad_g(M, p) = [project(M, p, mI[:, i]) for i in 1:d]

Then we can take a starting point

p0 = project(M, [ones(2)..., zeros(d - 3)..., 0.1])

Simple debug output

Any solver accepts the keyword debug=, which in the simplest case can be set to an array of strings, symbols and a number.

• Strings are printed in every iteration as is (cf. DebugDivider) and should be used to finish the array with a line break.
• the last number in the array is used with DebugEvery to print the debug only every $k$th iteration.
• Any Symbol is converted into certain debug prints

Certain symbols starting with a capital letter are mapped to certain prints, for example :Cost is mapped to DebugCost() to print the current cost function value. A full list is provided in the DebugActionFactory. A special keyword is :Stop, which is only added to the final debug hook to print the stopping criterion.

Any symbol with a small letter is mapped to fields of the AbstractManoptSolverState which is used. This way you can easily print internal data, if you know their names.

Let’s look at an example first: if we want to print the current iteration number, the current cost function value as well as the value ϵ from the ExactPenaltyMethodState. To keep the amount of print at a reasonable level, we want to only print the debug every twenty-fifth iteration.

Then we can write

p1 = exact_penalty_method(    M, f, grad_f, p0; g = g, grad_g = grad_g,    debug = [:Iteration, :Cost, " | ", (:ϵ, "ϵ: %.8f"), 25, "\n", :Stop]);

Initial f(x): -0.497512 | ϵ: 0.00100000
# 25    f(x): -0.499449 | ϵ: 0.00017783
# 50    f(x): -0.499996 | ϵ: 0.00003162
# 75    f(x): -0.500000 | ϵ: 0.00000562
# 100   f(x): -0.500000 | ϵ: 0.00000100
The value of the variable (ϵ) is smaller than or equal to its threshold (1.0e-6).
At iteration 102 the algorithm performed a step with a change (4.2533629774851707e-7) less than 1.0e-6.

Specifying when to print something

While in the last step, we specified what to print, this can be extended to even specify when to print it. Currently the following four “places” are available, ordered by when they appear in an algorithm run.

• :Start to print something at the start of the algorithm. At this place all other (the following) places are “reset”: :BeforeIteration and :Iteration are triggered with an iteration number 0, so they may already print, while :Stop is triggered with -1, which resets it without printing
• :BeforeIteration to print something before an iteration starts
• :Iteration to print something after an iteration. For example the group of prints from the last code block [:Iteration, :Cost, " | ", (:ϵ,"ϵ: %.8f"), 25,] is added to this entry.
• :Stop to print something when the algorithm stops. In the example, the :Stop symbol adds the DebugStoppingCriterion to this place.

Specifying something especially for one of these places is done by specifying a Pair, so for example :BeforeIteration => :Iteration would add the display of the iteration number to be printed before the iteration is performed.

Changing this in the run does not change the output. Being more precise for the other entries, we could also write

p1 = exact_penalty_method(    M, f, grad_f, p0; g = g, grad_g = grad_g,    debug = [        :BeforeIteration => [:Iteration],        :Iteration => [:Cost, " | ", :ϵ, "\n"],        :Stop => DebugStoppingCriterion(),        25,    ],);

Initial f(x): -0.497512 | ϵ: 0.001
# 25    f(x): -0.499449 | ϵ: 0.0001778279410038921
# 50    f(x): -0.499996 | ϵ: 3.1622776601683734e-5
# 75    f(x): -0.500000 | ϵ: 5.623413251903474e-6
# 100   f(x): -0.500000 | ϵ: 1.0e-6
The value of the variable (ϵ) is smaller than or equal to its threshold (1.0e-6).
At iteration 102 the algorithm performed a step with a change (4.2533629774851707e-7) less than 1.0e-6.

This also illustrates, that instead of Symbols we can also always pass down a DebugAction directly, for example when there is a reason to create or configure the action more individually than the default from the symbol. Note that the number (25) yields that all but :Start and :Stop are only displayed every twenty-fifth iteration.

Sub solver debug

Sub solvers have a sub_kwargs keyword, such that you can pass keywords to the sub solver as well. This works well if you do not plan to change the subsolver. If you do you can wrap your own sub_state= argument in a decorate_state! and pass a debug= keyword to this function call. Keywords in a keyword have to be passed as pairs (:debug => [...]).

For most debugs, there further exists a longer form to specify the format to print. We want to use this to specify the format to print ϵ. This is done by putting the corresponding symbol together with the string to use in formatting into a tuple like (:ϵ," | ϵ: %.8f"), where we can already include the divider as well.

A main problem now is, that this debug is issued every sub solver call or initialization, as the following print of just a . per sub solver test/call illustrates

p3 = exact_penalty_method(    M, f, grad_f, p0; g = g, grad_g = grad_g,    debug = ["\n", :Iteration, DebugCost(), (:ϵ, " | ϵ: %.8f"), 25, "\n", :Stop],    sub_kwargs = [:debug => ["."]]);

Initial f(x): -0.497512 | ϵ: 0.00100000
....................................................................................
# 25    f(x): -0.499449 | ϵ: 0.00017783
.......................................................................
# 50    f(x): -0.499996 | ϵ: 0.00003162
..................................................
# 75    f(x): -0.500000 | ϵ: 0.00000562
..................................................
# 100   f(x): -0.500000 | ϵ: 0.00000100
....The value of the variable (ϵ) is smaller than or equal to its threshold (1.0e-6).
At iteration 102 the algorithm performed a step with a change (4.2533629774851707e-7) less than 1.0e-6.

The different lengths of the dotted lines come from the fact that —at least in the beginning— the subsolver performs a few steps and each sub solver’s step prints a dot.

For this issue, there is the next symbol (similar to the :Stop) to indicate that a debug set is a sub solver set :WhenActive, which introduces a DebugWhenActive that is only activated when the outer debug is actually active, or in other words DebugEvery is active itself. Furthermore, we want to print the iteration number before printing the sub solver’s steps, so we put this into a Pair, but we can leave the remaining ones as single entries. Finally we also prefix :Stop with " | " and print the iteration number at the time we stop. We get

p4 = exact_penalty_method(    M,    f,    grad_f,    p0;    g = g,    grad_g = grad_g,    debug = [        :BeforeIteration => [:Iteration, "\n"],        :Iteration => [DebugCost(), (:ϵ, " | ϵ: %.8f"), "\n"],        :Stop,        25,    ],    sub_kwargs = [        :debug => [            " | ",            :Iteration,            :Cost,            "\n",            :WhenActive,            :Stop => [(:Stop, " | "), " | stopped after iteration ", :Iteration, "\n"],        ],    ],);

Initial 
f(x): -0.497512 | ϵ: 0.00100000
# 25    
 | Initial f(x): -0.499126
 | # 1     f(x): -0.499147
 | The algorithm reached approximately critical point after 1 iterations; the gradient norm (0.00031307624887101047) is less than 0.001.
 | stopped after iteration # 1     
f(x): -0.499449 | ϵ: 0.00017783
# 50    
 | Initial f(x): -0.499993
 | # 1     f(x): -0.499994
 | The algorithm reached approximately critical point after 1 iterations; the gradient norm (0.0009767910400237663) is less than 0.001.
 | stopped after iteration # 1     
f(x): -0.499996 | ϵ: 0.00003162
# 75    
 | Initial f(x): -0.500000
 | # 1     f(x): -0.500000
 | The algorithm reached approximately critical point after 1 iterations; the gradient norm (0.00022396291196612712) is less than 0.001.
 | stopped after iteration # 1     
f(x): -0.500000 | ϵ: 0.00000562
# 100   
 | Initial f(x): -0.500000
 | # 1     f(x): -0.500000
 | The algorithm reached approximately critical point after 1 iterations; the gradient norm (3.8129640908105984e-6) is less than 0.001.
 | stopped after iteration # 1     
f(x): -0.500000 | ϵ: 0.00000100
The value of the variable (ϵ) is smaller than or equal to its threshold (1.0e-6).
At iteration 102 the algorithm performed a step with a change (4.2533629774851707e-7) less than 1.0e-6.

where we now see that the sub solver requires only one or two steps. Since the iteration number is printed in :BeforeIteration, that is before the step, the sub solver run of an iteration is shown after its iteration number and before the cost, which is printed in :Iteration after the step.

Advanced debug output

There are two more advanced variants that can be used. The first is a tuple of a symbol and a string, where the string is used as the format print, that most DebugActions have. The second is, to directly provide a DebugAction.

We can for example change the way the :ϵ is printed by adding a format string and use DebugCost() which is equivalent to using :Cost. Especially with the format change, the lines are more consistent in length.

p2 = exact_penalty_method(    M, f, grad_f, p0; g = g, grad_g = grad_g,    debug = [:Iteration, DebugCost(), (:ϵ, " | ϵ: %.8f"), 25, "\n", :Stop]);

Initial f(x): -0.497512 | ϵ: 0.00100000
# 25    f(x): -0.499449 | ϵ: 0.00017783
# 50    f(x): -0.499996 | ϵ: 0.00003162
# 75    f(x): -0.500000 | ϵ: 0.00000562
# 100   f(x): -0.500000 | ϵ: 0.00000100
The value of the variable (ϵ) is smaller than or equal to its threshold (1.0e-6).
At iteration 102 the algorithm performed a step with a change (4.2533629774851707e-7) less than 1.0e-6.

You can also write your own DebugAction functor, where the function to implement has the same signature as step_solver!, that is an AbstractManoptProblem, an AbstractManoptSolverState, as well as the current iteration k. For example, a simplified version of the already mentioned DebugDivider could look like

mutable struct DebugDivider{TypeIO <: IO} <: DebugAction    io::TypeIO    divider::String    DebugDivider(divider = " | "; io::IO = stdout) = new{typeof(io)}(io, divider)endfunction (d::DebugDivider)(::AbstractManoptProblem, ::AbstractManoptSolverState, k::Int)    (k >= 0) && (!isempty(d.divider)) && (print(d.io, d.divider))    return nothingend

Status `~/work/Manopt.jl/Manopt.jl/tutorials/Project.toml`
  [47edcb42] ADTypes v1.24.0
  [6e4b80f9] BenchmarkTools v1.8.0
  [5ae59095] Colors v0.13.1
  [a0c0ee7d] DifferentiationInterface v0.7.21
  [31c24e10] Distributions v0.25.131
  [26cc04aa] FiniteDifferences v0.12.34
  [f6369f11] ForwardDiff v1.4.5
  [8ac3fa9e] LRUCache v1.6.2
  [af67fdf4] ManifoldDiff v0.4.5
  [1cead3c2] Manifolds v0.11.29
  [3362f125] ManifoldsBase v2.5.1
  [0fc0a36d] Manopt v0.6.7 `.`
  [91a5bcdd] Plots v1.41.7
  [731186ca] RecursiveArrayTools v4.5.1
  [37e2e46d] LinearAlgebra v1.12.0
  [9a3f8284] Random v1.11.0