Need advice: tracing function calls non-invasively

General Usage
1

Hi everyone !

I want to record statistics about calls of some functions – the number of calls, runtime, etc. – without modifying the function code (or the code in the function parent module).

I have the following prototype (see example in readme):
sumiya11/TraceIt.jl: Trace function calls with no overhead (github.com)

It does something like this:

using TraceIt

@trace Base.sum; @trace Base.log

reduce(log, map(sum, [[1, 2, 3], [4, 5], [6]]))

printtrace()   # mostly compilation time
Func. ╲ Stat. │ called  mem, b  gctime, s    time, s  time, %
──────────────┼──────────────────────────────────────────────
sum           │      3   12272        0.0  0.0102889  54.94 %
log           │      2  138281        0.0  0.0084373  45.06 %
──────────────┼──────────────────────────────────────────────
Σ             │      5  150553        0.0  0.0187262  100.0 %

Internally, @trace Foo.foo does

primary_world = Base.get_world_counter()
@eval Foo function foo(x)
    #=  record statistics globally  =#
    @info "foo is now traced!"
    return Base.invoke_in_world($primary_world, foo, x)
end

As I understand, this is not ideal. Tracing the functions that are nested will become complicated, and Base.invoke_in_world itself has overhead. (also, I realize that @eval inside of a macro is a bad idea; please bear with me :^D)

Is there a way to implement such tracing that could be better ?

Thank you !
–Alex

1 Like
2

Is it important that you get the exact numbers of function calls?

Otherwise, a sampling profiler could do the job, e.g.
https://www.julia-vscode.org/docs/dev/userguide/profiler/

Since Julia 1.8 that includes also information about GC, dynamic dispatch etc.

Maybe you could use Revise and GitHub - timholy/CodeTracking.jl: It's editing-time, do you know where your methods are?
With the @code_expr you could get the expression for a particular method and then you can modify the method to define your own variant which does the tracing. That way you avoid using different worlds.

(Anyway, nice prototype :slight_smile: )

1 Like
3

I have created a thing called “logging profiler” as a toy example when teaching generated functions. It is implemented here GitHub - pevnak/LoggingProfiler.jl: A profiler that logs beggning and and of each function, but I have touch it for a while and not sure about the state. If it is what you are looking for, I will be happy to help you to make this work. What stopped me to finish the project was that I did not know, how to deal with multi-threadding properly.

1 Like
4

There’s GitHub - carstenbauer/TimerOutputsTracked

2 Likes
5

Is it important that you get the exact numbers of function calls?

I think so. In the future potentially I’d like to also record information about function input values, samplifing profiling won’t be suitable.

Yeah, generating the expression for a method from scratch can be an option, thanks for the idea. CodeTracking.@code_expr is neat !

1 Like
6

thanks for the suggestions @Tomas_Pevny, @goerz !

TimerOutputsTracked is very cool. Though something seems broken on my example:

julia> using TimerOutputsTracked

julia> TimerOutputsTracked.track([Base.sum, Base.log])

julia> f() = reduce(log, map(sum, [[1, 2, 3], [4, 5], [6]]))
f (generic function with 1 method)

julia> @timetracked f()
8.783266944837743

julia> timings_tracked()
 ────────────────────────────────────────────────────────────────────
                            Time                    Allocations      
                   ───────────────────────   ────────────────────────
 Tot / % measured:      5.80s /   0.0%           16.1MiB /   0.0%    

 Section   ncalls     time    %tot     avg     alloc    %tot      avg
 ────────────────────────────────────────────────────────────────────
 ────────────────────────────────────────────────────────────────────

I’ll check out LoggingProfiler.jl, thanks for the pointer

7

Once I understand how these solutions work internally, would be interesting to compare their runtime overhead for tracking a small function

8

They are based on the same principle. The lecture which explains mechanism behind logging profiler is Lecture · Scientific Programming in Julia

Sorry for being brief, i am on ipad

1 Like