Skip to content

implement @time and @timev in terms of @timed #52889

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
IanButterworth merged 6 commits into from
Jan 20, 2024
Merged

implement @time and @timev in terms of @timed #52889

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
6 commits
Select commit Hold shift + click to select a range
f98fdda
implement in terms of `@timed`
ericphanson Jan 13, 2024
1334214
add basic test
ericphanson Jan 13, 2024
b9809bb
Update base/timing.jl
ericphanson Jan 13, 2024
3e341a2
add news entry
ericphanson Jan 13, 2024
7e602a0
Merge branch 'master' into eph/timed-time
ericphanson Jan 19, 2024
a0a75dc
Update base/timing.jl
ericphanson Jan 20, 2024
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
1 change: 1 addition & 0 deletions NEWS.md
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -93,6 +93,7 @@ New library features
content is fully written, then call `closewrite` manually to avoid
data-races. Or use the callback form of `open` to have all that handled
automatically.
* `@timed` now additionally returns the elapsed compilation and recompilation time ([#52889])

Standard library changes
------------------------
Expand Down
59 changes: 27 additions & 32 deletions base/timing.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -281,20 +281,10 @@ macro time(ex)
end
macro time(msg, ex)
quote
Experimental.@force_compile
local stats = gc_num()
local elapsedtime = time_ns()
cumulative_compile_timing(true)
local compile_elapsedtimes = cumulative_compile_time_ns()
local val = @__tryfinally($(esc(ex)),
(elapsedtime = time_ns() - elapsedtime;
cumulative_compile_timing(false);
compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes)
)
local diff = GC_Diff(gc_num(), stats)
local ret = @timed $(esc(ex))
local _msg = $(esc(msg))
time_print(stdout, elapsedtime, diff.allocd, diff.total_time, gc_alloc_count(diff), first(compile_elapsedtimes), last(compile_elapsedtimes), true; msg=_msg)
val
time_print(stdout, ret.time*1e9, ret.gcstats.allocd, ret.gcstats.total_time, gc_alloc_count(ret.gcstats), ret.compile_time*1e9, ret.recompile_time*1e9, true; msg=_msg)
ret.value
end
end

Expand Down Expand Up @@ -363,20 +353,10 @@ macro timev(ex)
end
macro timev(msg, ex)
quote
Experimental.@force_compile
local stats = gc_num()
local elapsedtime = time_ns()
cumulative_compile_timing(true)
local compile_elapsedtimes = cumulative_compile_time_ns()
local val = @__tryfinally($(esc(ex)),
(elapsedtime = time_ns() - elapsedtime;
cumulative_compile_timing(false);
compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes)
)
local diff = GC_Diff(gc_num(), stats)
local ret = @timed $(esc(ex))
local _msg = $(esc(msg))
timev_print(elapsedtime, diff, compile_elapsedtimes; msg=_msg)
val
timev_print(ret.time*1e9, ret.gcstats, (ret.compile_time*1e9, ret.recompile_time*1e9); msg=_msg)
ret.value
end
end

Expand Down Expand Up @@ -472,9 +452,9 @@ end
"""
@timed

A macro to execute an expression, and return the value of the expression, elapsed time,
total bytes allocated, garbage collection time, and an object with various memory allocation
counters.
A macro to execute an expression, and return the value of the expression, elapsed time in seconds,
total bytes allocated, garbage collection time, an object with various memory allocation
counters, compilation time in seconds, and recompilation time in seconds.

In some cases the system will look inside the `@timed` expression and compile some of the
called code before execution of the top-level expression begins. When that happens, some
Expand All @@ -500,19 +480,34 @@ julia> propertynames(stats.gcstats)

julia> stats.gcstats.total_time
5576500

julia> stats.compile_time
0.0

julia> stats.recompile_time
0.0

```

!!! compat "Julia 1.5"
The return type of this macro was changed from `Tuple` to `NamedTuple` in Julia 1.5.

!!! compat "Julia 1.11"
The `compile_time` and `recompile_time` fields were added in Julia 1.11.
"""
macro timed(ex)
quote
Experimental.@force_compile
local stats = gc_num()
local elapsedtime = time_ns()
local val = $(esc(ex))
elapsedtime = time_ns() - elapsedtime
cumulative_compile_timing(true)
local compile_elapsedtimes = cumulative_compile_time_ns()
local val = @__tryfinally($(esc(ex)),
(elapsedtime = time_ns() - elapsedtime;
cumulative_compile_timing(false);
compile_elapsedtimes = cumulative_compile_time_ns() .- compile_elapsedtimes)
)
local diff = GC_Diff(gc_num(), stats)
(value=val, time=elapsedtime/1e9, bytes=diff.allocd, gctime=diff.total_time/1e9, gcstats=diff)
(value=val, time=elapsedtime/1e9, bytes=diff.allocd, gctime=diff.total_time/1e9, gcstats=diff, compile_time=compile_elapsedtimes[1]/1e9, recompile_time=compile_elapsedtimes[2]/1e9)
end
end
3 changes: 3 additions & 0 deletions test/misc.jl
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -265,6 +265,9 @@ let
stats = @timed sin(1)
@test stats.value == sin(1)
@test isa(stats.time, Real) && stats.time >= 0
@test isa(stats.compile_time, Real) && stats.compile_time >= 0
@test isa(stats.recompile_time, Real) && stats.recompile_time >= 0
@test stats.compile_time <= stats.time

# The return type of gcstats was changed in Julia 1.4 (# 34147)
# Test that the 1.0 API still works
Expand Down