Null pass overhead

[MikeInnes]

This is a known issue, but just so it's recorded – Cassette's null pass still has a significant overhead compared to running a function directly.

julia> using Cassette, BenchmarkTools

julia> function loop(x, n)
         r = x/x
         while n > 0
           r *= sin(x)
           n -= 1
         end
         return r
       end
loop (generic function with 1 method)

julia> @btime loop(2, 50)
  474.760 ns (0 allocations: 0 bytes)
0.008615849517446223

julia> Cassette.@context NoOp
Cassette.Context{nametype(NoOp),M,P,T,B} where B<:Union{cNothing, IdDict{Module,Dict{Symbol,BindingMeta}}} where P<:Cassette.AbstractPass where T<:Union{Nothing, Tag} where M

julia> const ctx = NoOp()
Cassette.Context{nametype(NoOp),Nothing,Cassette.NoPass,Nothing,Nothing}(nametype(NoOp)(), nothing, Cassette.NoPass(), nothing, nothing)

julia> @btime Cassette.@overdub ctx loop(2, 50)
  48.256 μs (350 allocations: 7.03 KiB)
0.008615849517446223ple:     1

[jrevels]

The current suspicion is that cases like these that exhibit "mysterious" allocations (and accordingly, drastic slowdowns) are coming from miscompilation of Cassette's overdub generator - i.e. another Julia compiler bug. Example of a bug potentially causing generator miscompile (though this specific one isn't likely causing these kinds of slow downs: JuliaLang/julia#28595).

Related, but not affecting the OP: there's also the case that inference is sometimes thwarted due to poor varargs constant prop (see #71) which is something that we plan on fixing by adding a tuple type lattice element to inference.

In comparison, here's an example of the kind of slowdown that is expected from Cassette right now, assuming it doesn't hit these (unfortunately egregiously common) cases:

julia> function rosenbrock(x::Vector)
           a = 1.0
           b = 100.0
           result = 0.0
           for i in 1:length(x)-1
               result += (a - x[i])^2 + b*(x[i+1] - x[i]^2)^2
           end
           return result
       end
rosenbrock (generic function with 1 method)

julia> ctx, x = NoOp(), rand(1000);

julia> @btime Cassette.overdub($ctx, rosenbrock, $x)
  2.375 μs (0 allocations: 0 bytes)
20391.111122119724

julia> @btime rosenbrock($x)
  1.037 μs (2 allocations: 32 bytes)
20391.111122119724

[MikeInnes]

When you say "expected slowdown", I assume the idea is that future compiler optimisations will remove the rest of the overhead? Otherwise, 2x overhead on all code would be pretty heavy.

[jrevels]

Right. The intention is that future "null pass" overhead will go to 0 as we improve the compiler.

[HarrisonGrodin]

In the rosenbrock example, why does overdubbing not produce any allocations, even though calling the function normally does?

[jrevels]

In the rosenbrock example, why does overdubbing not produce any allocations, even though calling the function normally does?

Ah, good catch - I accidentally ran the benchmarks using a branch containing some WIP compiler modifications.

Here are the same benchmark runs on an "official" Julia 1.0 build (basically the same results minus the erroneous allocations):

julia> @btime Cassette.overdub($ctx, rosenbrock, $x)
  2.358 μs (0 allocations: 0 bytes)
21429.92238967933

julia> @btime rosenbrock($x)
  1.060 μs (0 allocations: 0 bytes)
21429.92238967933

julia> versioninfo()
Julia Version 1.0.0
Commit 5d4eaca0c9 (2018-08-08 20:58 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin17.5.0)
  CPU: Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.0 (ORCJIT, skylake)

[MikeInnes]

There could be multiple things going on here, but in my own cases I haven't seen anything suspicious when logging compilation or disabling the compiler's try/catch for this. However, I have noticed that adding "precompilation" statements, which avoid Julia having to re-compile the entire call tree at once, can solve this issue. For example, calling overdub(ctx, :, 1, 2) before overdub(rosenbrock, x) might avoid the latter being slow.

It could be some kind of over-specialisation heuristic that pops up for generated functions, but it's notable that the output of code_typed looks good with and without the precompilation hack.

Edit: looks like my hunch was right and this is what method_for_inference_limit_heuristics is for. I would still call it a bug that code_typed doesn't reflect what the compiler sees, though.

[jrevels]

Note that loop now shows zero overhead for execution in a no-op context on more recent Julia builds:

julia> versioninfo()
Julia Version 1.1.0-DEV.603
Commit cbb4f699c5 (2018-11-02 14:17 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin17.5.0)
  CPU: Intel(R) Core(TM) i7-7920HQ CPU @ 3.10GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.1 (ORCJIT, skylake)

julia> using Cassette, BenchmarkTools

julia> function loop(x, n)
                r = x/x
                while n > 0
                  r *= sin(x)
                  n -= 1
                end
                return r
              end
loop (generic function with 1 method)

julia> Cassette.@context NoOp;

julia> f(x, n) = Cassette.overdub(NoOp(), loop, x, n);

julia> @btime f(x, n) setup=(x=2; n=50)
  288.212 ns (0 allocations: 0 bytes)
0.008615849517446223

julia> @btime loop(x, n) setup=(x=2; n=50)
  288.055 ns (0 allocations: 0 bytes)
0.008615849517446223

As always, please keep filing issues for any new cases where no-op contextual execution has a performance overhead! Thanks 🙂

[MikeInnes]

julia> versioninfo()
Julia Version 1.1.0-DEV.695
Commit 9f43871e54* (2018-11-20 05:28 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin18.2.0)
  CPU: Intel(R) Core(TM) i5-8259U CPU @ 2.30GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-6.0.1 (ORCJIT, skylake)

julia> using Cassette, BenchmarkTools

julia> Cassette.@context NoOp;

julia> function loop(x, n)
         r = x/x
         while n > 0
           r *= sin(x)
           n -= 1
         end
         return r
       end

julia> loop2(x, n) = Cassette.overdub(NoOp(), loop, x, n);

julia> loop3(x, n) = Cassette.overdub(NoOp(), loop2, x, n);

julia> @btime loop(x, n) setup=(x=2; n=50);
  323.500 ns (0 allocations: 0 bytes)

julia> @btime loop2(x, n) setup=(x=2; n=50);
  324.163 ns (0 allocations: 0 bytes)

julia> @btime loop3(x, n) setup=(x=2; n=50);
  1.325 ms (7757 allocations: 147.05 KiB)

Should I open a new issue?

[jrevels]

Yes please! Thanks.