Reduce overhead running with Mocking activated but no patches applied

[nickrobinson251]

A colleague shared this profile, showing the Mocking's get_alternate call was taking the majority of the time despite there being no @patch applied:

I often experience that Mocking, once it had been activated indirectly in the shell by running some tests that use mocking, has perf degradation when subsequently running non-mocked code (see profile).

I wonder if we can reduce this overhead?

You can see there are two things taking the time:

1. the haskey call, from every function that is marked @mock checking if there is a corresponding @patch
2. the the macro expand -> current_logger_… call, from the @debug log message (possibly made worse by Improve Mocking debugging #128)

I wonder if we can avoid calling get_alternative at all if we're not iinside Mocking.apply?

e.g. Mocking.apply could set a global / ScopedValue PATCH_ENV_ACTIVE::Bool that can be checked alongside activated() to avoid calling get_alternate at all. (Ofc, would need benchmarking to prove this would reduce the overhead.)

--- a/src/mock.jl
+++ b/src/mock.jl
@@ -40,7 +40,7 @@ macro mock(expr)
     # When `Mocking.activated() == false` then Julia will optimize the
     # code below to have zero-overhead by only executing the original expression.
     result = quote
-        if $activated()
+        if $activated() && $PATCH_ENV_ACTIVE[]
             args_var = tuple($(args...))
             alternate_var = $get_alternate($target, args_var...; call_loc=$call_loc)
             if alternate_var !== nothing

--- a/src/patch.jl
+++ b/src/patch.jl
@@ -206,17 +206,21 @@ end
 # https://github.com/JuliaLang/julia/pull/50958
 if VERSION >= v"1.11.0-DEV.482"
     const PATCH_ENV = ScopedValue(PatchEnv())
-    with_active_env(body::Function, pe::PatchEnv) = with(body, PATCH_ENV => pe)
+    const PATCH_ENV_ACTIVE = ScopedValue(false)
+    with_active_env(body::Function, pe::PatchEnv) = with(body, PATCH_ENV => pe, PATCH_ENV_ACTIVE => true)

Or perhaps even just checking isempty on the patch env would do?

--- a/src/mock.jl
+++ b/src/mock.jl
@@ -40,7 +40,7 @@ macro mock(expr)
     # When `Mocking.activated() == false` then Julia will optimize the
     # code below to have zero-overhead by only executing the original expression.
     result = quote
-        if $activated()
+        if $activated() && $(!($isempty($PATCH_ENV[])))
             args_var = tuple($(args...))
             alternate_var = $get_alternate($target, args_var...; call_loc=$call_loc)
             if alternate_var !== nothing

[omus]

I wonder if we can reduce this overhead?

I'm onboard with this. We definitely should create some benchmarks to measure this that we can test over time to avoid performance regressions.

As for the @debug overhead can you determine if these were measured with debug logging enabled or disabled for this package. I thought when the log level was greater than debug we wouldn't see this kind of overhead but I'll admit I've never verified that.

Mocking.apply could set a global / ScopedValue PATCH_ENV_ACTIVE::Bool that can be checked alongside activated() to avoid calling get_alternate at all

I'm skeptical we can improve performance this way as the activated function is inlined to just be a simple Bool. It's been designed in a way that the get_alternate code path doesn't even exist without Mocking.activate() and it only becomes enabled via invalidation.

Something we could look into is using a LittleDict or something similar in the PatchEnv to reduce the haskey overhead.

One other thing which could be done is to give some guidance on where to put @mock calls. I'm curious if the performance slowdown is due to a mocked call being used in a loop. In such a scenario it may be possible to mock and patch the calling function to reduce the number of get_alternate calls.

[nickrobinson251]

if these were measured with debug logging enabled or disabled for this package

with debug logging disabled 😞

[NHDaly]

Mocking.apply could set a global / ScopedValue PATCH_ENV_ACTIVE::Bool that can be checked alongside activated() to avoid calling get_alternate at all

I'm skeptical we can improve performance this way as the activated function is inlined to just be a simple Bool. It's been designed in a way that the get_alternate code path doesn't even exist without Mocking.activate() and it only becomes enabled via invalidation.

I think there's still a possibility for Nick's suggestion to be a good perf improvement.

We agree that when Mocking is disabled, things are already quite fast. But we run our entire test-suite with Mocking.activate() called at the start, so that we don't end up compiling anything twice. And the concern here is that with mocking activated, but no patches applied, perf is slow.

So I think Nick's suggestion could still have a good positive impact by disabling anything if no patches are active?

[omus]

with debug logging disabled 😞

We'll that's sub-optimal. I thought part of the point of using macros for Julia logging was to be able to optimize the log messages away.

We can definitely refactor how the debugging works. We used to have to pass a debug flag into the apply call to enable it which was a bit strange which is why we switched over to using @debug which seemed more natural. Possibly adding the debug flag to Mocking.activate is the way to go.

I looked a little into Base.CoreLogging and discovered that debug logs aren't truly disabled unless you do:

Logging.disable_logging(Logging.Info)

I would be interested to see the flame graph again with the above code.

We agree that when Mocking is disabled, things are already quite fast. But we run our entire test-suite with Mocking.activate() called at the start, so that we don't end up compiling anything twice. And the concern here is that with mocking activated, but no patches applied, perf is slow.

So I think Nick's suggestion could still have a good positive impact by disabling anything if no patches are active?

I agree. The patch to effectively skip the get_alternate if there are not patches in the environment is a good performance optimization. Implementation wise the example provided won't work as we'd need to check !isempty(PATCH_ENV[].mapping) at runtime which would require PATCH_ENV to be exported.

I took a quick look at different dictionaries to see if there was any major performance differences:

julia> using BenchmarkTools, OrderedCollections

julia> d = Dict{Any,Vector{Function}}()
Dict{Any, Vector{Function}}()

julia> @btime !isempty(d)
  20.207 ns (0 allocations: 0 bytes)
false

julia> @btime haskey(d, get)
  79.976 ns (0 allocations: 0 bytes)
false

julia> id = Base.ImmutableDict{Any,Vector{Function}}()
Base.ImmutableDict{Any, Vector{Function}}()

julia> @btime !isempty(id)
  24.138 ns (0 allocations: 0 bytes)
false

julia> @btime haskey(id, get)
  86.322 ns (0 allocations: 0 bytes)
false

julia> ld = LittleDict{Any,Vector{Function}}()
LittleDict{Any, Vector{Function}, Vector{Any}, Vector{Vector{Function}}}()

julia> @btime !isempty(ld)
  28.559 ns (0 allocations: 0 bytes)
false

julia> @btime haskey(ld, get)
  208.120 ns (0 allocations: 0 bytes)
false

Something may be going on though as using the Dict already in Mocking.jl is more performant:

julia> using BenchmarkTools, Mocking

julia> @btime !isempty(Mocking.PATCH_ENV[].mapping)
  6.291 ns (0 allocations: 0 bytes)
false

julia> @btime haskey(Mocking.PATCH_ENV[].mapping, get)
  8.208 ns (0 allocations: 0 bytes)
false

Something this does bring up though is doing both a isempty and a haskey check will have a performance impact when mocking is activated and patches are applied.

[omus]

The initial PatchEnv we create for PATCH_ENV should always be empty. If we save that patch env to say const ROOT_ENV we could simply check PATCH_ENV[] !== ROOT_ENV to see if a user specified patch environment is used. This should be a very cheap check.