Measure compile time only when using time macros pt.2: handling when code under test throws and make compile timing thread-local

[IanButterworth]

#38885 intended to only enable compile time during the timing macros, however as @ericphanson pointed out if the code under test throws the timing could be left enabled.

The fix here of using a try-finally has the side effect of enabling the timing report even when errors throw, which didn't happen previously. That could be suppressed if the previous behavior is desired.

master

julia> x = rand(1000,1000);

julia> @time x * x;
  0.585421 seconds (2.35 M allocations: 134.031 MiB, 7.19% gc time, 94.24% compilation time)

julia> @time x * x;
  0.015857 seconds (2 allocations: 7.629 MiB)

julia> @time error()
ERROR: 
Stacktrace:
 [1] error()
   @ Base ./error.jl:42
 [2] top-level scope
   @ ./timing.jl:203 [inlined]
 [3] top-level scope
   @ ./REPL[3]:0

julia> # compilation timing is left enabled due to error

This PR

julia> x = rand(1000,1000);

julia> @time x * x;
  0.677077 seconds (2.36 M allocations: 134.586 MiB, 20.48% gc time, 90.76% compilation time)

julia> @time x * x;
  0.014838 seconds (2 allocations: 7.629 MiB)

julia> @time error()
  0.004712 seconds (406 allocations: 33.688 KiB, 98.85% compilation time)
ERROR: 
Stacktrace:
 [1] error()
   @ Base ./error.jl:42
 [2] top-level scope
   @ ./timing.jl:204 [inlined]
 [3] top-level scope
   @ ./REPL[3]:0

[KristofferC]

Are there any race condition concerns when calling @time now from multiple threads?

[IanButterworth]

@time's report printing has never been that well suited to threading

1.5.3

julia> x = rand(1000,1000);

julia> Threads.@threads for i in 1:20 @time x * x; end
  0.755160 seconds  0.769467 seconds (2.70 M allocations: 176.013 MiB, 7.66% gc time) (2.72
 M allocations: 176.882 MiB, 7.52% gc time)
  0.782703 seconds (2.73 M allocations: 192.447 MiB, 7.39% gc time)
  0.797099 seconds (2.73 M allocations: 200.083 MiB, 7.26% gc time)
  0.809425 seconds (2.73 M allocations: 207.717 MiB, 7.15% gc time)
  0.822897 seconds (2.73 M allocations: 215.344 MiB, 7.03% gc time)
  0.059053 seconds (  191 allocations: 45.788 MiB0.075888 seconds) (
20.86 k allocations: 39.226 MiB)
  0.084400 seconds (20.87 k allocations: 46.856 MiB)
  0.085214 seconds (20.86 k allocations: 46.855 MiB)
  0.086948 seconds (20.86 k allocations: 46.855 MiB)
  0.086245 seconds (20.85 k allocations: 46.854 MiB)
  0.063872 seconds (150 allocations: 45.785 MiB)
  0.079255 seconds (169 allocations: 38.157 MiB)
  0.085374 seconds (167 allocations: 30.527 MiB)
  0.083243 seconds (167 allocations: 30.527 MiB)
  0.083350 seconds (166 allocations: 22.897 MiB)
  0.083400 seconds (166 allocations: 22.897 MiB)
  0.052417 seconds (101 allocations: 15.264 MiB)
  0.038486 seconds (67 allocations: 7.633 MiB)

I'm working on a print lock & compile timer activation lock for this PR

[KristofferC]

I just meant if there is a race condition writing to the variable then (= undefined behaviour).

[IanButterworth]

Yes, sorry, I did understand that. I also noticed that this PR increases allocations due to the @time itself. Looking into it

[IanButterworth]

The diff is deceptively messy here. I just wrapped time_print's code in a print lock, and added the newline arg to print a newline within the print lock at the end

[JeffBezanson]

timev_print still prints its own newline outside the lock. If it's important for the newline to be printed inside the lock, we should do it always. If it's not, we should do it never and the caller can print a newline if wanted.

[IanButterworth]

For timev_print I've switched to using the internal newline print. From what I can tell time_print needs optionally do both it's used during the julia build process in sysimage.jl

[IanButterworth]

@KristofferC the setting of jl_measure_compile_time is now protected by a lock. Thanks for pointing that out.

