How to "fix" stacktraces for macros?

General Usage
1

When I time a function using TimerOutputs.jl’s @timeit, I get broken stacktraces when there is a compilation error inside the called function.

Example:

@timeit to "mesh loading" mesh = load_mesh(restart_filename)

yields something like

Loading mesh... ERROR: LoadError: MethodError: no method matching Val{1}(::Int64)
Closest candidates are:
  Val{1}() where x at essentials.jl:693
Stacktrace:
 [1] load_mesh(::String) at /home/user/.julia/packages/TimerOutputs/7Id5J/src/TimerOutput.jl:214
 [2] macro expansion at /home/user/.julia/packages/TimerOutputs/7Id5J/src/TimerOutput.jl:214 [inlined]
 [3] run() at /home/user/code/src/main.jl:32
...

That is, while [3] still points to the correct source location, [2] and [1] return useless information, making errors hard to track down unless I remove the @timeit macro (which may be non-trivial if there are nested macro uses). What can I do to get proper error information from within macros? I found this seemingly related issue, but I guess it does not apply to my case: Corrupt linenumber in stacktraces for functions with macros · Issue #28618 · JuliaLang/julia · GitHub

1 Like
2

@kristoffer.carlsson Sorry to ping you directly, but would you be able to give me some pointers in which direction to look for more answers?

3

Instead of :(...) you can try @q(...) from MacroTools.

help?> MacroTools.@q
  @q [expression]

  Like the quote keyword but doesn't insert line numbers from the construction
  site. e.g. compare @q begin end with quote end. Line numbers of interpolated
  expressions are preserverd.
4

Macros like @inline doesn’t mess with the Stacktrace info so maybe it is possible to look there how it should be done?

5

I will see if I can change the macro to fix this.

6

I checked the @inline macro, but it is so stupidly simple that it is hard to tell for me where the issue in the @timeit macro arises.

Compare (julia/expr.jl at 2d5741174ce3e6a394010d2e470e4269ca54607f · JuliaLang/julia · GitHub):

macro inline(ex)
    esc(isa(ex, Expr) ? pushmeta!(ex, :inline) : ex)
end

to TimerOutputs.jl/TimerOutput.jl at master · KristofferC/TimerOutputs.jl · GitHub (not included due to excessive length)

If there is any way I can help, though, please let me know. We are using @timeit to both identify and optimize hotspots, and the combination of run time and allocations is just perfect for that.

7

Well, the devil in the pushmeta! I would guess, heh.

8

The core problem is not really the example here but rather that you probably have

@timeit function load_mesh(...)
    ...
end

which creates a new function with the timings enabled from within TimerOutputs.jl and ruins the stacktrace.

9

No, it actually is my example (although your example might have similar issues :wink: ). Here’s an MWE:

mwe.jl:

using TimerOutputs

function foo(::Float64) end

@timeit "foo" foo(1)

Running julia mwe.jl then yields

ERROR: LoadError: MethodError: no method matching foo(::Int64)
Closest candidates are:
  foo(::Float64) at /path/to/mwe.jl:3
Stacktrace:
 [1] top-level scope at /home/user/.julia/packages/TimerOutputs/7Id5J/src/TimerOutput.jl:214
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] exec_options(::Base.JLOptions) at ./client.jl:287
 [6] _start() at ./client.jl:460
in expression starting at /path/to/mwe.jl:5

However, while constructing this MWE, I came across another (probably unrelated error) that I have encountered before: If I change the first line of mwe.jl to using TimerOutputs: @timeit, I get the following error:

ERROR: LoadError: UndefVarError: TimerOutputs not defined
Stacktrace:
 [1] top-level scope at /home/user/.julia/packages/TimerOutputs/7Id5J/src/TimerOutput.jl:210
 [2] include at ./boot.jl:328 [inlined]
 [3] include_relative(::Module, ::String) at ./loading.jl:1105
 [4] include(::Module, ::String) at ./Base.jl:31
 [5] exec_options(::Base.JLOptions) at ./client.jl:287
 [6] _start() at ./client.jl:460
in expression starting at /path/to/mwe.jl:5

I am not an expert in Julia, but from intuition I feel that if I make available all symbols that I am using in my user code through using/import, I should not get any errors about undefined symbols.

10

Yeah that looks like a bug

11

If it helps, I could open two separate issues for it?

12

Sure

13

Broken stacktraces: Compilation errors in timed function calls yield "broken" stacktraces · Issue #77 · KristofferC/TimerOutputs.jl · GitHub
UndefVarError for selective imports: UndefVarError for TimerOutput when selectively using symbols · Issue #78 · KristofferC/TimerOutputs.jl · GitHub

Thanks for providing the extremely helpful TimerOutputs.jl package as well as taking an interest in these issues!

1 Like