# @debug has massive performance impact on Windows

**URL:** <https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974>\
**Category:** Performance\
**Created:** [September 18, 2023, 9:53am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974 "2023-09-18T09:53:57Z")\
**Posts on this page:** 20\
**Page:** 1

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 9:53am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/1 "2023-09-18T09:53:57Z")

</div>

Hey guys,

I found that the `@debug` macro has a massive performance impact on my code. I use the macro very often, because the [documentation](https://docs.julialang.org/en/v1/stdlib/Logging/#man-logging) says:

> [The macro] will produce no output by default. Furthermore, it’s very cheap to leave debug statements like this in the source code because the system avoids evaluating the message if it would later be ignored.

But it looks like this _is not_ cheap, see the MWE, that is 10x slower by placing the macro in a fast evaluating function from the documentation examples.

Am I doing something wrong? Otherwise there should be a note in the docu that the macro should not be used in (performance) optimized code.

Thank you & best regards!

MWE (Julia 1.9.2)

```julia
using BenchmarkTools

function my_sum(x)
    return sum(x)
end

function my_sum_debug(x)
    @debug "The given x is " x 
    return sum(x)
end

x = rand(1000)
@btime my_sum($x) # 61.702 ns (0 allocations: 0 bytes)
@btime my_sum_debug($x) # 755.752 ns (2 allocations: 112 bytes)

```

---

<div class="post-metadata">

**Author:** ![skleinbo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/skleinbo/32/36080_2.png) [@skleinbo](https://discourse.julialang.org/u/skleinbo)\
**Post date:** [September 18, 2023, 10:22am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/2 "2023-09-18T10:22:10Z")

</div>

Well, it’s _absolutely_ cheap, not relatively. There is some small but fixed overhead (use `@macroexpand` to see the expression generated by `@debug`), and because the workload in your example is trivial, it becomes very noticeable. Make `x` a hundred times larger, and the impact of the debug statement is “only” about 3% (on my machine).

Please also note that you should _always_ interpolate external variables into benchmark expressions

```julia
@btime my_sum($x)

```

for an accurate measurement.

Edit: I concur with Mason below. The overhead in the original example is ~2x for me as well. 10x seems really excessive.

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 10:51am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/3 "2023-09-18T10:51:00Z")

</div>

Thanks!

Yep, I edited the “$”.

I see that the overhead for a single evaluation is not much, but in my special case it had a noticable effect, because there where thousands of @debug evaluations per second (which I thought were totally ignored as long as debugging is disabled) - I basically used it for easy print-debugging a entire software library.

---

<div class="post-metadata">

**Author:** ![Mason](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mason/32/2423_2.png) [@Mason](https://discourse.julialang.org/u/Mason)\
**Post date:** [September 18, 2023, 11:15am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/4 "2023-09-18T11:15:23Z")

</div>

Hm interesting, I can’t reproduce your benchmark. Here’s what I see:

> **Version info**
>
> ```julia
> julia> versioninfo()
> Julia Version 1.9.3
> Commit bed2cd540a* (2023-08-24 14:43 UTC)
> 
> Platform Info:
> OS: Linux (x86_64-pc-linux-gnu)
> CPU: 12 × AMD Ryzen 5 5600X 6-Core Processor
> WORD_SIZE: 64
> LIBM: libopenlibm
> LLVM: libLLVM-14.0.6 (ORCJIT, znver3)
> Threads: 6 on 12 virtual cores
> Environment:
> JULIA_NUM_THREADS = 6
> 
> ```
> 
> This text will be hidden

> **Definitions**
>
> ```julia
> using BenchmarkTools
> 
> function my_sum(x)
> return sum(x)
> end
> 
> function my_sum_debug(x)
> @debug "The given x is " x 
> return sum(x)
> end
> x = rand(1000)
> 
> ```
> 
> This text will be hidden

```julia
julia> @btime my_sum($x);
  51.152 ns (0 allocations: 0 bytes)

julia> @btime my_sum_debug($x);
  114.565 ns (0 allocations: 0 bytes)

```

Importantly, I’m not incurring any allocations from the debug statements, and they’re only taking ~60 extra nanoseconds rather than ~600 extra nanoseconds.

Are you sure you’re not in a mode where the debug statements are being saved to a file or something?

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 11:23am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/5 "2023-09-18T11:23:06Z")

</div>

Just started with a blank REPL (Julia 1.9.2) and `ENV["JULIA_DEBUG"]` is not set.  
I give 1.9.3 a try…

EDIT:  
Same allocations/timing in Julia 1.9.3 with undefinded `ENV["JULIA_DEBUG"]`

And even more intersting: If I set `ENV["JULIA_DEBUG"] = nothing`, benchmark worsens to 5 allocations and 264 bytes…

---

<div class="post-metadata">

**Author:** ![kristoffer.carlsson](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/kristoffer.carlsson/32/22_2.png) [@kristoffer.carlsson](https://discourse.julialang.org/u/kristoffer.carlsson)\
**Post date:** [September 18, 2023, 11:28am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/6 "2023-09-18T11:28:10Z")

</div>

```julia
julia> @btime my_sum($x)
  35.591 ns (0 allocations: 0 bytes)
506.50792005648816

julia> @btime my_sum_debug($x)
  56.696 ns (0 allocations: 0 bytes)
506.50792005648816

```

for me on 1.9.3.

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 11:32am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/7 "2023-09-18T11:32:00Z")

</div>

Hm… so am I doing something wrong?

```julia
Julia Version 1.9.3
Commit bed2cd540a (2023-08-24 14:43 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: 8 × Intel(R) Core(TM) i7-8565U CPU @ 1.80GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 1 on 8 virtual cores

```

Even in 1.9.3. I have:

```julia
julia> @btime my_sum($x)
  61.876 ns (0 allocations: 0 bytes)
500.0120162080791

julia> @btime my_sum_debug($x)
  479.487 ns (2 allocations: 112 bytes)
500.0120162080791

```

---

<div class="post-metadata">

**Author:** ![Mason](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mason/32/2423_2.png) [@Mason](https://discourse.julialang.org/u/Mason)\
**Post date:** [September 18, 2023, 11:41am UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/8 "2023-09-18T11:41:34Z")

</div>

What is the output of you running

```julia
using Logging
Logging.min_enabled_level(global_logger())

```

?

---

<div class="post-metadata">

**Author:** ![albheim](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/albheim/32/34660_2.png) [@albheim](https://discourse.julialang.org/u/albheim)\
**Post date:** [September 18, 2023, 12:17pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/9 "2023-09-18T12:17:27Z")

</div>

Do you have anything in your startup that could affect this for any reason? Tried starting julia with `julia --startup-file=no`?

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 12:17pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/10 "2023-09-18T12:17:30Z")

</div>

```julia
julia> using Logging
julia> Logging.min_enabled_level(global_logger())
Info

```

Thank you all for the fast replies BTW!

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 12:23pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/11 "2023-09-18T12:23:33Z")

</div>

same result with `julia --startup-file=no`

---

<div class="post-metadata">

**Author:** ![nilshg](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/nilshg/32/2283_2.png) [@nilshg](https://discourse.julialang.org/u/nilshg)\
**Post date:** [September 18, 2023, 12:24pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/12 "2023-09-18T12:24:58Z")

</div>

Just as an extra data point you’re not alone:

```julia
julia> @btime my_sum($x)
  67.076 ns (0 allocations: 0 bytes)
481.4370737577461

julia> @btime my_sum_debug($x)
  755.372 ns (2 allocations: 112 bytes)
481.4370737577461

julia> using Logging

julia> Logging.min_enabled_level(global_logger())
Info

```

on 1.10-beta2, Windows 10 (I assume Kristoffer and Mason you are on Linux?)

---

<div class="post-metadata">

**Author:** ![mihalybaci](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mihalybaci/32/13528_2.png) [@mihalybaci](https://discourse.julialang.org/u/mihalybaci)\
**Post date:** [September 18, 2023, 12:45pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/13 "2023-09-18T12:45:28Z")

</div>

Another Windows data point with a fresh Julia v1.9.3:

```julia
julia> @btime my_sum($x)
  94.249 ns (0 allocations: 0 bytes)
487.6221750988597

julia> @btime my_sum_debug($x)
  650.575 ns (2 allocations: 112 bytes)
487.6221750988597

julia> using Logging

julia> Logging.min_enabled_level(global_logger())
Info

```

---

<div class="post-metadata">

**Author:** ![Mason](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mason/32/2423_2.png) [@Mason](https://discourse.julialang.org/u/Mason)\
**Post date:** [September 18, 2023, 1:29pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/14 "2023-09-18T13:29:20Z")

</div>

@mihalybaci @nilshg @ThummeTo do you see similar performance problems on earlier versions of julia? e.g. 1.6 or 1.0? I’m curious if this is something that’s always been this way or is a recent regression.

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 1:39pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/15 "2023-09-18T13:39:00Z")

</div>

Julia 1.6.7 is similiar for me …

```julia
julia> @btime my_sum($x) 
  63.544 ns (0 allocations: 0 bytes)
494.6890586136828

julia> @btime my_sum_debug($x)
  461.224 ns (2 allocations: 144 bytes)
494.6890586136828

```

Julia 1.0.5:

```julia
julia> @btime my_sum($x) 
  59.858 ns (0 allocations: 0 bytes)
489.8734842999011

julia> @btime my_sum_debug($x)
  471.429 ns (4 allocations: 176 bytes)
489.8734842999011

```

---

<div class="post-metadata">

**Author:** ![skleinbo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/skleinbo/32/36080_2.png) [@skleinbo](https://discourse.julialang.org/u/skleinbo)\
**Post date:** [September 18, 2023, 1:40pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/16 "2023-09-18T13:40:53Z")

</div>

Try `Logging.disable_logging(Debug)` to filter debug messages at the earliest time. The remaining overhead should really be tiny.

On a tangent, does anybody know why `sum` is seemingly really slow on an M1…? That’s a ~3 fold increase over an 8th generation mobile i7 ([from OP](https://discourse.julialang.org/t/debug-has-massive-performance-impact/103974/7)).

```julia
julia> @btime sum($x) # 1000 elements Float64
  174.389 ns (0 allocations: 0 bytes)

```

> **versioninfo**
>
> ```julia
> julia> versioninfo()
> Julia Version 1.9.3
> Commit bed2cd540a1 (2023-08-24 14:43 UTC)
> Build Info:
> Official https://julialang.org/ release
> Platform Info:
> OS: macOS (arm64-apple-darwin22.4.0)
> CPU: 8 × Apple M1
> WORD_SIZE: 64
> LIBM: libopenlibm
> LLVM: libLLVM-14.0.6 (ORCJIT, apple-m1)
> Threads: 4 on 4 virtual cores
> Environment:
> JULIA_NUM_THREADS = 4
> JULIA_EDITOR = code
> JULIA_CONDAPKG_BACKEND = Current
> 
> ```

Compiler failing to simd?

---

<div class="post-metadata">

**Author:** ![nilshg](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/nilshg/32/2283_2.png) [@nilshg](https://discourse.julialang.org/u/nilshg)\
**Post date:** [September 18, 2023, 1:47pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/17 "2023-09-18T13:47:46Z")

</div>

On 1.0:

```julia
julia> x = rand(1000);

julia> @btime my_sum($x)
  33.971 ns (0 allocations: 0 bytes)
497.3346280689935

julia> @btime my_sum_debug($x)
  664.145 ns (4 allocations: 176 bytes)
497.3346280689935

```

---

<div class="post-metadata">

**Author:** ![kristoffer.carlsson](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/kristoffer.carlsson/32/22_2.png) [@kristoffer.carlsson](https://discourse.julialang.org/u/kristoffer.carlsson)\
**Post date:** [September 18, 2023, 1:50pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/18 "2023-09-18T13:50:10Z")

</div>

The difference is that on Windows, accessing the environment seems to allocate:

```julia
julia> f() = get(ENV, "JULIA_DEBUG", "")
f (generic function with 1 method)

julia> @btime f(); # Linux
  26.734 ns (0 allocations: 0 bytes)

julia> @btime f(); # Windows
  112.293 ns (2 allocations: 112 bytes)

```

---

<div class="post-metadata">

**Author:** ![mihalybaci](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mihalybaci/32/13528_2.png) [@mihalybaci](https://discourse.julialang.org/u/mihalybaci)\
**Post date:** [September 18, 2023, 1:51pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/19 "2023-09-18T13:51:40Z")

</div>

I also see the slowdown on v1.6.7, but @skleinbo 's trick of disabling logging pretty much eliminates it on the older and newer versions. There is a persistent ~20 ns difference (roughly 20%), but maybe that’s within the error?

---

<div class="post-metadata">

**Author:** ![ThummeTo](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/thummeto/32/26105_2.png) [@ThummeTo](https://discourse.julialang.org/u/ThummeTo)\
**Post date:** [September 18, 2023, 1:57pm UTC](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974/20 "2023-09-18T13:57:57Z")

</div>

I can confirm that ` Logging.disable_logging(Debug)` solves this in Julia 1.6.7 as well as in 1.9.3, the timing difference almost vanishes and we have zero allocations:

Julia 1.9.3 (Windows)

```julia
 @btime my_sum($x) 
  62.016 ns (0 allocations: 0 bytes)
511.22678570928684

julia> @btime my_sum_debug($x) 
  69.152 ns (0 allocations: 0 bytes)
511.22678570928684

```

So could this be Julia-Default?

[Next page](https://discourse.julialang.org/t/debug-has-massive-performance-impact-on-windows/103974.md?page=2)