Skip to content

Fix bug in @time compilation time measurement, using _tryfinally macro. #41923

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
merged 1 commit into from
Sep 23, 2021
Merged

Fix bug in @time compilation time measurement, using _tryfinally macro. #41923

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
24 changes: 18 additions & 6 deletions base/timing.jl
View file
Open in desktop
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)
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should the order of these be switched to avoid the possibility of compile time being more than 100%?

Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Ok, Oscar made the point that we care more about an accurate elapsed time than about compile time fraction, so maybe it's ok.

)
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
View file
Open in desktop
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