# \`ENV\["JULIA\_DEBUG"\] == "MyModule" && expensive\_debug\_method()\` good practice?

**URL:** https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197
**Category:** Performance
**Created:** [June 25, 2024, 12:18pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197 "2024-06-25T12:18:35Z")
**Posts on this page:** 8
**Page:** 1

<div class="post-metadata">

### Author: ![maxkapur](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/maxkapur/32/21208_2.png) [@maxkapur](https://discourse.julialang.org/u/maxkapur)
#### Post date: [June 25, 2024, 12:18pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/1 "2024-06-25T12:18:35Z")

</div>

Will Julia compile away lines like

```julia
ENV["JULIA_DEBUG"] == "MyModule" && expensive_debug_method()

```

when the environment variable is not set, or does the dictionary lookup happen at runtime? If the latter, is there a good way to implement nontrivial debug logic that will only be compiled in if `ENV["JULIA_DEBUG"] == "MyModule"`? Or is my question poorly posed?

The use case is as follows. Our code implements a custom constrained optimization solver for a particular problem. We already have a bunch of `@debug` messages that print convergence information at each iteration, and I see in the Logging section of the documentation that this has minimal performance impact because “the associated string processing will never be executed unless debug logging is enabled.”

Now, I want to add a debug-mode-only method that does some more expensive verification of the solver convergence (compute dual variables and checks KKT conditions). But if I write `ENV["JULIA_DEBUG"] == "MyModule" && check_kkt()`, then I want Julia to forgo compiling the `check_kkt()` method unless and until someone enables debug mode (i.e. _never_ in production).  
Is this something I should care about, and if so, is the implementation correct?

---

<div class="post-metadata">

### Author: ![maxkapur](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/maxkapur/32/21208_2.png) [@maxkapur](https://discourse.julialang.org/u/maxkapur)
#### Post date: [June 25, 2024, 12:22pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/2 "2024-06-25T12:22:24Z")

</div>

Similarly, can I expect the following not to be compiled if debug is disabled?

```julia
if rand() < 0.5
    @debug "Small"
end

```

---

<div class="post-metadata">

### Author: ![Sukera](https://avatars.discourse-cdn.com/v4/letter/s/ce7236/32.png) [@Sukera](https://discourse.julialang.org/u/Sukera)
#### Post date: [June 25, 2024, 12:27pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/3 "2024-06-25T12:27:12Z")

</div>

