Here is the code. I’m just providing the code to executed and observe the issue that I am talking about.
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.
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.
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.
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.
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.
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?
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.
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.
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.
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…
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?