Report elapsed time per solve with solution stats

src/run_spineopt.jl

@@ -141,13 +141,21 @@ function _run_spineopt(
     f(m)
     run_spineopt!(m, url_out; log_level, alternative, kwargs...)
     t_end = now()
-    elapsed_time_string = string(Dates.canonicalize(Dates.CompoundPeriod(Dates.Millisecond(t_end - t_start))))
+    elapsed_time_string = _elapsed_time_string(t_start, t_end)
     @log log_level 1 "Execution complete. Started at $t_start, ended at $t_end, elapsed time: $elapsed_time_string"
     if url_out !== nothing
         stat_keys = [
             :SpineOpt_version, :SpineOpt_git_hash, :SpineInterface_version, :SpineInterface_git_hash, :elapsed_time
         ]
         stat_values = Any[so_ver, so_git_hash, si_ver, si_git_hash, elapsed_time_string]
+        elapsed_time_by_solve = get(m.ext[:spineopt].extras, :elapsed_time_by_solve, nothing)
+        if elapsed_time_by_solve !== nothing
+            elapsed_time_by_solve_map = Map(
+                string.(keys(elapsed_time_by_solve)), collect(values(elapsed_time_by_solve))
+            )
+            push!(stat_keys, :elapsed_time_by_solve)
+            push!(stat_values, elapsed_time_by_solve_map)
+        end
         m_mp = master_model(m)
         if m_mp !== nothing
             gaps = m_mp.ext[:spineopt].benders_gaps

src/run_spineopt_basic.jl

@@ -513,6 +513,7 @@ function _do_solve_model!(
     save_outputs=true,
     skip_failed_windows=false,
 )
+    t_start = now()
     k0 = _resume_run!(m, resume_file_path; log_level, update_names)
     k0 === nothing && return m
     m.ext[:spineopt].has_results[] = false
@@ -546,6 +547,14 @@ function _do_solve_model!(
         m.ext[:spineopt].has_results[] = false
     end
     _call_event_handlers(m, :model_solved)
+    t_end = now()
+    elapsed_time_string = _elapsed_time_string(t_start, t_end)
+    if !isempty(output_suffix)
+        push!(
+            get!(m.ext[:spineopt].extras, :elapsed_time_by_solve, Dict()),
+            output_suffix => _elapsed_time_string(t_start, t_end),
+        )
+    end
     true
 end
 

src/util/misc.jl

@@ -356,6 +356,10 @@ function _with_model_env(f, m)
     end
 end
 
+function _elapsed_time_string(t_start, t_end)
+    string(Dates.canonicalize(Dates.CompoundPeriod(Dates.Millisecond(t_end - t_start))))
+end
+
 # Base
 _ObjectArrayLike = Union{ObjectLike,Array{T,1} where T<:ObjectLike}
 _RelationshipArrayLike{K} = NamedTuple{K,V} where {K,V<:Tuple{Vararg{_ObjectArrayLike}}}