Skip to content
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

Jump to bottom

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

Merged
merged 8 commits into from
Jan 6, 2021
Merged

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

Changes from 3 commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
6d82244
ensure compile timing disables in time & timev macros
IanButterworth Dec 16, 2020
729f0a1
make comp measurement switching threadsafe
IanButterworth Dec 20, 2020
5aaa970
don't report time for errors. make printing thread-friendly
IanButterworth Dec 20, 2020
77d57bd
collect time report into string and print in one step
IanButterworth Dec 25, 2020
a9e2925
use sprint to collate report
IanButterworth Dec 27, 2020
179f411
make compile timing thread-local
IanButterworth Dec 30, 2020
67b41d6
remove unnecesary locks
IanButterworth Dec 30, 2020
2bda755
tidying
IanButterworth Dec 30, 2020
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
92 changes: 55 additions & 37 deletions base/timing.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -56,8 +56,17 @@ function gc_alloc_count(diff::GC_Diff)
end

# cumulative total time spent on compilation
cumulative_compile_time_ns_before() = ccall(:jl_cumulative_compile_time_ns_before, UInt64, ())
cumulative_compile_time_ns_after() = ccall(:jl_cumulative_compile_time_ns_after, UInt64, ())
const comp_timer_lock = ReentrantLock()
function cumulative_compile_time_ns_before()
lock(comp_timer_lock) do
IanButterworth marked this conversation as resolved.
Show resolved Hide resolved
ccall(:jl_cumulative_compile_time_ns_before, UInt64, ())
end
end
function cumulative_compile_time_ns_after()
lock(comp_timer_lock) do
ccall(:jl_cumulative_compile_time_ns_after, UInt64, ())
end
end

# total time spend in garbage collection, in nanoseconds
gc_time_ns() = ccall(:jl_gc_total_hrtime, UInt64, ())
Expand Down Expand Up @@ -115,35 +124,39 @@ function format_bytes(bytes) # also used by InteractiveUtils
end
end

function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0)
timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6)
length(timestr) < 10 && print(" "^(10 - length(timestr)))
print(timestr, " seconds")
parens = bytes != 0 || allocs != 0 || gctime > 0 || compile_time > 0
parens && print(" (")
if bytes != 0 || allocs != 0
allocs, ma = prettyprint_getunits(allocs, length(_cnt_units), Int64(1000))
if ma == 1
print(Int(allocs), _cnt_units[ma], allocs==1 ? " allocation: " : " allocations: ")
else
print(Ryu.writefixed(Float64(allocs), 2), _cnt_units[ma], " allocations: ")
end
print(format_bytes(bytes))
end
if gctime > 0
const print_lock = ReentrantLock()
function time_print(elapsedtime, bytes=0, gctime=0, allocs=0, compile_time=0, newline=false)
lock(print_lock) do
IanButterworth marked this conversation as resolved.
Show resolved Hide resolved
timestr = Ryu.writefixed(Float64(elapsedtime/1e9), 6)
length(timestr) < 10 && print(" "^(10 - length(timestr)))
print(timestr, " seconds")
parens = bytes != 0 || allocs != 0 || gctime > 0 || compile_time > 0
parens && print(" (")
if bytes != 0 || allocs != 0
print(", ")
allocs, ma = prettyprint_getunits(allocs, length(_cnt_units), Int64(1000))
if ma == 1
print(Int(allocs), _cnt_units[ma], allocs==1 ? " allocation: " : " allocations: ")
else
print(Ryu.writefixed(Float64(allocs), 2), _cnt_units[ma], " allocations: ")
end
print(format_bytes(bytes))
end
print(Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time")
end
if compile_time > 0
if bytes != 0 || allocs != 0 || gctime > 0
print(", ")
if gctime > 0
if bytes != 0 || allocs != 0
print(", ")
end
print(Ryu.writefixed(Float64(100*gctime/elapsedtime), 2), "% gc time")
end
if compile_time > 0
if bytes != 0 || allocs != 0 || gctime > 0
print(", ")
end
print(Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
end
print(Ryu.writefixed(Float64(100*compile_time/elapsedtime), 2), "% compilation time")
parens && print(")")
newline && println()
nothing
end
parens && print(")")
nothing
Copy link
Member Author

Choose a reason for hiding this comment

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

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

Copy link
Member

Choose a reason for hiding this comment

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

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.

Copy link
Member Author

Choose a reason for hiding this comment

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

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

end

function timev_print(elapsedtime, diff::GC_Diff, compile_time)
Expand Down Expand Up @@ -200,13 +213,14 @@ macro time(ex)
local stats = gc_num()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local elapsedtime = time_ns()
local val = $(esc(ex))
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
local val = try
$(esc(ex))
finally
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
end
local diff = GC_Diff(gc_num(), stats)
time_print(elapsedtime, diff.allocd, diff.total_time,
gc_alloc_count(diff), compile_elapsedtime)
println()
time_print(elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), compile_elapsedtime, true)
val
end
end
Expand Down Expand Up @@ -248,10 +262,14 @@ macro timev(ex)
local stats = gc_num()
local compile_elapsedtime = cumulative_compile_time_ns_before()
local elapsedtime = time_ns()
local val = $(esc(ex))
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
timev_print(elapsedtime, GC_Diff(gc_num(), stats), compile_elapsedtime)
local val = try
$(esc(ex))
finally
elapsedtime = time_ns() - elapsedtime
compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime
end
local diff = GC_Diff(gc_num(), stats)
timev_print(elapsedtime, diff, compile_elapsedtime)
val
end
end
Expand Down