Surprising runtime behaviour with objective types

[goerch]

Based on the discussion at https://discourse.julialang.org/t/surprising-runtime-behaviour-when-wrapping-functions/68140/3 the small test program

using BenchmarkTools
using NLSolversBase

function evaluate(f, x)
    return f(x)
end
function evaluate(od::OnceDifferentiable, x)
    return od.f(x)
end

function test(f, n)
    [evaluate(f, x) for x in 1:n]
end

f = x -> x
df = x -> [1, 1]
x_seed = [0.0, 0.0]
f_seed = [0.0, 0.0]
df_seed = [0.0 0.0; 0.0 0.0]
od = OnceDifferentiable(f, df, nothing, x_seed, f_seed, df_seed)
for n in [10, 100, 1000, 10000, 100000]
    test(f, n)
    @time test(f, n)

    test(od, n)
    @time test(od, n)
end
println()

@btime test(f, 10)
@btime test(od, 10)
@btime test(f, 100)
@btime test(od, 100)
@btime test(f, 1000)
@btime test(od, 1000)
@btime test(f, 10000)
@btime test(od, 10000)
@btime test(f, 100000)
@btime test(od, 100000)
println()

prints

  0.000011 seconds (3 allocations: 224 bytes)
  0.000013 seconds (3 allocations: 224 bytes)
  0.000001 seconds (3 allocations: 960 bytes)
  0.000003 seconds (3 allocations: 960 bytes)
  0.000001 seconds (4 allocations: 8.016 KiB)
  0.000024 seconds (493 allocations: 15.656 KiB)
  0.000006 seconds (5 allocations: 78.281 KiB)
  0.000265 seconds (9.49 k allocations: 226.547 KiB)
  0.000213 seconds (5 allocations: 781.406 KiB)
  0.013753 seconds (99.49 k allocations: 2.281 MiB, 79.70% gc time)

  267.021 ns (3 allocations: 224 bytes)
  445.685 ns (3 allocations: 224 bytes)
  282.657 ns (3 allocations: 960 bytes)
  1.940 μs (3 allocations: 960 bytes)
  783.750 ns (3 allocations: 8.00 KiB)
  20.600 μs (492 allocations: 15.64 KiB)
  4.740 μs (4 allocations: 78.27 KiB)
  223.000 μs (9493 allocations: 226.53 KiB)
  43.200 μs (4 allocations: 781.39 KiB)
  2.244 ms (99493 allocations: 2.28 MiB)

Maybe Michael Hatherly's solution improves this test case, too?

[goerch]

Modifying OnceDifferentiable to

mutable struct OnceDifferentiable{F, DF, FDF, TF, TDF, TX} <: AbstractObjective
    f::F # objective
    df::DF # (partial) derivative of objective
    fdf::FDF # objective and (partial) derivative of objective
    F::TF # cache for f output
    DF::TDF # cache for df output
    x_f::TX # x used to evaluate f (stored in F)
    x_df::TX # x used to evaluate df (stored in DF)
    f_calls::Vector{Int}
    df_calls::Vector{Int}
end

I see

 0.000015 seconds (3 allocations: 224 bytes)
  0.000005 seconds (1 allocation: 160 bytes)
  0.000001 seconds (3 allocations: 960 bytes)
  0.000000 seconds (1 allocation: 896 bytes)
  0.000002 seconds (4 allocations: 8.016 KiB)
  0.000001 seconds (2 allocations: 7.953 KiB)
  0.000011 seconds (5 allocations: 78.281 KiB)
  0.000011 seconds (3 allocations: 78.219 KiB)
  0.000178 seconds (5 allocations: 781.406 KiB)
  0.000110 seconds (3 allocations: 781.344 KiB)

  305.021 ns (3 allocations: 224 bytes)
  53.191 ns (1 allocation: 160 bytes)
  326.941 ns (3 allocations: 960 bytes)
  86.506 ns (1 allocation: 896 bytes)
  850.000 ns (3 allocations: 8.00 KiB)
  596.154 ns (1 allocation: 7.94 KiB)
  6.100 μs (4 allocations: 78.27 KiB)
  4.520 μs (2 allocations: 78.20 KiB)
  45.800 μs (4 allocations: 781.39 KiB)
  47.400 μs (2 allocations: 781.33 KiB)

BTW, a similar problem could arise in other objective types too.

[pkofod]

Yeah, this is because it's not type stable. This was on purpose to avoid recompilation. I can benchmark it again. The reason is that there's dynamic dispatch which causes allocations.