Best practice for functions which print debugging info?


#1

I write physics simulations in Julia. Quite often when building the functions that run these, I effectively ‘debug with printf’.

These introspections are useful to keep around after the initial effort to get the code working, but I was wondering what the recommended way to make the code permanent would be. Obviously for production runs of a code, you would want these suppressed, ideally with no overhead cost.

In C, this is often by done by a #define DEBUG 1, and then #ifdefs wrapping the printf functions. The equivalent in Julia would be to have a const VERBOSE=true in the global scope, and then if VERBOSE wrapping the print functions. I guess you could also use a @macro to compact away the if/end boilerplate.

Alternatively, you could add a function foo(...;verbose::Bool=false) keyword argument to the function. This looks to me much nicer, except for the fact that the function signature has this bit tacked on. But are there any hidden performance gremlins? Is there a way to tell Julia in the function signature, that the variable is const, so that the compiler can avoid even touching the verbose printing code unless it’s being used?

I guess this is heading in the direction where a full-blown logging package would be sensible (with differing levels of verbosity, warn/error/info levels), but it is also nice to know what to do on a smaller scale.


#2

You can write a macro that

  1. based on some static constant, adds or doesn’t add a debugging line of code
  2. the debugging line, if it is compiled in, can check a mask to see if it will actually print anything or not
    (or log anything)
  3. for ease of getting formatted output (nice when debugging), I’d recommend my https://github.com/ScottPJones/StringUtils.jl (unregistered) package ;-), it’s a lot easier to use than trying to the @printf working inside of a macro with all the escaping rules.

#3

You can skip the if/end text by using &&, like so:

const DEBUG = false
function test()
       DEBUG && println("out")
       2+2 
 end
julia> @code_llvm test()

define i64 @julia_test_62881() #0 !dbg !5 {
top:
  ret i64 4
}

Since DEBUG is const, the printing doesn’t get compiled into the function and there is no overhead. I’m not sure if there’s any advantage to a macro approach, but this is easier for me since I still haven’t figured out metaprogramming.


#4

There has been some discussion of a logging system in this pull request. For now it lives in a package, Logging.jl.


#5

Thanks for all the suggestions!

For this current project, I’ve found the function foo(...;verbose=true) option the most nice to use.

I haven’t yet checked to see how time is wasted (or looked for any type instability gremlins), but it’s a definite benefit when using these functions in the REPL to have a ‘verbose’ option, much like a unix program on the command line.


#6

Hi

Based on my understanding, if you define the parameter to have a default value, 2 versions of the function gets compiled: One with the default and another with the parameter as a variable. I was hoping that for the case where the value is not specified and it used the default, it would see the default as a constant and optimise like in a slightly modified version of @aaowens ’ example, however it doesn’t seem to be the case:

julia> @inline function test(verbose=false)
       verbose && println("out")
       2+2
       end

test (generic function with 2 methods)

julia> @code_llvm test()

julia> @code_warntype test()
   ...
   unless false goto 8
   ...

julia> @code_warntype test(true)
   ...
    unless verbose::Bool goto 7
   ...

Without the @inline it just sets the value and calls the other version which now takes a value. With @inline macro, it half propagates through into the specific version of the function now generated for the case of test(), but the branch still remains.

To really try to get rid of this, you would need to look at:
http://docs.julialang.org/en/stable/manual/types/#value-types , but also see the warnings related to that in the performance section.


#7

i would probably think toward adding a log receiver parameter of type ::IO. to provide the default nolog behavior, i would create a type

immutable Discard <: IO end

@inline print(::Discard, etc...) = nothing

and also whatever other methods needed, and then having

function myfunc(params; log::IO = Discard())

if your only problem is not polluting production code with log, this does that. the only drawback is that you can’t turn on logging with some global flag, but have to actually pass a parameter, and then pass it further down the line as functions call each other.


#8

Checkout value types. These types can be dispatched on and can maybe help you create special functions that include dubug printouts without overhead.


#9

Indeed the Discard() already exists and is called DevNull.


#10

DevNull does not satisfy “no overhead cost”. i guess because print is not implemented directly.

logtest(a, log::IO) = begin
    print(log, "bef")
    a = 2a
    print(log, "aft")
    a
end

@code_llvm logtest(2, Discard())

; Function Attrs: uwtable
define i64 @julia_logtest_72305(i64) #0 {
top:
  %1 = shl i64 %0, 1
  ret i64 %1
}

@code_llvm logtest(2, DevNull)

; Function Attrs: uwtable
define i64 @julia_logtest_72307(i64) #0 {
top:
  %1 = load %jl_value_t*, %jl_value_t** inttoptr (i64 2233970656 to %jl_value_t**), align 32
  %2 = call i64 @julia_write_72083(%jl_value_t* %1) #1
  %3 = shl i64 %0, 1
  %4 = load %jl_value_t*, %jl_value_t** inttoptr (i64 2233970672 to %jl_value_t**), align 16
  %5 = call i64 @julia_write_72083(%jl_value_t* %4) #1
  ret i64 %3
}

#11

forgot to mention that my implementation example is not quite right, to resolve ambiguity, you also need to define

print(::Discard, ::AbstractString) = nothing


#12

I doubt the overhead is a big deal in any reasonable application, but I looked into it. It turns out that the overhead disappears with a specialization to unsafe_write and a small optimization to write which aids inlining. See https://github.com/JuliaLang/julia/pull/20830 for details.


#13

Say you don’t want to stop your long running process, but you want some temporary verbose output.

With the example below, the penalty seems to be 7%. Those are not type instability gremlins, just added functionalty gremlins.


module globalslowdown
export  changeable, preset, setverbose
global verbose = false
const presetverbose = false
const loops = 80000000
function changeable()
	global verbose
	a=1.0
	for i = 1:loops
		a=sin(a)	
		verbose  && isinteger(i/10000000) && print(a," ")
	end
end
function preset()
	a=1.0
	for i = 1:loops
		a=sin(a)	
		presetverbose  && isinteger(i/10000000) && print(a," ")
	end
end
setverbose(v::Bool) = global verbose = v
end # module

@time globalslowdown.changeable()
@time globalslowdown.changeable()
@time globalslowdown.preset()
@time globalslowdown.preset()
globalslowdown.setverbose(true)
@time globalslowdown.changeable()
println()
@time globalslowdown.changeable()


#14

Do any of the logging packages allow for a message to be printed only once? In my use case I want some functions to announce which method was called and for what parameters, but these functions are called thousands of times. I only want to log the first call.

Something like

function test(x)
@debug_once "$x"
...
end

This macro could define a const d1 = Ref(false) and then update the value if the debug is logged. Maybe this would be a performance issue, but it seems to be the same concept as the deprecation warnings and I don’t think they cause much issue.