allow attaching the `@tracepoint` macro directly to a function definition #13

KristofferC · 2023-05-16T13:48:30Z

Fixes #12

It is a common use case to time the full execution of a function. It is a bit awkward to write:

function f(x)
    @tracepoint "f" begin
        ...
    end
end

So this allows one to write

@tracepoint f(x)
    ...
end

instead. Running Tracy on the added test code (given here for convenience):

@tracepoint "zone f" f(x) = x^2
foreach(n -> f(n), 1:10)
@tracepoint function g(x)
    x^2
end
foreach(n -> g(n), 1:20)
@tracepoint "hxT" function h(x::T) where {T}
    T(x^2)
end
foreach(n -> h(n), 1:30)
i = @tracepoint x->x^2
foreach(n -> i(n), 1:40)

gives:

Regarding the new dependency, I think it is warranted. The AST for function definitions is quite rich and handling all the cases is not something that is so easy. The easiest way to do this without the dependency would be to copy paste the used parts from ExprTools.jl. The dependency is also pretty light weight:

julia> @time using ExprTools
  0.004472 seconds

topolarity · 2023-05-17T14:36:29Z

Does this PR have good lineinfo, or is that left for future work?

KristofferC · 2023-05-17T14:46:12Z

Does this PR have good lineinfo, or is that left for future work?

I did not notice the same problem as in TimerOutputs.jl. Here is Tracy with this PR:

In [1]: using Tracy

In [2]: function foo(::Float64) end
foo (generic function with 1 method)

In [3]: @tracepoint "foo" foo(1)
ERROR: MethodError: no method matching foo(::Int64)

Closest candidates are:
  foo(::Float64)
   @ Main REPL[2]:1

Stacktrace:
 [1] top-level scope
   @ ~/JuliaPkgs/tracy.jl/src/tracepoint.jl:98 [inlined]
 [2] top-level scope
   @ ./REPL[3]:0
 [3] top-level scope
   @ ~/.julia/juliaup/julia-1.9.0+0.x64.linux.gnu/share/julia/stdlib/v1.9/REPL/src/REPL.jl:1416

And the [3] frame points to the actual place where we errored. In KristofferC/TimerOutputs.jl#77 (comment) the stacktrace had no information about the original location at all.

topolarity · 2023-05-17T14:53:57Z

Here's a case where the function is incorrectly reported as being defined in Tracy.jl:

julia> using Tracy

julia> @tracepoint function foo(::Float64) error("test") end
foo (generic function with 1 method)

