Specifying keyword argument results in much slower code

General Usage Performance
1

Hi,

I noticed the performance regression in this simple test program of my package PseudoArcLengthContinuation.jl. I have a keyword argument which is only used for printing purposes so it should not affect the computations. Here is a MWE:

using PseudoArcLengthContinuation, LinearAlgebra

println("\n\n--> Continuation method")
k = 2
N = 10
F = (x, p)-> p .* x .+ x.^(k+1)/(k+1) .+ 1.0e-2
Jac_m = (x, p) -> diagm(0 => p  .+ x.^k)
opts = PseudoArcLengthContinuation.ContinuationPar(dsmax = 0.02, dsmin=1e-2, ds=0.0001, maxSteps = 140, pMin = -3)
x0 = 0.01 * ones(N)
opts.newtonOptions.tol     = 1e-8
opts.newtonOptions.verbose       = false

br1, sol, _ = @time PseudoArcLengthContinuation.continuation(F,Jac_m,x0,-1.5,opts,verbosity=0)

br2, sol, _ = @time PseudoArcLengthContinuation.continuation(F,Jac_m,x0,-1.5,opts,verbosity=0, printsolution = x -> norm(x,2))

On my machine, the timings are as follows

0.003155 seconds (21.00 k allocations: 1.335 MiB)
0.348949 seconds (766.59 k allocations: 39.182 MiB, 6.28% gc time)

It looks like a type problem but I enforced the type of keyword parameter printsolution::Function.

I would appreciate if someone has an idea as I use this type of arguments everywhere…

Thank you for your help,

Best regards

2

It’s always helpful to use BenchmarkTools:

julia> using BenchmarkTools

julia> @btime PseudoArcLengthContinuation.continuation(
           $F,$Jac_m,$x0,-1.5,$opts,verbosity=0);
  2.322 ms (20838 allocations: 1.33 MiB)

julia> @btime PseudoArcLengthContinuation.continuation(
           $F,$Jac_m,$x0,-1.5,$opts,verbosity=0, printsolution = x -> norm(x,2));
  2.320 ms (20838 allocations: 1.33 MiB)

But you may ask that why @time ... was showing super slow timing even executing it multiple times. This is because (“in REPL”) a new closure is created every time the code containing it is evaluated:

julia> x -> norm(x,2)
#16 (generic function with 1 method)

julia> x -> norm(x,2)
#18 (generic function with 1 method)

The numbers #16 and #18 indicate they are different objects. So, to use @time properly, you can assign it to a variable and call your function twice:

julia> f = x -> norm(x,2)
#20 (generic function with 1 method)

julia> @time PseudoArcLengthContinuation.continuation(
           F,Jac_m,x0,-1.5,opts,verbosity=0, printsolution = f);
  0.363651 seconds (1.08 M allocations: 55.602 MiB, 3.65% gc time)

julia> @time PseudoArcLengthContinuation.continuation(
           F,Jac_m,x0,-1.5,opts,verbosity=0, printsolution = f);
  0.004810 seconds (20.85 k allocations: 1.331 MiB)

This means that, as long as you use PseudoArcLengthContinuation.continuation in some function, the slowness you observe is irrelevant.

By the way, not related to the question, but a quick comment. Enforcing ::Function in a keyword argument probably is not a good approach, since any Julia object can behave like a “function” (a callable):

julia> struct MyNorm
           p::Int
       end

julia> (n::MyNorm)(v) = norm(v, n.p)

julia> f = MyNorm(1)
MyNorm(1)

julia> f(1:3)
6.0

julia> f isa Function
false

Now, I can’t pass f as a printsolution.

4 Likes
3

I did that! But I could not make sense of it with the result of @time. Thank you for reassuring me!