From 9afd645b4af3fcb9684a97f61144cdadcb1ab9d2 Mon Sep 17 00:00:00 2001 From: fpacaud Date: Mon, 15 Aug 2022 15:44:11 -0500 Subject: [PATCH 1/2] add functions to decompose the time spent in callbacks/linear solver --- src/utils.jl | 71 +++++++++++++++++++++++++++++++++++++++++++++ test/madnlp_test.jl | 12 ++++++++ 2 files changed, 83 insertions(+) diff --git a/src/utils.jl b/src/utils.jl index 9e56b46c..cc9aef30 100644 --- a/src/utils.jl +++ b/src/utils.jl @@ -84,3 +84,74 @@ const SubVector{Tv} = SubArray{Tv, 1, Vector{Tv}, Tuple{Vector{Int}}, false} acceptable_cnt::Int = 0 end + +""" + timing_callbacks(ips::InteriorPointSolver; ntrials=10) + +Return the average timings spent in each callback for `ntrials` different trials. +Results are returned inside a 5-element array, ordered as +``` +results = [ + time_eval_objective, + time_eval_constraints, + time_eval_gradient_objective, + time_eval_jacobian_constraints, + time_eval_hessian_lagrangian, +] + +``` +""" +function timing_callbacks(ips; ntrials=10) + time_callbacks = zeros(Float64, 5) + for _ in 1:ntrials + time_callbacks[1] += @elapsed eval_f_wrapper(ips, ips.x) + time_callbacks[2] += @elapsed eval_cons_wrapper!(ips, ips.c, ips.x) + time_callbacks[3] += @elapsed eval_grad_f_wrapper!(ips, ips.f,ips.x) + time_callbacks[4] += @elapsed eval_jac_wrapper!(ips, ips.kkt, ips.x) + time_callbacks[5] += @elapsed eval_lag_hess_wrapper!(ips, ips.kkt, ips.x, ips.l) + end + time_callbacks ./= ntrials + return time_callbacks +end + +""" + timing_linear_solver(ips::InteriorPointSolver; ntrials=10) + +Return the average timings spent in the linear solver for `ntrials` different trials. +Results are returned inside a 3-element array, ordered as +``` +results = [ + time_build_kkt, + time_factorization, + time_triangular_solve, +] + +``` +""" +function timing_linear_solver(ips; ntrials=10) + time_linear_solver = zeros(Float64, 3) + for _ in 1:ntrials + time_linear_solver[1] += @elapsed build_kkt!(ips.kkt) + time_linear_solver[2] += @elapsed factorize!(ips.linear_solver) + time_linear_solver[3] += @elapsed solve_refine_wrapper!(ips,ips.d,ips.p) + end + time_linear_solver ./= ntrials + return time_linear_solver +end + +""" + timing_madnlp(ips::InteriorPointSolver; ntrials=10) + +Return the average time spent in the callbacks and in the linear solver, +for `ntrials` different trials. + +Results are returned as a named-tuple. + +""" +function timing_madnlp(ips; ntrials=10) + return ( + time_linear_solver=timing_linear_solver(ips; ntrials=ntrials), + time_callbacks=timing_callbacks(ips; ntrials=ntrials), + ) +end + diff --git a/test/madnlp_test.jl b/test/madnlp_test.jl index 5bb7a3f6..0e889892 100644 --- a/test/madnlp_test.jl +++ b/test/madnlp_test.jl @@ -96,3 +96,15 @@ end @test ips.status == MadNLP.SOLVE_SUCCEEDED end +@testset "MadNLP timings" begin + nlp = MadNLPTests.HS15Model() + ips = MadNLP.InteriorPointSolver(nlp) + time_callbacks = MadNLP.timing_callbacks(ips) + @test isa(time_callbacks, Array) + time_linear_solver = MadNLP.timing_linear_solver(ips) + @test isa(time_linear_solver, Array) + time_madnlp = MadNLP.timing_madnlp(ips) + @test isa(time_madnlp.time_linear_solver, Array) + @test isa(time_madnlp.time_callbacks, Array) +end + From 1568da5e5980f51e7e44504b656016b4547df7b8 Mon Sep 17 00:00:00 2001 From: fpacaud Date: Tue, 16 Aug 2022 12:55:37 -0500 Subject: [PATCH 2/2] address PR's comments --- src/utils.jl | 60 ++++++++++++++++++++------------------------- test/madnlp_test.jl | 8 +++--- 2 files changed, 30 insertions(+), 38 deletions(-) diff --git a/src/utils.jl b/src/utils.jl index cc9aef30..11561616 100644 --- a/src/utils.jl +++ b/src/utils.jl @@ -89,54 +89,46 @@ end timing_callbacks(ips::InteriorPointSolver; ntrials=10) Return the average timings spent in each callback for `ntrials` different trials. -Results are returned inside a 5-element array, ordered as -``` -results = [ - time_eval_objective, - time_eval_constraints, - time_eval_gradient_objective, - time_eval_jacobian_constraints, - time_eval_hessian_lagrangian, -] - -``` +Results are returned inside a named-tuple. + """ function timing_callbacks(ips; ntrials=10) - time_callbacks = zeros(Float64, 5) + t_f, t_c, t_g, t_j, t_h = (0.0, 0.0, 0.0, 0.0, 0.0) for _ in 1:ntrials - time_callbacks[1] += @elapsed eval_f_wrapper(ips, ips.x) - time_callbacks[2] += @elapsed eval_cons_wrapper!(ips, ips.c, ips.x) - time_callbacks[3] += @elapsed eval_grad_f_wrapper!(ips, ips.f,ips.x) - time_callbacks[4] += @elapsed eval_jac_wrapper!(ips, ips.kkt, ips.x) - time_callbacks[5] += @elapsed eval_lag_hess_wrapper!(ips, ips.kkt, ips.x, ips.l) + t_f += @elapsed eval_f_wrapper(ips, ips.x) + t_c += @elapsed eval_cons_wrapper!(ips, ips.c, ips.x) + t_g += @elapsed eval_grad_f_wrapper!(ips, ips.f,ips.x) + t_j += @elapsed eval_jac_wrapper!(ips, ips.kkt, ips.x) + t_h += @elapsed eval_lag_hess_wrapper!(ips, ips.kkt, ips.x, ips.l) end - time_callbacks ./= ntrials - return time_callbacks + return ( + time_eval_objective = t_f / ntrials, + time_eval_constraints = t_c / ntrials, + time_eval_gradient = t_g / ntrials, + time_eval_jacobian = t_j / ntrials, + time_eval_hessian = t_h / ntrials, + ) end """ timing_linear_solver(ips::InteriorPointSolver; ntrials=10) Return the average timings spent in the linear solver for `ntrials` different trials. -Results are returned inside a 3-element array, ordered as -``` -results = [ - time_build_kkt, - time_factorization, - time_triangular_solve, -] - -``` +Results are returned inside a named-tuple. + """ function timing_linear_solver(ips; ntrials=10) - time_linear_solver = zeros(Float64, 3) + t_build, t_factorize, t_backsolve = (0.0, 0.0, 0.0) for _ in 1:ntrials - time_linear_solver[1] += @elapsed build_kkt!(ips.kkt) - time_linear_solver[2] += @elapsed factorize!(ips.linear_solver) - time_linear_solver[3] += @elapsed solve_refine_wrapper!(ips,ips.d,ips.p) + t_build += @elapsed build_kkt!(ips.kkt) + t_factorize += @elapsed factorize!(ips.linear_solver) + t_backsolve += @elapsed solve_refine_wrapper!(ips,ips.d,ips.p) end - time_linear_solver ./= ntrials - return time_linear_solver + return ( + time_build_kkt = t_build / ntrials, + time_factorization = t_factorize / ntrials, + time_backsolve = t_backsolve / ntrials, + ) end """ diff --git a/test/madnlp_test.jl b/test/madnlp_test.jl index 0e889892..103720a9 100644 --- a/test/madnlp_test.jl +++ b/test/madnlp_test.jl @@ -100,11 +100,11 @@ end nlp = MadNLPTests.HS15Model() ips = MadNLP.InteriorPointSolver(nlp) time_callbacks = MadNLP.timing_callbacks(ips) - @test isa(time_callbacks, Array) + @test isa(time_callbacks, NamedTuple) time_linear_solver = MadNLP.timing_linear_solver(ips) - @test isa(time_linear_solver, Array) + @test isa(time_linear_solver, NamedTuple) time_madnlp = MadNLP.timing_madnlp(ips) - @test isa(time_madnlp.time_linear_solver, Array) - @test isa(time_madnlp.time_callbacks, Array) + @test isa(time_madnlp.time_linear_solver, NamedTuple) + @test isa(time_madnlp.time_callbacks, NamedTuple) end