> [@maxkapur](#):
>
> when the environment variable is not set, or does the dictionary lookup happen at runtime?

> [@maxkapur](#):
>
> But if I write `ENV["JULIA_DEBUG"] == "MyModule" && check_kkt()`, then I want Julia to forgo compiling the `check_kkt()` method unless and until someone enables debug mode (i.e. _never_ in production).

The dictionary lookup happens at runtime & `check_kkt` will be compiled (but not necessarily run, which is the expensive bit).

> [@maxkapur](#):
>
> Similarly, can I expect the following not to be compiled if debug is disabled?
> 
> ```julia
> if rand() < 0.5
> @debug "Small"
> end
> 
> ```

How should the compiler compile away a call that modifies the RNG state? `rand()` must be called, since it’s not a pure function. The output may not necessarily happen, but the debug string will likely still be constructed.

* * *

You mention printing convergence information - how much overhead is concretely introduced by the logging, and does that information really need to be printed at every iteration?

---

<div class="post-metadata">

### Author: ![maxkapur](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/maxkapur/32/21208_2.png) [@maxkapur](https://discourse.julialang.org/u/maxkapur)
#### Post date: [June 25, 2024, 12:38pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/4 "2024-06-25T12:38:34Z")

</div>

> [@Sukera](#):
>
> How should the compiler compile away a call that modifies the RNG state? ``

Good point. That was a poorly chosen example. I should have written:

```julia
expensive_but_pure_function() && @debug "foo"

```

In theory (but it sounds like not in practice?) the compiler could skip computing the function when debug is disabled here.

---

<div class="post-metadata">

### Author: ![maxkapur](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/maxkapur/32/21208_2.png) [@maxkapur](https://discourse.julialang.org/u/maxkapur)
#### Post date: [June 25, 2024, 12:42pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/5 "2024-06-25T12:42:03Z")

</div>

> [@Sukera](#):
>
> You mention printing convergence information - how much overhead is concretely introduced by the logging, and does that information really need to be printed at every iteration?

A lot. Usually what I do is turn on debug mode and run `julia --project sample_problems.jl 2> log.txt`. This yields a ~50 MB log file that I then process with regex to produce statistics on how many iterations it takes to solve typical instances. It’s sort of a crude, but effective “profiler” that uses the abstractions of “number of iterations” and convergence measures instead of raw function calls.

---

<div class="post-metadata">

### Author: ![Sukera](https://avatars.discourse-cdn.com/v4/letter/s/ce7236/32.png) [@Sukera](https://discourse.julialang.org/u/Sukera)
#### Post date: [June 25, 2024, 2:10pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/6 "2024-06-25T14:10:02Z")

</div>

> [@maxkapur](#):
>
> I should have written:
> 
> ```julia
> expensive_but_pure_function() && @debug "foo"
> 
> ```
> 
> In theory (but it sounds like not in practice?) the compiler could skip computing the function when debug is disabled here.

That’s not how compilers work. It’s not a compile-time known thing whether `@debug` will need to execute or not, since that too is a runtime switch. The `JULIA_DEBUG` environment variable merely provides an interface to change the active logging level from outside the running program, by controlling a global variable. For example, it’s possible to switch the global logger at runtime using `global_logger`. As such, `expensive_but_pure_function()` will be executed regardless of whether `@debug` will print a value or not, because deciding whether to log or not depends on external state.

> [@maxkapur](#):
>
> A lot.

That’s not really a quantifiable amount - are we talking like a 2x slowdown? 3x? How long does one iteration take?

> [@maxkapur](#):
>
> This yields a ~50 MB log file that I then process with regex to produce statistics on how many iterations it takes to solve typical instances. It’s sort of a crude, but effective “profiler” that uses the abstractions of “number of iterations” and convergence measures instead of raw function calls.

It sounds like it would be easier, more performant & more memory efficient to keep that information around in a e.g. memory mapped array, instead of using logging to keep the information. That would also simplify your analysis pipeline because you skip having to regex the information you want out of the text file. In addition, you can then have a global `const KEEP_STATISTICS = true` that you can then switch to `false` to avoid recording any data. Since that’s a global constant, switches like `KEEP_STATISTICS && expensive_but_pure_function()` compile away completely.

---

<div class="post-metadata">

### Author: ![ericphanson](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/ericphanson/32/215186_2.png) [@ericphanson](https://discourse.julialang.org/u/ericphanson)
#### Post date: [June 25, 2024, 2:29pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/7 "2024-06-25T14:29:29Z")

</div>

For logging in particular, one feature of the log macros is that they are lazy, so in

```julia
@debug "hello" foo=expensive()

```

then `expensive()` won’t be called unless debug logging is enabled. But this isn’t really any better than

```julia
if debug
     foo = expensive()
    @debug "hello" foo
end

```

both should be reasonably fast (just checking a bool value or if debug logging is enabled), but are not compile-time checks.

---

<div class="post-metadata">

### Author: ![maxkapur](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/maxkapur/32/21208_2.png) [@maxkapur](https://discourse.julialang.org/u/maxkapur)
#### Post date: [June 25, 2024, 9:49pm UTC](https://discourse.julialang.org/t/env-julia-debug-mymodule-expensive-debug-method-good-practice/116197/8 "2024-06-25T21:49:09Z")

</div>

OK, so the problem (as often) is with my mental model. I think of environment variables as “belonging” to the OS and therefore a kind of constant (in the sense that they shouldn’t change while the Julia process is running, just like any `const`), but as @Sukera says you can enable/disable debug dynamically using built-in methods (or just by setting `ENV["JULIA_DEBUG"]`). Actually, the Julia docs speak to this and mention which environment variables behave like constants and which you can change at runtime: [Environment Variables · The Julia Language](https://docs.julialang.org/en/v1/manual/environment-variables/#JULIA_PKG_SERVER_REGISTRY_PREFERENCE)

> [@Sukera](#):
>
> That’s not really a quantifiable amount - are we talking like a 2x slowdown? 3x? How long does one iteration take?

I haven’t implemented any “expensive” debug logic yet; everything currently in the program is stuff like

```julia
if converged()
    @debug "Converged in $current_iteration iterations"
    return x_optimal
end

```

where the call to `converged()` has to run no matter what. What slows things down are _printing the debug statements themselves_–e.g. the test suite goes from 20 seconds to 80 seconds when it is trying to print all that stuff out. Redirecting `stderr` substantially reduces the runtime when debugging (although not all the way to 20 seconds, because of the file output overhead).

I see the merit in the `const KEEP_STATISTICS = true` approach, but I have to admit that I am partial to my current solution because it single-sources whether or not we are in debug mode, and there is no need to remember to change the variable back before you commit files to version control.

Actually, after reading your suggestion, my first inclination was to write

```julia
const KEEP_STATISTICS = get(ENV, "JULIA_DEBUG", "") == "MyModule")

```

which would let me do `KEEP_STATISTICS && expensive_but_pure_function()` (the function doesn’t even have to be pure in this case, does it?). But I concede that the performance gained by writing this instead of just

```julia
debug() && expensive_function()

```

where

```julia
debug() = get(ENV, "JULIA_DEBUG", "") == "MyModule"

```

as @ericphanson suggests is probably pretty marginal.
