Real runtime vs. @btime output

New to Julia
, ,
1

I am going through this ML tutorial on Julia, and I noticed something odd. Output of the following script

using BenchmarkTools
using Flux

@btime f(x) = x^2+1

@btime df(x) = gradient(f,x,nest=true)[1]

is this:

  0.908 ns (0 allocations: 0 bytes)
  0.908 ns (0 allocations: 0 bytes)

But it takes about 12 seconds for the script to run (I used the stopwatch on my phone).

I know little about concepts like runtime, performance, etc., so I may sound too clueless (which I am), but I was wondering whether this is normal.

To reiterate my question:

(1) What is the reason for this behavior?
(2) Can it be improved?

2

@btime takes 5 seconds to run because it will run your function repeatedly for about 5 seconds (to get accurate runtime measurements).

1 Like
3

In addition, if this is the first run after starting Julia, then this is what you’ll see discussed as “TTFP” (time to first plot) because for a long time Plots.jl was particularly bad. But “TTFG” with Zygote is around 12 seconds, sadly. This you should roughly think of as compilation time. Ideally the compiled code would all be stored somewhere to re-use, except the bits that have changed…

1 Like
4

What you are profiling here using @btime are the definitions of the the function/gradient, which is uber fast. You are not even running either.

4 Likes
5

Thanks for your responses. When I removed the @btime and run the script again, it took about 10 seconds. I suspect it is the using statements that cause the delay (I used debug printing), although I do not know why.

6

as @raminammour said, the only code you are running is the time to define the functions f(x) and df(x).

trying this may help illustrate what is happening

$ julia -q
julia> using BenchmarkTools
julia> @btime f() = sleep(2)
julia> @btime f()
7

@lawless-m Oh, I understand that. My point is, even without the benchmarking, the script takes about 10 seconds to run (and not just the first time).

8

That sounds about right for using Flux, and it’s why you want to do as much as possible without restarting Julia

9

@Jeff_Emanuel I see. I suppose using cell blocks (e.g. Jupyter) would solve the issue?

1 Like
10

That would help. For most things, I just use the REPL and Revise.

The problem with trying to script like this is that Julia does not have the chance to cache the compilation. From a cold start. Julia not only has to startup, but it also needs to compile your code again.

For starting out, I might use Revise with includet to start prototyping a function. After I edit the function in a separate file, Revise will reload the changed file for me. The first execution of the changed function will be slower due to recompilation. Subsequent executions will be much faster.

1 Like
11

@mkitti Thanks. I will give that a try.

12

By the way if you want to just time execution as opposed to benchmarking, this is what @time is for. You could also just use Base.time_ns() directly to get the time before and after running something.

There is a bit more going on with @time than some would like.

julia> @macroexpand @time 1
quote
    #= timing.jl:216 =#
    while false
        #= timing.jl:216 =#
    end
    #= timing.jl:217 =#
    local var"#1#stats" = Base.gc_num()
    #= timing.jl:218 =#
    local var"#3#elapsedtime" = Base.time_ns()
    #= timing.jl:219 =#
    local var"#4#compile_elapsedtime" = Base.cumulative_compile_time_ns_before()
    #= timing.jl:220 =#
    local var"#2#val" = $(Expr(:tryfinally, 1, quote
    var"#3#elapsedtime" = Base.time_ns() - var"#3#elapsedtime"
    #= timing.jl:222 =#
    var"#4#compile_elapsedtime" = Base.cumulative_compile_time_ns_after() - var"#4#compile_elapsedtime"
end))
    #= timing.jl:224 =#
    local var"#5#diff" = Base.GC_Diff(Base.gc_num(), var"#1#stats")
    #= timing.jl:225 =#
    Base.time_print(var"#3#elapsedtime", (var"#5#diff").allocd, (var"#5#diff").total_time, Base.gc_alloc_count(var"#5#diff"), var"#4#compile_elapsedtime", true)
    #= timing.jl:226 =#
    var"#2#val"
end
1 Like