# Real runtime vs. @btime output

**URL:** <https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001>\
**Category:** New to Julia\
**Tags:** question, performance, ttfp\
**Created:** [January 21, 2022, 7:38pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001 "2022-01-21T19:38:01Z")\
**Posts on this page:** 12\
**Page:** 1

<div class="post-metadata">

**Author:** ![jafar.isbarov](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jafar.isbarov/32/36130_2.png) [@jafar.isbarov](https://discourse.julialang.org/u/jafar.isbarov)\
**Post date:** [January 21, 2022, 7:38pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/1 "2022-01-21T19:38:01Z")

</div>

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

```julia
using BenchmarkTools
using Flux

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

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

```

is this:

```julia
  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?

---

<div class="post-metadata">

**Author:** ![Oscar\_Smith](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/oscar_smith/32/25343_2.png) [@Oscar\_Smith](https://discourse.julialang.org/u/Oscar_Smith)\
**Post date:** [January 21, 2022, 8:00pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/2 "2022-01-21T20:00:49Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![mcabbott](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mcabbott/32/6603_2.png) [@mcabbott](https://discourse.julialang.org/u/mcabbott)\
**Post date:** [January 21, 2022, 8:06pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/3 "2022-01-21T20:06:15Z")

</div>

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…

---

<div class="post-metadata">

**Author:** ![raminammour](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/raminammour/32/13572_2.png) [@raminammour](https://discourse.julialang.org/u/raminammour)\
**Post date:** [January 21, 2022, 8:25pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/4 "2022-01-21T20:25:47Z")

</div>

> [@jafar.isbarov](#):
>
> ```julia
> @btime f(x) = x^2+1
> 
> @btime df(x) = gradient(f,x,nest=true)[1]
> 
> ```

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.

---

<div class="post-metadata">

**Author:** ![jafar.isbarov](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jafar.isbarov/32/36130_2.png) [@jafar.isbarov](https://discourse.julialang.org/u/jafar.isbarov)\
**Post date:** [January 21, 2022, 8:37pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/5 "2022-01-21T20:37:25Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![lawless-m](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/lawless-m/32/30869_2.png) [@lawless-m](https://discourse.julialang.org/u/lawless-m)\
**Post date:** [January 22, 2022, 2:37pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/6 "2022-01-22T14:37:27Z")

</div>

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
$ julia -q
julia> using BenchmarkTools
julia> @btime f() = sleep(2)
julia> @btime f()

```

---

<div class="post-metadata">

**Author:** ![jafar.isbarov](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jafar.isbarov/32/36130_2.png) [@jafar.isbarov](https://discourse.julialang.org/u/jafar.isbarov)\
**Post date:** [January 22, 2022, 8:29pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/7 "2022-01-22T20:29:25Z")

</div>

@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).

---

<div class="post-metadata">

**Author:** ![Jeff\_Emanuel](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jeff_emanuel/32/15440_2.png) [@Jeff\_Emanuel](https://discourse.julialang.org/u/Jeff_Emanuel)\
**Post date:** [January 22, 2022, 8:54pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/8 "2022-01-22T20:54:47Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![jafar.isbarov](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jafar.isbarov/32/36130_2.png) [@jafar.isbarov](https://discourse.julialang.org/u/jafar.isbarov)\
**Post date:** [January 22, 2022, 8:57pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/9 "2022-01-22T20:57:07Z")

</div>

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

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [January 22, 2022, 11:42pm UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/10 "2022-01-22T23:42:45Z")

</div>

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.

---

<div class="post-metadata">

**Author:** ![jafar.isbarov](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/jafar.isbarov/32/36130_2.png) [@jafar.isbarov](https://discourse.julialang.org/u/jafar.isbarov)\
**Post date:** [January 23, 2022, 8:57am UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/11 "2022-01-23T08:57:34Z")

</div>

@mkitti Thanks. I will give that a try.

---

<div class="post-metadata">

**Author:** ![mkitti](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/mkitti/32/12459_2.png) [@mkitti](https://discourse.julialang.org/u/mkitti)\
**Post date:** [January 23, 2022, 10:14am UTC](https://discourse.julialang.org/t/real-runtime-vs-btime-output/75001/12 "2022-01-23T10:14:34Z")

</div>

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
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

```