# Why sum of the measured times of each function is not equal to the total run time?

**URL:** <https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261>\
**Category:** General Usage\
**Created:** [August 20, 2020, 10:24am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261 "2020-08-20T10:24:46Z")\
**Posts on this page:** 20\
**Page:** 1

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 10:24am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/1 "2020-08-20T10:24:46Z")

</div>

Here is the code. I’m just providing the code to executed and observe the issue that I am talking about.

```julia
A= sparse([0 1 0 1;1 0 1 0;0 1 0 0;1 0 0 0])

sm_vec = rand(4, 5)

k = 3

function Filter(sm_vec, k, A)
    @time begin
    N = size(sm_vec, 2);

    sz = size(A, 1)

    V = zeros(size(A, 1), N);

    val = sum(A, dims = 1) .^ (-.5);

    I2 = 1:sz

    D = sparse(I2, I2, sparsevec(val))

    A = D * A * D

    on = ones(Int, size(A, 1))

    for iter in 1:N

        sm = view(sm_vec, :, iter)

        for loop in 1:k

            sm = A * sm

        end

        sm_ot = sm - ((dot(sm, on) / dot(on, on)) * on)

        sm_norm = sm_ot ./ norm(sm_ot);

        V[: , iter] = sm_norm;
    end
end#time
    return V

end #end of function

@time result = Filter(sm_vec, k, A)

0.000012 seconds (37 allocations: 3.531 KiB)
0.000824 seconds (149 allocations: 8.547 KiB)

```

Why the measured times are not the same? The purpose of this question is that I am trying to speed up the code but I need to figure out which part takes the most time. I put @time begin…end in several places throughout the code but surprisingly, I noticed that the sum of those measured times inside the function is not equal to the the measure time of calling the function.

---

<div class="post-metadata">

**Author:** ![kristoffer.carlsson](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/kristoffer.carlsson/32/22_2.png) [@kristoffer.carlsson](https://discourse.julialang.org/u/kristoffer.carlsson)\
**Post date:** [August 20, 2020, 10:37am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/2 "2020-08-20T10:37:01Z")

</div>

Are you measuring compilation time?

---

<div class="post-metadata">

**Author:** ![DNF](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/dnf/32/10191_2.png) [@DNF](https://discourse.julialang.org/u/DNF)\
**Post date:** [August 20, 2020, 11:37am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/3 "2020-08-20T11:37:31Z")

</div>

Can you show how you are measuring the timings? Can you include the benchmarking code?

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 3:09pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/4 "2020-08-20T15:09:28Z")

</div>

I just edited the post to show how I measure the time. I know that tic-toc is not the best way but I’m just trying to find out which part of my code is slow so I can work on the speed up.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 3:10pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/5 "2020-08-20T15:10:16Z")

</div>

I use tic-toc to measure time. I guess it includes the compilation time as well.

---

<div class="post-metadata">

