Diagnostics API

Detailed API Documentation is provided at Diagnostics API Reference.

Logging the Solve Process

All NonlinearSolve.jl native solvers allow storing and displaying the trace of the nonlinear solve process. This is controlled by 3 keyword arguments to solve:

1. show_trace: Must be Val(true) or Val(false). This controls whether the trace is displayed to the console. (Defaults to Val(false))
2. trace_level: Needs to be one of Trace Objects: TraceMinimal, TraceWithJacobianConditionNumber, or TraceAll. This controls the level of detail of the trace. (Defaults to TraceMinimal())
3. store_trace: Must be Val(true) or Val(false). This controls whether the trace is stored in the solution object. (Defaults to Val(false))

Detailed Internal Timings

All the native NonlinearSolve.jl algorithms come with in-built TimerOutputs.jl support. However, this is disabled by default and can be enabled via NonlinearSolve.enable_timer_outputs.

Note that you will have to restart Julia to disable the timer outputs once enabled.

Example Usage

using ModelingToolkit, NonlinearSolve

@variables x y z
@parameters σ ρ β

# Define a nonlinear system
eqs = [0 ~ σ * (y - x),
    0 ~ x * (ρ - z) - y,
    0 ~ x * y - β * z]
@named ns = NonlinearSystem(eqs, [x, y, z], [σ, ρ, β])

u0 = [x => 1.0, y => 0.0, z => 0.0]

ps = [σ => 10.0 ρ => 26.0 β => 8 / 3]

prob = NonlinearProblem(ns, u0, ps)

solve(prob)

retcode: Success
u: 3-element Vector{Float64}:
  3.793345350492673e-20
  2.9557012405196054e-18
 -4.2310897604246004e-16

This produced the output, but it is hard to diagnose what is going on. We can turn on the trace to see what is happening:

solve(prob; show_trace = Val(true), trace_level = TraceAll(10))

Algorithm: Broyden(
    descent = NewtonDescent(),
    update_rule = GoodBroydenUpdateRule(),
    reinit_rule = NoChangeInStateReset(),
    max_resets = 100,
    initialization = IdentityInitialization(structure = FullStructure()),
    inverse_jacobian = true
)

----     -------------        -----------          -------
Iter     f(u) inf-norm        Step 2-norm          cond(J)
----     -------------        -----------          -------
0        2.60000000e+01       1.19656636e-309      Inf
1        3.11334008e+01       5.00000000e-01       1.00000000e+00
11       3.56364608e-09       1.87220799e-08       9.23959279e+01
Final    1.12829060e-15
----------------------

You can also store the trace in the solution object:

sol = solve(prob; trace_level = TraceAll(), store_trace = Val(true));

sol.trace

----     -------------        -----------          -------             
Iter     f(u) inf-norm        Step 2-norm          cond(J)             
----     -------------        -----------          -------             
0        2.60000000e+01       9.76987084e-310      Inf                 
1        3.11334008e+01       5.00000000e-01       1.00000000e+00      
2        1.70049757e+01       2.47663402e+00       4.01371531e+00      
3        1.25070298e+01       4.55718519e-01       3.44264376e+00      
4        4.08844590e-02       1.26766212e+00       1.04551194e+01      
5        4.28684266e-02       1.01939613e-03       1.04494280e+01      
6        4.69551736e-02       1.54013596e-03       1.23850377e+01      
7        2.18953882e-02       9.39808481e-03       4.41202867e+01      
8        3.44645828e-03       6.91851172e-03       7.57097566e+01      
9        1.70717053e-06       1.29181254e-03       8.96736841e+01      
10       5.34816923e-08       6.20165360e-07       8.97163144e+01      
11       3.56364608e-09       1.87220799e-08       9.23959279e+01      
12       5.75065840e-10       1.55202581e-09       9.99847641e+01      
13       1.99849681e-11       2.08160415e-10       8.66802131e+01      
14       1.12829060e-15       7.49496905e-12       8.97701883e+01      

Now, let's try to investigate the time it took for individual internal steps. We will have to use the init and solve! API for this. The TimerOutput will be present in cache.timer. However, note that for poly-algorithms this is currently not implemented.

cache = init(prob, NewtonRaphson(); show_trace = Val(true));
solve!(cache)
cache.timer

 ───────────────────────────────────────────────────────────────────────────────
                                       Time                    Allocations      
                              ───────────────────────   ────────────────────────
       Tot / % measured:           1.20s /  22.6%            202MiB /  21.7%    

 Section              ncalls     time    %tot     avg     alloc    %tot      avg
 ───────────────────────────────────────────────────────────────────────────────
 cache construction        1    272ms   99.9%   272ms   43.7MiB   99.8%  43.7MiB
 solve                     1    145μs    0.1%   145μs   70.0KiB    0.2%  70.0KiB
   descent                 1   21.3μs    0.0%  21.3μs   1.00KiB    0.0%  1.00KiB
     linear solve          1   19.4μs    0.0%  19.4μs      224B    0.0%     224B
   jacobian                1   3.21μs    0.0%  3.21μs     48.0B    0.0%    48.0B
   step                    1   1.12μs    0.0%  1.12μs     80.0B    0.0%    80.0B
   linesearch              1    405ns    0.0%   405ns     16.0B    0.0%    16.0B
 ───────────────────────────────────────────────────────────────────────────────

Let's try for some other solver:

cache = init(prob, DFSane(); show_trace = Val(true), trace_level = TraceMinimal(50));
solve!(cache)
cache.timer

 ────────────────────────────────────────────────────────────────────────────────
                                        Time                    Allocations      
                               ───────────────────────   ────────────────────────
       Tot / % measured:            259ms /  30.8%           28.6MiB /  44.0%    

 Section               ncalls     time    %tot     avg     alloc    %tot      avg
 ────────────────────────────────────────────────────────────────────────────────
 cache construction         1   71.3ms   89.3%  71.3ms   12.2MiB   96.6%  12.2MiB
 solve                    139   8.51ms   10.7%  61.2μs    442KiB    3.4%  3.18KiB
   linesearch             139   8.05ms   10.1%  57.9μs    144KiB    1.1%  1.03KiB
   update spectral ...    139   30.0μs    0.0%   216ns   2.17KiB    0.0%    16.0B
   step                   139   25.7μs    0.0%   185ns   10.9KiB    0.1%    80.0B
   descent                139   17.3μs    0.0%   125ns   2.17KiB    0.0%    16.0B
 ────────────────────────────────────────────────────────────────────────────────