|
| 1 | +# [Logging](@id sec_logging) |
| 2 | + |
| 3 | +In the final part of the square‑root story we instrument the Heron iteration with logging. |
| 4 | +The logging system answers two questions separately: |
| 5 | + |
| 6 | +* **What happens when we log?** → a [`LoggingAction`](@ref). |
| 7 | +* **When do we log?** → an [`AlgorithmLogger`](@ref) mapping contexts to actions. |
| 8 | + |
| 9 | +This separation lets users compose rich behaviors (printing, collecting stats, plotting) without modifying algorithm code, and lets algorithm authors emit domain‑specific events. |
| 10 | + |
| 11 | +## Recap: Default logging contexts |
| 12 | + |
| 13 | +The generic `solve!` loop in `interface/interface.jl` emits these contexts: |
| 14 | + |
| 15 | +| Context | Meaning | |
| 16 | +|-----------:|------------------------------------------| |
| 17 | +| `:Start` | Just before iteration begins | |
| 18 | +| `:Init` | After state initialization | |
| 19 | +| `:PreStep` | Right before a `step!` | |
| 20 | +| `:PostStep`| Right after a `step!` | |
| 21 | +| `:Stop` | After halting (stopping criterion met) | |
| 22 | + |
| 23 | +Algorithms may add their own (e.g. `:Refinement`, `:RejectedStep`) by calling [`handle_message`](@ref) with a custom symbol. |
| 24 | + |
| 25 | +## Global enable/disable |
| 26 | + |
| 27 | +```julia |
| 28 | +using AlgorithmsInterface: set_global_logging_state!, get_global_logging_state |
| 29 | +set_global_logging_state!(false) # silence all logging |
| 30 | +previous = set_global_logging_state!(true) # restore |
| 31 | +``` |
| 32 | + |
| 33 | +## Instrumenting the square‑root algorithm |
| 34 | + |
| 35 | +We start with minimal feedback: iteration number and current estimate. |
| 36 | + |
| 37 | +```julia |
| 38 | +iter_printer = CallbackAction() do alg, prob, st |
| 39 | + @printf("Iter %3d x = %.12f\n", st.iteration, st.x) |
| 40 | +end |
| 41 | + |
| 42 | +logger = AlgorithmLogger(:PostStep => iter_printer) |
| 43 | + |
| 44 | +with(ALGORITHM_LOGGER => logger) do |
| 45 | + state = solve(SqrtProblem(42.0), HeronAlgorithm(1.0, StopAfterIteration(8))) |
| 46 | + println("Final ≈ sqrt(42): ", state.x) |
| 47 | +end |
| 48 | +``` |
| 49 | + |
| 50 | +### Timing the run |
| 51 | + |
| 52 | +Add actions for start timestamp and per‑step elapsed time: |
| 53 | + |
| 54 | +```julia |
| 55 | +start_time = Ref{Float64}(0.0) |
| 56 | + |
| 57 | +record_start = CallbackAction() do alg, prob, st |
| 58 | + start_time[] = time() |
| 59 | +end |
| 60 | + |
| 61 | +show_elapsed = CallbackAction() do alg, prob, st |
| 62 | + dt = time() - start_time[] |
| 63 | + @printf("Iter %3d elapsed = %.3fs\n", st.iteration, dt) |
| 64 | +end |
| 65 | + |
| 66 | +logger = AlgorithmLogger( |
| 67 | + :Init => record_start, |
| 68 | + :PostStep => LogGroup([iter_printer, show_elapsed]), |
| 69 | + :Stop => CallbackAction() do alg, prob, st |
| 70 | + @printf("Done after %d iterations (total %.3fs)\n", st.iteration, time() - start_time[]) |
| 71 | + end, |
| 72 | +) |
| 73 | +``` |
| 74 | + |
| 75 | +### Conditional logging (every N steps) |
| 76 | + |
| 77 | +```julia |
| 78 | +every_five = IfAction( |
| 79 | + (prob, alg, st; kwargs...) -> st.iteration % 5 == 0, |
| 80 | + CallbackAction() do alg, prob, st |
| 81 | + println("Checkpoint at iteration ", st.iteration) |
| 82 | + end, |
| 83 | +) |
| 84 | + |
| 85 | +logger = AlgorithmLogger(:PostStep => every_five) |
| 86 | +``` |
| 87 | + |
| 88 | +### Capturing history for analysis |
| 89 | + |
| 90 | +Instead of printing, store iterates in a custom action: |
| 91 | + |
| 92 | +```julia |
| 93 | +struct CaptureHistory <: LoggingAction |
| 94 | + xs::Vector{Float64} |
| 95 | +end |
| 96 | +CaptureHistory() = CaptureHistory(Float64[]) |
| 97 | + |
| 98 | +function AlgorithmsInterface.handle_message!(act::CaptureHistory, prob::SqrtProblem, alg::HeronAlgorithm, st::HeronState; kwargs...) |
| 99 | + push!(act.xs, st.x) |
| 100 | + return nothing |
| 101 | +end |
| 102 | + |
| 103 | +history = CaptureHistory() |
| 104 | +logger = AlgorithmLogger(:PostStep => history) |
| 105 | +with(ALGORITHM_LOGGER => logger) do |
| 106 | + solve(SqrtProblem(42.0), HeronAlgorithm(1.0, StopWhenStable(1e-10) & StopAfterIteration(200))) |
| 107 | +end |
| 108 | +println("Stored ", length(history.xs), " iterates") |
| 109 | +``` |
| 110 | + |
| 111 | +You can later inspect convergence visually (plot `history.xs`). |
| 112 | + |
| 113 | +### Multiple simultaneous behaviors |
| 114 | + |
| 115 | +Group actions to avoid multiple context entries: |
| 116 | + |
| 117 | +```julia |
| 118 | +logger = AlgorithmLogger( |
| 119 | + :PostStep => LogGroup([iter_printer, history, every_five]), |
| 120 | +) |
| 121 | +``` |
| 122 | + |
| 123 | +### Adding custom contexts |
| 124 | + |
| 125 | +Suppose we augment Heron's method with a fallback if `x` becomes non‑finite. We can log that: |
| 126 | + |
| 127 | +```julia |
| 128 | +fallback_action = CallbackAction() do alg, prob, st; println("Fallback triggered at iteration ", st.iteration); end |
| 129 | +logger = AlgorithmLogger(:Fallback => fallback_action, :PostStep => iter_printer) |
| 130 | + |
| 131 | +function safe_step!(prob::SqrtProblem, alg::HeronAlgorithm, st::HeronState) |
| 132 | + isnan(st.x) && begin |
| 133 | + handle_message(prob, alg, st, :Fallback) |
| 134 | + st.x = alg.initial_guess |
| 135 | + end |
| 136 | + step!(prob, alg, st) |
| 137 | +end |
| 138 | +``` |
| 139 | + |
| 140 | +Just call `handle_message(prob, alg, st, :YourContext)` whenever the event occurs. |
| 141 | + |
| 142 | +### Robustness: error isolation |
| 143 | + |
| 144 | +If a `LoggingAction` throws, the system catches and reports the error without aborting the algorithm. Keep actions side‑effect focused and fast; heavy processing can collect data during iteration and post‑process afterwards. |
| 145 | + |
| 146 | +### Writing a new action type (summary statistics) |
| 147 | + |
| 148 | +```julia |
| 149 | +struct StatsCollector <: LoggingAction |
| 150 | + n::Int |
| 151 | + sum::Float64 |
| 152 | +end |
| 153 | +StatsCollector() = StatsCollector(0, 0.0) |
| 154 | + |
| 155 | +function AlgorithmsInterface.handle_message!(act::StatsCollector, prob::SqrtProblem, alg::HeronAlgorithm, st::HeronState; kwargs...) |
| 156 | + act.n += 1 |
| 157 | + act.sum += st.x |
| 158 | +end |
| 159 | + |
| 160 | +avg_action = CallbackAction() do alg, prob, st |
| 161 | + # could query stats at :Stop using captured object |
| 162 | +end |
| 163 | +stats = StatsCollector() |
| 164 | +logger = AlgorithmLogger(:PostStep => LogGroup([stats, iter_printer])) |
| 165 | +``` |
| 166 | + |
| 167 | +At the end: |
| 168 | + |
| 169 | +```julia |
| 170 | +println("Average iterate value = ", stats.sum / stats.n) |
| 171 | +``` |
| 172 | + |
| 173 | +## Choosing what to store vs. print |
| 174 | + |
| 175 | +Guidelines: |
| 176 | + |
| 177 | +* Use printing for immediate feedback (development / CLI runs). |
| 178 | +* Store vectors / tables in custom actions for later analysis or plotting. |
| 179 | +* Keep actions pure w.r.t. algorithm state (read but do not modify `state`). |
| 180 | +* Prefer one `LogGroup` per context over many individual mappings. |
| 181 | + |
| 182 | +## Reference API |
| 183 | + |
| 184 | +Auto‑generated documentation for logging infrastructure follows. |
| 185 | + |
| 186 | +```@autodocs |
| 187 | +Modules = [AlgorithmsInterface] |
| 188 | +Pages = ["logging.jl"] |
| 189 | +Order = [:type, :function] |
| 190 | +Private = true |
| 191 | +``` |
| 192 | + |
| 193 | +## Wrap‑up |
| 194 | + |
| 195 | +You have now seen: defining an algorithm (interface page), controlling halting (stopping criteria), and instrumenting execution (logging). Together these patterns encourage modular, testable iterative algorithm design. |
0 commit comments