**Author:** ![rdeits](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/rdeits/32/286_2.png) [@rdeits](https://discourse.julialang.org/u/rdeits)\
**Post date:** [August 20, 2020, 3:12pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/6 "2020-08-20T15:12:33Z")

</div>

`tick` and `tock` are not part of base Julia. Where are you getting them from?

In any case, if they work anything like `tic` and `toc` in Matlab, then `tock` gives the time since the last `tick` call. When your final call to `tock` happens outside of the loop, when was the last `tick` call? Hint: It’s not the `tick` before the loop.

Don’t use `tick/tock` to measure timing. It’s not a good idea in Matlab because of exactly this problem, and there are better tools for this in Julia like `@elapsed`.

---

<div class="post-metadata">

**Author:** ![pixel27](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/pixel27/32/8902_2.png) [@pixel27](https://discourse.julialang.org/u/pixel27)\
**Post date:** [August 20, 2020, 5:43pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/7 "2020-08-20T17:43:19Z")

</div>

```julia
function f1()
    sleep(1)
    return 1
end

function f2()
    sleep(2)
    return 2
end

function f3()
    sleep(3)
    return 3
end

function test(N)
    local f1Total = 0
    local f2Total = 0
    local f3Total = 0

    local started = time_ns()
    for loop = 1:N
        local s = time_ns()
        a = f1()
        local t = time_ns() - s
        f1Total += t
        # println("F1: $t ns")

        local s = time_ns()
        b = f2()
        local t = time_ns() - s
        f2Total += t
        # println("F2: $t ns")

        local s = time_ns()
        c = f3()
        local t = time_ns() - s
        f3Total += t
        # println("F3: $t ns")
    end
    local total = time_ns() - started
    local overhead = total - f1Total - f2Total - f3Total

    println("F1 Total: ($N): $f1Total ns")
    println("F2 Total: ($N): $f2Total ns")
    println("F3 Total: ($N): $f3Total ns")
    println("Total: ($N): $total ns")
    println("Overhead: ($N): $overhead ns")
end

```

On my machine I’m seeing around 3000ns to 4000ns of overhead which would be the calls to `time_ns()` along with the math (addition/subtraction) to track the times. BTW `println` if fairly “expensive” so if you are printing the time inside the loop that will add more overhead to the loop. On my machine uncommenting the `println`(s) inside the loop boost the overhead to a bit over 2 million nano seconds.

Here are my results without println in the loops:

```julia
F1 Total: (10): 10021025897 ns
F2 Total: (10): 20017349021 ns
F3 Total: (10): 30031619654 ns
Total: (10): 60069998184 ns
Overhead: (10): 3612 ns

```

To the others on this thread there appears to be a package named:  
[https://github.com/schmrlng/CPUTime.jl](https://github.com/schmrlng/CPUTime.jl)  
That has the tic()/tock() functions…

---

<div class="post-metadata">

**Author:** ![Henrique\_Becker](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/henrique_becker/32/15443_2.png) [@Henrique\_Becker](https://discourse.julialang.org/u/Henrique_Becker)\
**Post date:** [August 20, 2020, 6:57pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/8 "2020-08-20T18:57:21Z")

</div>

Just to check, you get those values in the second run, right?

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 9:00pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/9 "2020-08-20T21:00:47Z")

</div>

I think that the problem is not using tick() and tock() since I get the same results using other methods like @time. I still see a big difference in sum of the functions (or chunk of code) compared to the total run time of function. Basically, when I measure the elapsed time of code inside the function, it is a lot less (\>2x) than the total run time.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 9:13pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/10 "2020-08-20T21:13:02Z")

</div>

Even if I don’t add anything extra, I still get higher run time compared to just measuring each chunk of code.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 9:13pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/11 "2020-08-20T21:13:38Z")

</div>

Yes.

---

<div class="post-metadata">

**Author:** ![yuyichao](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/yuyichao/32/20_2.png) [@yuyichao](https://discourse.julialang.org/u/yuyichao)\
**Post date:** [August 20, 2020, 9:35pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/12 "2020-08-20T21:35:23Z")

</div>

It seems that you still didn’t answer anything about the overhead. What’s your N.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 20, 2020, 9:52pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/13 "2020-08-20T21:52:00Z")

</div>

N is small (e.g 5). In each iteration I multiply a sparse matrix into a vector three times (updating the vector each time). How this could be related to my question though? What do you exactly mean by overhead?

---

<div class="post-metadata">

**Author:** ![yuyichao](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/yuyichao/32/20_2.png) [@yuyichao](https://discourse.julialang.org/u/yuyichao)\
**Post date:** [August 20, 2020, 10:19pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/14 "2020-08-20T22:19:27Z")

</div>

It is already described in detail above.

> [@pixel27](#):
>
> On my machine I’m seeing around 3000ns to 4000ns of overhead which would be the calls to `time_ns()` along with the math (addition/subtraction) to track the times. BTW `println` if fairly “expensive” so if you are printing the time inside the loop that will add more overhead to the loop. On my machine uncommenting the `println` (s) inside the loop boost the overhead to a bit over 2 million nano seconds.

There’s nothing magical there. The only things that `@time` does is to get the current time. You can just print out the 32 time points and see where’s the missing time. If you want others to help you figure out the exact cause, you would have to give much more details to your code so that others can actually run it.

---

<div class="post-metadata">

**Author:** ![Juan](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/juan/32/7657_2.png) [@Juan](https://discourse.julialang.org/u/Juan)\
**Post date:** [August 20, 2020, 10:58pm UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/15 "2020-08-20T22:58:12Z")

</div>

Maybe because the functions _tick()_ and _tock()_ themselves also last some time.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 21, 2020, 12:04am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/16 "2020-08-21T00:04:30Z")

</div>

I just provided the code which can be executed to see the problem.

---

<div class="post-metadata">

**Author:** ![yuyichao](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/yuyichao/32/20_2.png) [@yuyichao](https://discourse.julialang.org/u/yuyichao)\
**Post date:** [August 21, 2020, 12:10am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/17 "2020-08-21T00:10:18Z")

</div>

Errrr, you have a whole loop after the inner time measurement. Why do you expect that to cost no time?

Top post was edited so this doesn’t make sense anymore. The original code I was replying to was.

```julia

function Filter(sm_vec, k, A)
    @time begin
    N = size(sm_vec, 2);

    sz = size(A, 1)

    V = zeros(size(A, 1), N);

    val = sum(A, dims = 1) .^ (-.5);

    I2 = 1:sz

    D = sparse(I2, I2, sparsevec(val))

    A = D * A * D

    on = ones(Int, size(A, 1))

end#time

    for iter in 1:N

        sm = view(sm_vec, :, iter)

        for loop in 1:k

            sm = A * sm

        end

        sm_ot = sm - ((dot(sm, on) / dot(on, on)) * on)

        sm_norm = sm_ot ./ norm(sm_ot);

        V[: , iter] = sm_norm;
    end

    return V

end #end of function

@time result = Filter(sm_vec, k, A)

```

Which have the inner time measurement not enclosing the whole function.

---

<div class="post-metadata">

**Author:** ![yuyichao](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/yuyichao/32/20_2.png) [@yuyichao](https://discourse.julialang.org/u/yuyichao)\
**Post date:** [August 21, 2020, 12:18am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/18 "2020-08-21T00:18:37Z")

</div>

Also, the time here is no where close to 1-2 seconds in about 5 loops so a lot of the overhead as explained above are going to be important. If the 1-2 second time measurement does not correspond to the 5 loops, please provide more detail about the relevant information for the same setup rather than answering different questions based on different experiments without explicitly mentioning the difference. There’s no way for others to figure out…

If you are not just complaining about 0.000824 being very different from 0.000012, please explain in full detail what you are actually talking about instead.

Also, as an aside, it’ll be better if you post update in comment or at least keep the old version instead of just editing the top post like this… now it’s impossible for people reading this thread to make sense of a lot of the previous posts from other people without looking at the edit history of yours…

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 21, 2020, 12:31am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/19 "2020-08-21T00:31:37Z")

</div>

I edited the post. The results are for the current version.

---

<div class="post-metadata">

**Author:** ![Nova](https://avatars.discourse-cdn.com/v4/letter/n/c5a1d2/32.png) [@Nova](https://discourse.julialang.org/u/Nova)\
**Post date:** [August 21, 2020, 12:36am UTC](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261/20 "2020-08-21T00:36:54Z")

</div>

Sure, I will keep updating in future instead of editing the post. This was actually my first post. My exact question is why there is difference between 0.000824 and 0.000012?

[Next page](https://discourse.julialang.org/t/why-sum-of-the-measured-times-of-each-function-is-not-equal-to-the-total-run-time/45261.md?page=2)