julia> foo(1.5)
ERROR: test
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] foo(#unused#::Float64)
   @ Main ~/repos/Tracy.jl/src/tracepoint.jl:98
 [3] top-level scope
   @ REPL[3]:1

No trace of REPL[2], where the function is actually defined

KristofferC · 2023-05-17T14:58:50Z

What Julia version / OS is this? I get:

julia> foo(1.5)
ERROR: test
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] macro expansion
   @ ./REPL[3]:1 [inlined]
 [3] foo(#unused#::Float64)
   @ Main ~/JuliaPkgs/tracy.jl/src/tracepoint.jl:98
 [4] top-level scope
   @ REPL[4]:1

topolarity · 2023-05-17T15:25:14Z

That was 1.8, looks like 1.9 added the macro expansion to the trace, which is very nice.

Still I think we should should shoot for @macroexpand @tracepoint function foo(::Float64) showing no references to Tracy.jl

KristofferC · 2023-05-17T15:26:56Z

Still I think we should should shoot for @macroexpand @tracepoint function foo(::Float64) showing no references to Tracy.jl

Sounds like a good idea.

…tion It is a common use case to time the full execution of a function. It is a bit awkward to write: ``` function f(x) @Tracepoint "f" begin ... end end ``` So this allows you to write ``` @Tracepoint f(x) ... end ``` instead.

This adds `replace_linenums!` which rewrites the line/file info in any "new" parts of the expression that are added by @Tracepoint and changes them to appear as if they were written at the macro instantiation site. With this change, the stack traces no longer mention macro expansion: ``` julia> @Tracepoint function foo(x::Float64) if x == 1.5 error("test") end error("foo") end foo (generic function with 1 method) julia> foo(1.0) ERROR: foo Stacktrace: [1] error(s::String) @ Base ./error.jl:35 [2] foo(x::Float64) @ Main ./REPL[8]:5 [3] top-level scope @ REPL[9]:1 julia> foo(1.5) ERROR: test Stacktrace: [1] error(s::String) @ Base ./error.jl:35 [2] foo(x::Float64) @ Main ./REPL[8]:3 [3] top-level scope @ REPL[10]:1 ```

topolarity · 2023-05-19T23:16:01Z

@KristofferC Feel free to take over from here 👍 - I think this should be good to go w.r.t. the source info

KristofferC · 2023-05-22T08:14:45Z

Feel free to take over from here +1 - I think this should be good to go w.r.t. the source info

Do I understand correctly that we do not get a reference to the Tracy.jl file even if we are now erroring in Tracy.jl code? As a test I did:

diff --git a/src/tracepoint.jl b/src/tracepoint.jl
index 36b3159..0537a2a 100644
--- a/src/tracepoint.jl
+++ b/src/tracepoint.jl
@@ -123,6 +123,7 @@ function _tracepoint(name::Union{String, Nothing}, func::Union{String, Nothing},
             if $srcloc.file == C_NULL
                 initialize!($srcloc)
             end
+            error()
             local ctx = @ccall libtracy.___tracy_emit_zone_begin(pointer_from_objref($srcloc)::Ptr{Cvoid},
                                                                  $srcloc.enabled::Cint)::TracyZoneContext
         end

which gives me

In [3]: @tracepoint "foo" sleep(0.1)
ERROR: 
Stacktrace:
 [1] error()
   @ Base ./error.jl:44
 [2] top-level scope
   @ ./REPL[3]:1
 [3] top-level scope
   @ ~/.julia/juliaup/julia-1.9.0+0.x64.linux.gnu/share/julia/stdlib/v1.9/REPL/src/REPL.jl:1416

This doesn't seem great, or? There is no way to know where the error actually happens in this case. I feel that we should still have line numbers that point to the Tracy code for the actual code that comes from us. But the function definition + the code from the user should have their original line numbers.

It feels like the only thing we need to fix is the line info of the function definition?

KristofferC · 2023-05-22T08:42:14Z

I would claim something like 4a091fb works better.

We still get the correct info for the method:

julia> @tracepoint function foo(::Float64) error("test") end
foo (generic function with 1 method)

julia> foo(1.5)
ERROR: test
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] foo(#unused#::Float64)
   @ Main ./REPL[2]:1
 [3] top-level scope
   @ REPL[3]:1

But if we error inside the Tracy code (here by artificially inserting an error call):

julia> @tracepoint function foo(::Float64) error("test") end
foo (generic function with 1 method)

julia> foo(1.5)
ERROR: 
Stacktrace:
 [1] error()
   @ Base ./error.jl:44
 [2] macro expansion
   @ ~/JuliaPkgs/tracy.jl/src/tracepoint.jl:100 [inlined]
 [3] foo(#unused#::Float64)
   @ Main ./REPL[2]:1
 [4] top-level scope
   @ REPL[3]:1

we get a stackframe pointing to the actual location where the error happened.

topolarity · 2023-05-22T12:15:50Z

Ooh, I didn't know the first source location in the function block is special like that.

That's much better than the brute force approach, let's do it 👍

Here's a deliberate ccall error that gives a great backtrace with your approach:

julia> foo(1.0)
ERROR: could not load symbol "___tracy_emit_zone_end2":
/home/topolarity/.julia/artifacts/479490205d4946c1957f89ae999083163ff32116/lib/libTracyClient.so: undefined symbol: ___tracy_emit_zone_end2
Stacktrace:
 [1] macro expansion
   @ ~/repos/Tracy.jl/src/tracepoint.jl:108 [inlined]
 [2] foo(x::Float64)
   @ Main ./REPL[3]:5
 [3] top-level scope
   @ REPL[4]:1

This will help make sure our LineNumberNode-rewriting doesn't break in the future

This is technically redundant with the `all_names_expected` check above, but that separate check may fall out-of-sync or have different typos than in the main if-else tree so it's nice to just catch this branch.

topolarity

This is a very good-looking change at this point (and a fun collab hah)

KristofferC · 2023-05-22T13:12:52Z

(and a fun collab hah)

Parallel work!

KristofferC requested a review from topolarity May 16, 2023 13:48

KristofferC force-pushed the kc/func_def branch 2 times, most recently from 0ee0f7a to 75a77f0 Compare May 17, 2023 13:53

KristofferC force-pushed the kc/func_def branch from 75a77f0 to 799a1d6 Compare May 19, 2023 07:16

KristofferC added 2 commits May 22, 2023 08:20

replace line info for function definition

9b18621

fix passing along name and be more careful with tests

444fa86

KristofferC force-pushed the kc/func_def branch from 90bf99b to 444fa86 Compare May 22, 2023 12:52

topolarity added 2 commits May 22, 2023 08:55

Check stacktrace in @tracepoint-wrapped function tests

647b602

This will help make sure our LineNumberNode-rewriting doesn't break in the future

Ensure zone name matching is exhaustive in tests

259e699

This is technically redundant with the `all_names_expected` check above, but that separate check may fall out-of-sync or have different typos than in the main if-else tree so it's nice to just catch this branch.

topolarity approved these changes May 22, 2023

View reviewed changes

KristofferC merged commit 05ec32c into main May 22, 2023

KristofferC deleted the kc/func_def branch May 22, 2023 13:13

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

allow attaching the `@tracepoint` macro directly to a function definition #13

allow attaching the `@tracepoint` macro directly to a function definition #13

KristofferC commented May 16, 2023 •

edited

Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023 •

edited

Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023 •

edited

Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023

topolarity commented May 19, 2023

KristofferC commented May 22, 2023 •

edited

Loading

KristofferC commented May 22, 2023 •

edited

Loading

topolarity commented May 22, 2023

topolarity left a comment

KristofferC commented May 22, 2023

allow attaching the @tracepoint macro directly to a function definition #13

allow attaching the @tracepoint macro directly to a function definition #13

Conversation

KristofferC commented May 16, 2023 • edited Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023 • edited Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023 • edited Loading

topolarity commented May 17, 2023

KristofferC commented May 17, 2023

topolarity commented May 19, 2023

KristofferC commented May 22, 2023 • edited Loading

KristofferC commented May 22, 2023 • edited Loading

topolarity commented May 22, 2023

topolarity left a comment

Choose a reason for hiding this comment

KristofferC commented May 22, 2023

allow attaching the `@tracepoint` macro directly to a function definition #13

allow attaching the `@tracepoint` macro directly to a function definition #13

KristofferC commented May 16, 2023 •

edited

Loading

KristofferC commented May 17, 2023 •

edited

Loading

KristofferC commented May 17, 2023 •

edited

Loading

KristofferC commented May 22, 2023 •

edited

Loading

KristofferC commented May 22, 2023 •

edited

Loading