@time macro can have huge error

[ufechner7]

Steps to reproduce:

mkdir temp
cd temp
git clone https://github.com/ufechner7/KiteViewer.git
cd KiteViewer
julia --project
using Pkg
Pkg.instantiate()
exit()
./create_sys_image.sh

And then execute the test:

./runjulia
include("test/time_bug.jl")

Result:

# [ Info:  started timer at: 2021-02-20T13:58:23.814
#   0.668130 seconds (933.81 k allocations: 55.527 MiB, 1.70% gc time, 98.76% compilation time)
# [ Info:          2.896614005s: 2 seconds, 896 milliseconds

# julia> 2.8966/0.668
# 4.336227544910179

# @time reports 0.67 seconds, while the real execution time incl. compilation is more like 2.90 seconds

This means that the @time macro reports a time that is more than a factor of four lower then the real execution time.

The same problem happens without using a custom sysimage, but the relative error is smaller (8s vs 5s).
This are times that I can measure with my stopwatch, so I can confirm that the time reported by
tick and tock is much closer to the real time than the time reported by the @time macro.

I would consider any error of more then 10% as a bug, in particular if the measured time is above 1s.

Any comment?

[DilumAluthge]

@IanButterworth

[IanButterworth]

Have you checked whether the same happens in 1.5?

If it does, it could be that execution time is dominated by interpretation, given @time's result doesn't include interpretation

[ufechner7]

Well, measuring the time is simple: Record the start time and the end time and calculate the difference. If the @time macro is not doing that, then it has a major design flaw that should be fixed. Just my two cents...

[IanButterworth]

Yeah, it's a fair point. There has been some efforts to fix it #37938

It's not clear if your issue is specific to 1.6 though, and it's still just a guess that missing interpreter top level compilation time is the cause.
Perhaps an easier thing than testing 1.5.3 would be to just compare in 1.6 the result of @time vs. the number returned from @elapsed given that @elapsed didn't change in 1.6.

[ufechner7]

More or less the same results when using @Elapsed:

# Output:
# julia> include("test/time2_bug.jl")
# 
# [ Info:  started timer at: 2021-02-20T13:58:23.814
#   0.670841 
# [ Info:          2.92531268s: 2 seconds, 925 milliseconds

# julia> 2.9253/0.6708
# 4.360912343470483

# @elapsed reports 0.67 seconds, while the real execution time incl. compilation is more like 2.9 seconds

[IanButterworth]

Ok. Seems like it's an issue of missing the top-level compilation, and not specific to 1.6
Perhaps it's worth renaming this issue to remove the 1.6rc1?

I may open an issue to specifically track @time missing top-level compilation time, given it's an ongoing issue that's been a bit buried in PR comments etc.

[timholy]

Why do we force-compile @time blocks?

julia/base/timing.jl

Line 202 in 3129a5b

while false; end # compiler heuristic: compile this block (alter this if the heuristic changes)

So presumably what's happening is this:

• tick starts
• Julia starts compiling the @time block. Notably, this compiles things that can be inferred from the top-level @time code, the ex payload, & passed types. In this case, that's most of the time. This all happens before @time's own internal timers start, because compilation happens before execution.
• @time starts its own timers
• it executes the ex passed to time. Anything that needed runtime dispatch gets compiled now (any non-inferrable internal calls from the ex payload)
• @time wraps up collecting data & returns
• tock runs

So tick/tock include the time needed to compile this whereas @time's report does not.

It seems like commenting-out the while false; end might fix it but it would be nice to know why it's there. git blame suggests #35353 but that was just a code move. To me it seems that if we precompile all of @time's dependencies (which we do) then having this block run in compiled mode rather than interpreted mode is wrong. Maybe it was added to improve accuracy of @time for fast-running code? Isn't that what @btime is for?

[KristofferC]

git blame suggests #35353 but that was just a code move

Origin is #33717

[timholy]

CC @vtjnash, any thoughts?

[ufechner7]

I did the same test on Julia 1.5.3:

# On Julia 1.5.3:
# julia> include("test/time_bug.jl")
# [ Info:  started timer at: 2021-02-21T10:59:55.463
#   0.811249 seconds (1.94 M allocations: 103.003 MiB, 2.59% gc time)
# [ Info:          2.161581335s: 2 seconds, 161 milliseconds

# julia> 2.161/0.811
# 2.664611590628853

# @time reports 0.81 seconds, while the real execution time incl. compilation is more like 2.16 seconds

This means the error is a factor of 2.7 on Julia 1.5.3 and a factor of 4.33 on Julia 1.6.0rc1 .

[ufechner7]

As far as I see there are two options to fix this issue:
a. merge #37938
b. delete the line while false; end from the @time macro

What are the advantages and disadvantages of these two possible fixes?

[IanButterworth]

Some testing on master

julia> @eval function f(a)  # Expensive function to compile. From https://github.com/JuliaLang/julia/pull/37678#discussion_r495515401
                  $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end)
                  $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end)
                  return a
              end
f (generic function with 1 method)

julia> @time f(2)
  0.000000 seconds
-3.706395705243192e209

julia> @time x = 1
  0.000000 seconds
1

julia> Revise.track(Base)

## `while false; end` removed from @time

julia> @time 1 # Let Revise recompile @time itself given change (the % overflow is excusable here)
  0.000001 seconds (30 allocations: 2.188 KiB, 196153.24% compilation time)
1

julia> @eval function f(a)   # Note the slight change to indices
                  $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:101]...) end)
                  $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:101]...) end)
                  return a
              end
f (generic function with 1 method)

julia> @time f(2)
  0.896492 seconds (1.54 M allocations: 65.063 MiB, 1.47% gc time, 100.00% compilation time)
-3.063136946481976e207

julia> @time x = 1
  0.000001 seconds (6 allocations: 192 bytes)
1

So it's necessary to make allocations accurate.

If we remove the while false; end can we just subtract the baseline (6 allocations: 192 bytes) from the report??
We could add a unit test to ensure that(6 allocations: 192 bytes) stays the baseline

[ufechner7]

Sounds good. But this: 196153.24% compilation time also needs to be fixed.

[KristofferC]

I take it you missed the comment above it.