Greater than 100% compilation time reported by @time

[CameronBieganek]

cameron@Camerons-MBP:~$ julia
               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.6.1 (2021-04-23)
 _/ |\__'_|_|_|\__'_|  |  Official https://julialang.org/ release
|__/                   |

julia> @time map(x -> 2x, 1:3);
  0.023913 seconds (50.75 k allocations: 3.048 MiB, 107.64% compilation time)

macOS 10.13.6
Julia 1.6.1

[IanButterworth]

One explanation for this could be if the the compile and inference timers are nested and double-counting time. Could that be the case @JeffBezanson ?

Some more data points:

julia> @time map(x ->2x, 1:3);
  0.025242 seconds (50.75 k allocations: 3.048 MiB, 107.13% compilation time)

julia> @time map(x ->2x, 1:3);
  0.030358 seconds (48.48 k allocations: 2.853 MiB, 99.40% compilation time)

julia> @time map(x ->2x, 1:3);
  0.029765 seconds (48.47 k allocations: 2.865 MiB, 99.37% compilation time)

julia> @time @eval map(x ->2x, 1:3);
  0.025242 seconds (50.90 k allocations: 3.058 MiB, 103.76% compilation time)

julia> @time @eval map(x ->2x, 1:3);
  0.027906 seconds (48.63 k allocations: 2.863 MiB, 98.17% compilation time)

julia> @time @eval map(x ->2x, 1:3);
  0.023328 seconds (48.62 k allocations: 2.875 MiB, 97.56% compilation time)

julia> @time @eval map(x ->4324322x, 1:3);
  0.024817 seconds (48.62 k allocations: 2.860 MiB, 97.98% compilation time)

[IanButterworth]

I did a bit of (non-threadsafe) debugging in IanButterworth@4ffb0f3

Seems like there is double-counting going on. A non-zero value for the start time vars at these checks means timing is happening within another.

julia> @time map(x ->2x, 1:3);
nested timing detected in jl_typeinf_begin compiler_start_time = 597062558202189 inference_start_time = 0
nested timing detected in jl_generate_fptr compiler_start_time = 0 inference_start_time = 597062558224369
nested timing detected in jl_typeinf_begin compiler_start_time = 597062563178618 inference_start_time = 597062558224369
nested timing detected in jl_generate_fptr compiler_start_time = 0 inference_start_time = 597062563187454
nested timing detected in jl_typeinf_begin compiler_start_time = 597062589464894 inference_start_time = 597062563187454
  0.031410 seconds (52.03 k allocations: 3.241 MiB, 106.29% compilation time)

julia> @time map(x ->2x, 1:3);
nested timing detected in jl_generate_fptr compiler_start_time = 0 inference_start_time = 597062589472279
nested timing detected in jl_typeinf_begin compiler_start_time = 598776873104500 inference_start_time = 597062589472279
nested timing detected in jl_generate_fptr compiler_start_time = 0 inference_start_time = 598776873111641
nested timing detected in jl_typeinf_begin compiler_start_time = 598776878127762 inference_start_time = 598776873111641
  0.029258 seconds (49.72 k allocations: 3.057 MiB, 98.88% compilation time)

julia> x = rand(10,10);

julia> @time x * x;
nested timing detected in jl_typeinf_begin compiler_start_time = 598835000573246 inference_start_time = 0
  0.617166 seconds (2.55 M allocations: 141.028 MiB, 5.98% gc time, 99.95% compilation time)

[IanButterworth]

Maybe I'm barking up the wrong tree. This seems like a fix #41286

[IanButterworth]

It's baaack

julia> @time_imports using OmniPackage
...
               ┌ 255.1 ms FoldsThreads.Implementations.__init__() 447.05% compilation time
    276.9 ms  FoldsThreads 411.82% compilation time

Seems threading related here

[sdall]

I can confirm that this issue appears to be related to multi-threading.

julia> @time f()
2.447361 seconds (11.96 M allocations: 626.750 MiB, 5.85% gc time, 138.45% compilation time)

On the other hand, the compilation time is below 100.00% in a single-threaded scenario.