Measuring time in Julia and the behavior of function calling

Question

I have two questions and I would write them at the bottom of this article.

Background

I measured time using TimerOutputs.jl package and I found incomprehensible behavior.

I wrote the function named f and measured the following 4 sections:whole in,i section,x section,whole out.

The code and the result is following:

[input 1]

using TimerOutputs
const to = TimerOutput()

f = function()
    @timeit to "whole in" begin
        a = [];
    
        @timeit to "i section" begin
            for i in 1:1000
                push!(a,randn(5,5))
            end
        end
    
        @timeit to "x section" begin
            for x in 1:1000
                push!(a,randn(5,5) .+ x )
            end
        end
    end
end

@timeit to "whole out" f()

show(to)

[output 1]

 ────────────────────────────────────────────────────────────────────────
                                 Time                   Allocations      
                         ──────────────────────   ───────────────────────
    Tot / % measured:         106ms / 95.8%           12.0MiB / 99.4%    

 Section         ncalls     time   %tot     avg     alloc   %tot      avg
 ────────────────────────────────────────────────────────────────────────
 whole out            1    102ms   100%   102ms   11.9MiB  100%   11.9MiB
   whole in           1    310μs  0.30%   310μs    878KiB  7.18%   878KiB
     x section        1    155μs  0.15%   155μs    579KiB  4.73%   579KiB
     i section        1    151μs  0.15%   151μs    298KiB  2.43%   298KiB
 ────────────────────────────────────────────────────────────────────────

[input 2]

TimerOutputs.time(to["whole out"])/TimerOutputs.time(to["whole out"]["whole in"])

[output 2]

328.0928134063809

Questions

Q1:

Why is the time for running whole out 328 times bigger than that for running whole in?

I guess this difference comes from the mechanics of how CPU and Memory behaves when a function is called, but I don't have any knowledge. I want to make it clear.

Q2:

I want to measure time for running f and use the result (output of @timeit for whole out) inside the f. How can I do this?

Any information would be appreciated.

Answer 1

Q1: You're likely timing the precompilation of f. Try to run f once before or reset the timer:

julia> reset_timer!(to) ;

julia> @timeit to "whole out" f()

julia> show(to)
 ────────────────────────────────────────────────────────────────────────
                                 Time                   Allocations
                         ──────────────────────   ───────────────────────
    Tot / % measured:         4.02s / 0.02%           0.99MiB / 86.4%

 Section         ncalls     time   %tot     avg     alloc   %tot      avg
 ────────────────────────────────────────────────────────────────────────
 whole out            1    856μs   100%   856μs    879KiB  100%    879KiB
   whole in           1    842μs  98.4%   842μs    878KiB  100%    878KiB
     x section        1    515μs  60.2%   515μs    579KiB  65.8%   579KiB
     i section        1    321μs  37.6%   321μs    298KiB  33.9%   298KiB
 ────────────────────────────────────────────────────────────────────────

Q2: I'm not sure what you mean. Maybe it would be best to ask that again in a separate question with corresponding copy-pastable code of what you've tried so far.