Skip to content

Commit 8ebf8fd

Browse files
NHDalyKristofferC
authored andcommitted
Fix bug in @time compilation time measurement, using tryfinally macro. (#41923)
Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time. (cherry picked from commit 08e100b)
1 parent cd462dc commit 8ebf8fd

File tree

2 files changed

+18
-12
lines changed

2 files changed

+18
-12
lines changed

base/timing.jl

Lines changed: 18 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -164,6 +164,16 @@ function timev_print(elapsedtime, diff::GC_Diff, compile_time)
164164
padded_nonzero_print(diff.full_sweep, "full collections")
165165
end
166166

167+
# Like a try-finally block, except without introducing the try scope
168+
# NOTE: This is deprecated and should not be used from user logic. A proper solution to
169+
# this problem will be introduced in https://github.com/JuliaLang/julia/pull/39217
170+
macro __tryfinally(ex, fin)
171+
Expr(:tryfinally,
172+
:($(esc(ex))),
173+
:($(esc(fin)))
174+
)
175+
end
176+
167177
"""
168178
@time
169179
@@ -207,9 +217,10 @@ macro time(ex)
207217
local stats = gc_num()
208218
local elapsedtime = time_ns()
209219
local compile_elapsedtime = cumulative_compile_time_ns_before()
210-
local val = $(esc(ex))
211-
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
212-
elapsedtime = time_ns() - elapsedtime
220+
local val = @__tryfinally($(esc(ex)),
221+
(elapsedtime = time_ns() - elapsedtime;
222+
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
223+
)
213224
local diff = GC_Diff(gc_num(), stats)
214225
time_print(elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), compile_elapsedtime, true)
215226
val
@@ -253,9 +264,10 @@ macro timev(ex)
253264
local stats = gc_num()
254265
local elapsedtime = time_ns()
255266
local compile_elapsedtime = cumulative_compile_time_ns_before()
256-
local val = $(esc(ex))
257-
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
258-
elapsedtime = time_ns() - elapsedtime
267+
local val = @__tryfinally($(esc(ex)),
268+
(elapsedtime = time_ns() - elapsedtime;
269+
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
270+
)
259271
local diff = GC_Diff(gc_num(), stats)
260272
timev_print(elapsedtime, diff, compile_elapsedtime)
261273
val

src/task.c

Lines changed: 0 additions & 6 deletions
Original file line numberDiff line numberDiff line change
@@ -559,12 +559,6 @@ static void JL_NORETURN throw_internal(jl_task_t *ct, jl_value_t *exception JL_M
559559
assert(!jl_get_safe_restore());
560560
jl_ptls_t ptls = ct->ptls;
561561
ptls->io_wait = 0;
562-
// @time needs its compile timer disabled on error,
563-
// and cannot use a try-finally as it would break scope for assignments
564-
// We blindly disable compilation time tracking here, for all running Tasks, even though
565-
// it may cause some incorrect measurements. This is a known bug, and is being tracked
566-
// here: https://github.com/JuliaLang/julia/pull/39138
567-
jl_atomic_store_relaxed(&jl_measure_compile_time_enabled, 0);
568562
JL_GC_PUSH1(&exception);
569563
jl_gc_unsafe_enter(ptls);
570564
if (exception) {

0 commit comments

Comments
 (0)