Skip to content

Commit

Permalink
Fix bug in @time compilation time measurement, using tryfinally mac…
Browse files Browse the repository at this point in the history
…ro. (JuliaLang#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.
  • Loading branch information
NHDaly authored and LilithHafner committed Mar 8, 2022
1 parent 936d2db commit 1872837
Show file tree
Hide file tree
Showing 2 changed files with 18 additions and 12 deletions.
24 changes: 18 additions & 6 deletions base/timing.jl
Original file line number Diff line number Diff line change
Expand Up @@ -164,6 +164,16 @@ function timev_print(elapsedtime, diff::GC_Diff, compile_time)
padded_nonzero_print(diff.full_sweep, "full collections")
end

# Like a try-finally block, except without introducing the try scope
# NOTE: This is deprecated and should not be used from user logic. A proper solution to
# this problem will be introduced in https://github.com/JuliaLang/julia/pull/39217
macro __tryfinally(ex, fin)
Expr(:tryfinally,
:($(esc(ex))),
:($(esc(fin)))
)
end

"""
@time
Expand Down Expand Up @@ -207,9 +217,10 @@ macro time(ex)
local stats = gc_num()
local elapsedtime = time_ns()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local val = $(esc(ex))
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
elapsedtime = time_ns() - elapsedtime
local val = @__tryfinally($(esc(ex)),
(elapsedtime = time_ns() - elapsedtime;
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
time_print(elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), compile_elapsedtime, true)
val
Expand Down Expand Up @@ -253,9 +264,10 @@ macro timev(ex)
local stats = gc_num()
local elapsedtime = time_ns()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local val = $(esc(ex))
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
elapsedtime = time_ns() - elapsedtime
local val = @__tryfinally($(esc(ex)),
(elapsedtime = time_ns() - elapsedtime;
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)
)
local diff = GC_Diff(gc_num(), stats)
timev_print(elapsedtime, diff, compile_elapsedtime)
val
Expand Down
6 changes: 0 additions & 6 deletions src/task.c
Original file line number Diff line number Diff line change
Expand Up @@ -560,12 +560,6 @@ static void JL_NORETURN throw_internal(jl_task_t *ct, jl_value_t *exception JL_M
assert(!jl_get_safe_restore());
jl_ptls_t ptls = ct->ptls;
ptls->io_wait = 0;
// @time needs its compile timer disabled on error,
// and cannot use a try-finally as it would break scope for assignments
// We blindly disable compilation time tracking here, for all running Tasks, even though
// it may cause some incorrect measurements. This is a known bug, and is being tracked
// here: https://github.com/JuliaLang/julia/pull/39138
jl_atomic_store_relaxed(&jl_measure_compile_time_enabled, 0);
JL_GC_PUSH1(&exception);
jl_gc_unsafe_enter(ptls);
if (exception) {
Expand Down

0 comments on commit 1872837

Please sign in to comment.