I've returned to the previous non-reporting when errors throw as there doesn't seem to be a need to change that

julia> @time error()
ERROR: 
Stacktrace:
 [1] error()
   @ Base ./error.jl:42
 [2] top-level scope
   @ ./timing.jl:217 [inlined]
 [3] top-level scope
   @ ./REPL[11]:0

The report printing is also now protected by a lock to make threaded printing look better.

julia> Threads.@threads for i in 1:20 @time x * x; end
  0.013592 seconds (77 allocations: 45.782 MiB, 1509301427.48% compilation time)
  0.030026 seconds (104 allocations: 45.783 MiB, 0.09% compilation time)
  0.062268 seconds (73 allocations: 30.522 MiB, 0.02% compilation time)
  0.045501 seconds (88 allocations: 38.152 MiB, 0.04% compilation time)
  0.078885 seconds (59 allocations: 22.891 MiB, 0.01% compilation time)
  0.094609 seconds (44 allocations: 15.261 MiB)
  0.121956 seconds (217 allocations: 45.788 MiB, 23.85% gc time)
  0.020401 seconds (208 allocations: 45.787 MiB)
  0.028625 seconds (199 allocations: 45.787 MiB)
  0.039365 seconds (189 allocations: 45.786 MiB)
  0.047761 seconds (182 allocations: 45.786 MiB)
  0.057183 seconds (182 allocations: 45.786 MiB)
  0.058982 seconds (174 allocations: 45.785 MiB)
  0.064370 seconds (174 allocations: 45.785 MiB)
  0.067353 seconds (174 allocations: 45.785 MiB)
  0.065737 seconds (173 allocations: 38.156 MiB)
  0.066426 seconds (172 allocations: 30.526 MiB)
  0.068942 seconds (171 allocations: 22.897 MiB)
  0.067828 seconds (170 allocations: 15.267 MiB)
  0.066753 seconds (169 allocations: 7.638 MiB)

Although, the first comp time % report here is surprisingly nonsensically high.. Compilation on multiple threads is evidently confusing the singular cumulative counter. I don't see a simple fix. Though I guess it's ok to leave as-is and tackle that in a future PR

[IanButterworth]

The compilation timing is now thread-local, without the need for locks, and seems to behave well:

julia> x = rand(10,10);

julia> Threads.@threads for i in 1:20 @time x * x; end
  0.626245 seconds (2.35 M allocations: 126.426 MiB, 16.45% gc time, 0.00% compilation time)
  0.626233 seconds (2.35 M allocations: 126.428 MiB, 16.45% gc time, 0.00% compilation time)
  0.626298 seconds (2.35 M allocations: 126.432 MiB, 16.45% gc time, 0.00% compilation time)
  0.626271 seconds (2.35 M allocations: 126.427 MiB, 16.45% gc time, 0.00% compilation time)
  0.626324 seconds (2.35 M allocations: 126.431 MiB, 16.45% gc time, 99.95% compilation time)
  0.626306 seconds (2.35 M allocations: 126.430 MiB, 16.45% gc time, 0.00% compilation time)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000003 seconds (1 allocation: 896 bytes)
  0.000003 seconds (1 allocation: 896 bytes)
  0.000023 seconds (1 allocation: 896 bytes)
  0.000001 seconds (1 allocation: 896 bytes)
  0.000007 seconds (16 allocations: 1.828 KiB)
  0.000004 seconds (10 allocations: 1.312 KiB)
  0.000003 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000003 seconds (14 allocations: 1.922 KiB)
  0.000003 seconds (1 allocation: 896 bytes)
  0.000007 seconds (2 allocations: 928 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000003 seconds (15 allocations: 1.750 KiB)

julia> x = rand(10,10);

julia> for i in 1:10 @time x * x; end
  0.563264 seconds (2.35 M allocations: 126.422 MiB, 6.58% gc time, 99.94% compilation time)
  0.000006 seconds (1 allocation: 896 bytes)
  0.000006 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)
  0.000001 seconds (1 allocation: 896 bytes)
  0.000001 seconds (1 allocation: 896 bytes)
  0.000002 seconds (1 allocation: 896 bytes)

[IanButterworth]

@JeffBezanson I think this should be ready for another review

[vtjnash]

This appears to have broken the tests (https://build.julialang.org/#/builders/5/builds/1156)