Skip to content
Closed
Show file tree
Hide file tree
Changes from all commits
Commits
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
48 changes: 48 additions & 0 deletions src/TimerOutput.jl
Original file line number Diff line number Diff line change
Expand Up @@ -11,6 +11,15 @@ TimeData(ncalls, time, allocs) = TimeData(ncalls, time, allocs, time)
Base.copy(td::TimeData) = TimeData(td.ncalls, td.time, td.allocs)
TimeData() = TimeData(0, 0, 0, time_ns())

# convenience function for deserialisation
function TimeData(dict::Dict{String, Any})
return TimeData(dict["n_calls"], dict["time_ns"], dict["allocated_bytes"], dict["start_time_ns"])
end

function Base.:(==)(self::TimeData, other::TimeData)
return (self.ncalls == other.ncalls) && (self.time == other.time) && (self.allocs == other.allocs) && (self.firstexec == other.firstexec)
end

function Base.:+(self::TimeData, other::TimeData)
TimeData(self.ncalls + other.ncalls,
self.time + other.time,
Expand Down Expand Up @@ -48,9 +57,42 @@ mutable struct TimerOutput

end

# convenience function for deserialisation
function TimerOutput(dict::Dict{String, Any})
return TimerOutput(
TimeData(dict["start_data"]),
TimeData(dict["n_calls"], dict["time_ns"], dict["allocated_bytes"], dict["start_time_ns"]),
Dict{String, TimerOutput}(
k => TimerOutput(v) for (k, v) ∈ dict["inner_timers"]
),
Vector{TimerOutput}(TimerOutput.(dict["timer_stack"])),
dict["name"],
dict["flattened"],
dict["enabled"],
(0, 0), # we don't appear to be using the internal totmeasured field?
dict["prev_timer_label"],
isnothing(dict["prev_timer"]) ? nothing : TimerOutput(dict["prev_timer"])
)
end

Base.copy(to::TimerOutput) = TimerOutput(copy(to.start_data), copy(to.accumulated_data), copy(to.inner_timers),
copy(to.timer_stack), to.name, to.flattened, to.enabled, to.totmeasured, "", nothing)

function Base.:(==)(self::TimerOutput, other::TimerOutput)
return all([
self.start_data == other.start_data,
self.accumulated_data == other.accumulated_data,
self.inner_timers == other.inner_timers,
self.timer_stack == other.timer_stack,
self.name == other.name,
self.flattened == other.flattened,
self.enabled == other.enabled,
self.totmeasured == other.totmeasured,
self.prev_timer_label == other.prev_timer_label,
self.prev_timer == other.prev_timer
])
end

const DEFAULT_TIMER = TimerOutput()
const _timers = Dict{String, TimerOutput}("Default" => DEFAULT_TIMER)
const _timers_lock = ReentrantLock() # needed for adding new timers on different threads
Expand Down Expand Up @@ -158,6 +200,7 @@ end
ncalls(to::TimerOutput) = to.accumulated_data.ncalls
allocated(to::TimerOutput) = to.accumulated_data.allocs
time(to::TimerOutput) = to.accumulated_data.time
firstexec(to::TimerOutput) = to.accumulated_data.firstexec
totallocated(to::TimerOutput) = totmeasured(to)[2]
tottime(to::TimerOutput) = totmeasured(to)[1]

Expand All @@ -167,6 +210,11 @@ allocated() = allocated(DEFAULT_TIMER)
totallocated() = totmeasured(DEFAULT_TIMER)[2]
tottime() = totmeasured(DEFAULT_TIMER)[1]

ncalls(td::TimeData) = td.ncalls
time(td::TimeData) = td.time
allocated(td::TimeData) = td.allocs
firstexec(td::TimeData) = td.firstexec

get_defaulttimer() = DEFAULT_TIMER
Base.@deprecate get_defaultimer get_defaulttimer

Expand Down
5 changes: 2 additions & 3 deletions src/show.jl
Original file line number Diff line number Diff line change
Expand Up @@ -8,9 +8,8 @@ function Base.show(io::IO, to::TimerOutput; allocations::Bool = true, sortby::Sy
sortby in (:time, :ncalls, :allocations, :name, :firstexec) || throw(ArgumentError("sortby should be :time, :allocations, :ncalls, :name, or :firstexec, got $sortby"))
linechars in (:unicode, :ascii) || throw(ArgumentError("linechars should be :unicode or :ascii, got $linechars"))

t₀, b₀ = to.start_data.time, to.start_data.allocs
t₁, b₁ = time_ns(), gc_bytes()
Δt, Δb = t₁ - t₀, b₁ - b₀
# make sure the deltas we report actually match the time elapsed - can cause problems if we go back to look at results at a later time
Δt, Δb = totmeasured(to)

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

I've added this in since I found if I deserialised a TimerOutput that I ran several hours ago, it showed the "total time" as being e.g. 7 hours, when the actual time was only 400 seconds. This way, the delta remains unaffected by time elapsed since the operation was run

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

I've pulled this out into a specific fix here #187

Copy link
Copy Markdown
Contributor Author

Choose a reason for hiding this comment

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

Thanks :)

Copy link
Copy Markdown
Collaborator

Choose a reason for hiding this comment

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

It was actually reverted. The behavior is intentional in some uses of this package

∑t, ∑b = to.flattened ? to.totmeasured : totmeasured(to)

max_name = longest_name(to)
Expand Down
19 changes: 18 additions & 1 deletion src/utilities.jl
Original file line number Diff line number Diff line change
Expand Up @@ -120,12 +120,29 @@ Converts a `TimerOutput` into a nested set of dictionaries, with keys and value
"""
function todict(to::TimerOutput)
return Dict{String,Any}(
"name" => to.name,
"n_calls" => ncalls(to),
"time_ns" => time(to),
"allocated_bytes" => allocated(to),
"total_allocated_bytes" => totallocated(to),
"total_time_ns" => tottime(to),
"inner_timers" => Dict{String, Any}(k => todict(v) for (k,v) in to.inner_timers)
"inner_timers" => Dict{String, Any}(k => todict(v) for (k,v) in to.inner_timers),
"timer_stack" => todict.(to.timer_stack),
"start_time_ns" => firstexec(to),
"start_data" => todict(to.start_data),
"flattened" => to.flattened,
"enabled" => to.enabled,
"prev_timer_label" => to.prev_timer_label,
"prev_timer" => isnothing(to.prev_timer) ? nothing : todict(to.prev_timer)
)
end

function todict(td::TimeData)
return Dict{String, Any}(
"n_calls" => ncalls(td),
"time_ns" => time(td),
"allocated_bytes" => allocated(td),
"start_time_ns" => firstexec(td)
)
end

Expand Down
3 changes: 3 additions & 0 deletions test/runtests.jl
Original file line number Diff line number Diff line change
Expand Up @@ -682,6 +682,9 @@ end
end

compare(to, todict(to))

# make sure we can serialise and deserialise properly
@test TimerOutput(todict(to)) == to
end

@testset "InstrumentedFunctions" begin
Expand Down