Is @time not tracking the full evaluation time?

General Usage
1

If I type something like the following into the 1.5.1 REPL, I find the results very surprising:

julia> @time NTuple{10000, Int}[]
  0.000001 seconds (1 allocation: 80 bytes)
NTuple{10000,Int64}[]

@time reports a very small time, but the REPL hangs for a long period before anything is printed to the terminal if this expression is evaluated for the first time in a new REPL session.

2

It times the evaluation, but doesn’t time how long it takes to print the thing (or compile the functions necessary to print it).

1 Like
3

You can @time @time foo(). The outer time gets closer to user experience.

4

That doesn’t solve this case unfortunately. I see:

julia> @time @time NTuple{10_000, Int}[]
  0.000001 seconds (1 allocation: 80 bytes)
  0.021888 seconds (20.72 k allocations: 1.085 MiB)
NTuple{10000,Int64}[]

But the lag before NTuple{10000,Int64}[] is actually printed is something like 20 seconds.

1 Like
5

This is very helpful. Essentially one needs to do something like,

julia> @time show(stdout, NTuple{10000, Int}[])
NTuple{10000,Int64}[] 53.567039 seconds (1.52 M allocations: 54.703 MiB, 0.02% gc time)

to get a time that matches what a user would expect.

1 Like
6

This is similar to measuring plotting time. Instead of @time plot(rand(3,3)) you do @time (p = plot(rand(3,3)); display(p))

2 Likes
7

Just to give an explanation instead of just examples: the time to build the object is being measured, but as printing was not explicitly called and is done by the REPL after it evaluated @time ... (because a @time ... expression just returns the value of ..., and the REPL prints the value of each line by default), this implicit REPL method call is not being measured.

One way of avoiding this delay would be never compiling such methods, by placing a ; at the end of the line, and suppressing the default printing by the REPL.

4 Likes