Skip to content
Open
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
5 changes: 5 additions & 0 deletions Project.toml
Original file line number Diff line number Diff line change
Expand Up @@ -4,14 +4,19 @@ version = "0.5.29"

[deps]
ExprTools = "e2ba6199-217a-4e67-a87a-7c52f15ade04"
PrettyTables = "08abe8d2-0d0c-5749-adfa-8a2ac140af0d"
Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7"

[weakdeps]
FlameGraphs = "08572546-2f56-4bcf-ba4e-bab62c3a3f89"

[sources]
PrettyTables = {rev = "master", url = "https://github.com/ronisbr/PrettyTables.jl.git"}

[compat]
ExprTools = "0.1.0"
FlameGraphs = "1"
PrettyTables = "2"
julia = "1.10"

[extras]
Expand Down
9 changes: 0 additions & 9 deletions src/TimerOutput.jl
Original file line number Diff line number Diff line change
Expand Up @@ -121,15 +121,6 @@ function totmeasured(to::TimerOutput)
return t, b
end

function longest_name(to::TimerOutput, indent = 0)
m = textwidth(to.name) + indent
for inner_timer in values(to.inner_timers)
m = max(m, longest_name(inner_timer, indent + 2))
end
return m
end


# merging timer outputs
const merge_lock = ReentrantLock() # needed for merges of objects on different threads

Expand Down
1 change: 1 addition & 0 deletions src/TimerOutputs.jl
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
module TimerOutputs

using ExprTools
using PrettyTables

import Base: show, time_ns
export TimerOutput, @timeit, @timeit_debug, reset_timer!, print_timer, timeit,
Expand Down
284 changes: 163 additions & 121 deletions src/show.jl
Original file line number Diff line number Diff line change
@@ -1,164 +1,206 @@
#TODO: Alternate background color between gray and white?

print_timer(; kwargs...) = print_timer(stdout; kwargs...)
print_timer(to::TimerOutput; kwargs...) = print_timer(stdout, to; kwargs...)
print_timer(io::IO; kwargs...) = print_timer(io, DEFAULT_TIMER; kwargs...)
print_timer(io::IO, to::TimerOutput; kwargs...) = (show(io, to; kwargs...); println(io))

function _extract_table_data(to::TimerOutput, sortby::Symbol, root_time_total::Int64, root_alloc_total::Int64, indent_level::Int = 0)
sections = String[]
ncalls_data = Int[]
time_data = Int64[]
time_pct_data = Float64[]
time_avg_data = Float64[]
alloc_data = Int64[]
alloc_pct_data = Float64[]
alloc_avg_data = Float64[]

# Sort sections
rev = !in(sortby, [:name, :firstexec])
by(x) = sortf(x, sortby)
sorted_timers = sort!(collect(values(to.inner_timers)); rev = rev, by = by)

for timer in sorted_timers
# Add indentation for nested sections
section_name = " "^indent_level * timer.name

push!(sections, section_name)
push!(ncalls_data, timer.accumulated_data.ncalls)
push!(time_data, timer.accumulated_data.time)
push!(time_pct_data, root_time_total > 0 ? 100.0 * timer.accumulated_data.time / root_time_total : 0.0)
push!(time_avg_data, timer.accumulated_data.ncalls > 0 ? timer.accumulated_data.time ÷ timer.accumulated_data.ncalls : 0)
push!(alloc_data, timer.accumulated_data.allocs)
push!(alloc_pct_data, root_alloc_total > 0 ? 100.0 * timer.accumulated_data.allocs / root_alloc_total : 0.0)
push!(alloc_avg_data, timer.accumulated_data.ncalls > 0 ? timer.accumulated_data.allocs ÷ timer.accumulated_data.ncalls : 0)

# Recursively add nested timers
if !isempty(timer.inner_timers)
nested_sections, nested_ncalls, nested_time, nested_time_pct, nested_time_avg,
nested_alloc, nested_alloc_pct, nested_alloc_avg = _extract_table_data(timer, sortby, root_time_total, root_alloc_total, indent_level + 1)

append!(sections, nested_sections)
append!(ncalls_data, nested_ncalls)
append!(time_data, nested_time)
append!(time_pct_data, nested_time_pct)
append!(time_avg_data, nested_time_avg)
append!(alloc_data, nested_alloc)
append!(alloc_pct_data, nested_alloc_pct)
append!(alloc_avg_data, nested_alloc_avg)
end
end

return sections, ncalls_data, time_data, time_pct_data, time_avg_data, alloc_data, alloc_pct_data, alloc_avg_data
end

Base.show(to::TimerOutput; kwargs...) = show(stdout, to; kwargs...)
function Base.show(io::IO, to::TimerOutput; allocations::Bool = true, sortby::Symbol = :time, linechars::Symbol = :unicode, compact::Bool = false, title::String = "")
function Base.show(io::IO, to::TimerOutput; allocations::Bool = true, sortby::Symbol = :time, linechars = nothing, compact::Bool = false, title::String = "")
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"))
if linechars !== nothing
Base.depwarn("the `linechars` argument has been deprecated and now does nothing", :linechars)
end

# Calculate total measurements
t₀, b₀ = to.start_data.time, to.start_data.allocs
t₁, b₁ = time_ns(), gc_bytes()
Δt, Δb = t₁ - t₀, b₁ - b₀
∑t, ∑b = to.flattened ? to.totmeasured : totmeasured(to)

max_name = longest_name(to)
available_width = get(io, :limit, false) ? displaysize(io)[2] : typemax(Int)
requested_width = max_name
if compact
if allocations
requested_width += 43
else
requested_width += 25
end
else
if allocations
requested_width += 59
else
requested_width += 33
end
# Extract table data
if isempty(to.inner_timers)
println(io, "No sections recorded.")
return
end

sections, ncalls_data, time_data, time_pct_data, time_avg_data,
alloc_data, alloc_pct_data, alloc_avg_data = _extract_table_data(to, sortby, ∑t, ∑b)

#requested_width = 34 + (allocations ? 27 : 0) + max_name
name_length = max(9, max_name - max(0, requested_width - available_width))
# Format the data for display
time_strings = [prettytime(t) for t in time_data]
time_pct_strings = [prettypercent(pct, 100.0) for pct in time_pct_data]
time_avg_strings = [prettytime(t) for t in time_avg_data]
alloc_strings = [prettymemory(a) for a in alloc_data]
alloc_pct_strings = [prettypercent(pct, 100.0) for pct in alloc_pct_data]
alloc_avg_strings = [prettymemory(a) for a in alloc_avg_data]

print_header(io, Δt, Δb, ∑t, ∑b, name_length, true, allocations, linechars, compact, title)
rev = !in(sortby, [:name, :firstexec])
by(x) = sortf(x, sortby)
for timer in sort!(collect(values(to.inner_timers)); rev = rev, by = by)
_print_timer(io, timer, ∑t, ∑b, 0, name_length, allocations, sortby, compact)
end
return print_header(io, Δt, Δb, ∑t, ∑b, name_length, false, allocations, linechars, compact, title)
end

function sortf(x, sortby)
sortby == :time && return x.accumulated_data.time
sortby == :ncalls && return x.accumulated_data.ncalls
sortby == :allocations && return x.accumulated_data.allocs
sortby == :name && return x.name
sortby == :firstexec && return x.accumulated_data.firstexec
error("internal error")
end
# Build table data matrix
data_cols = [sections, ncalls_data, time_strings, time_pct_strings]

# truncate string and add dots
function truncdots(str, n)
textwidth(str) <= n && return str
n <= 3 && return ""
io = IOBuffer()
for (i, c) in enumerate(str)
i == n - 2 && (write(io, "..."); break)
write(io, c)
if !compact
push!(data_cols, time_avg_strings)
end
return String(take!(io))
end

function print_header(io, Δt, Δb, ∑t, ∑b, name_length, header, allocations, linechars, compact, title)
midrule = linechars == :unicode ? "─" : "-"
topbottomrule = linechars == :unicode ? "─" : "-"
sec_ncalls = string(rpad("Section", name_length, " "), " ncalls ")
time_headers = " time %tot" * (compact ? "" : " avg")
alloc_headers = allocations ? (" alloc %tot" * (compact ? "" : " avg")) : ""
total_table_width = sum(textwidth.((sec_ncalls, time_headers, alloc_headers))) + 3

# Just hardcoded shit to make things look nice
!allocations && (total_table_width -= 3)
if allocations
empty_col = fill(" ", length(sections)) # Use spaces to create wider separation
push!(data_cols, empty_col)
push!(data_cols, alloc_strings)
push!(data_cols, alloc_pct_strings)

function center(str, len)
x = (len - textwidth(str)) ÷ 2
return string(" "^x, str, " "^(len - textwidth(str) - x))
if !compact
push!(data_cols, alloc_avg_strings)
end
end
table_data = reduce(hcat, data_cols)

return if header
time_alloc_pading = " "^(textwidth(sec_ncalls))
if compact
if allocations
println(io, "Total measured: $(prettytime(Δt)) / $(prettymemory(Δb))")
else
println(io, "Total measured: $(prettytime(Δt))")
end
println(io)

title = center(truncdots(title, textwidth(sec_ncalls)), textwidth(sec_ncalls))
column_labels = ["Section", "ncalls", "time", "%tot"]

if compact
time_header = " Time "
if allocations
append!(column_labels, [" ", "alloc", "%tot"])
else
time_header = " Time "
end
else
row1 = []
push!(row1, EmptyCells(2))

time_underline = midrule^textwidth(time_header)
time_cols = compact ? 2 : 3
push!(row1, MultiColumn(time_cols, "Time (tot / % meas)"))

if compact
allocation_header = " Allocations "
else
allocation_header = " Allocations "
if allocations
push!(row1, EmptyCells(1))
alloc_cols = compact ? 2 : 3
push!(row1, MultiColumn(alloc_cols, "Allocations (tot / % meas)"))
end

alloc_underline = midrule^textwidth(allocation_header)
#tot_meas_str = string(" ", rpad("Tot / % measured:", textwidth(sec_ncalls) - 1, " "))
if compact
tot_meas_str = center("Total measured:", textwidth(sec_ncalls))
row2 = Any["", ""]
measured_pct_time = ∑t > 0 ? prettypercent(∑t, Δt; dolpad = false) : " -%"
time_measured = "$(prettytime(Δt)) / $measured_pct_time"
if !compact
push!(row2, MultiColumn(3, time_measured))
else
tot_meas_str = center("Tot / % measured:", textwidth(sec_ncalls))
push!(row2, time_measured)
end

str_time = center(string(prettytime(Δt), compact ? "" : string(" / ", prettypercent(∑t, Δt))), textwidth(time_header))
str_alloc = center(string(prettymemory(Δb), compact ? "" : string(" / ", prettypercent(∑b, Δb))), textwidth(allocation_header))

header_str = string(" time %tot %timed")
tot_midstr = string(sec_ncalls, " ", header_str)
printstyled(io, topbottomrule^total_table_width, "\n"; bold = true)
if ! (allocations == false && compact == true)
printstyled(io, title; bold = true)
print(io, time_header)
allocations && print(io, " ", allocation_header)
print(io, "\n")
print(io, time_alloc_pading, time_underline)
allocations && print(io, " ", alloc_underline)
print(io, "\n")
print(io, tot_meas_str, str_time)
allocations && print(io, " ", str_alloc)
print(io, "\n\n")
if allocations
push!(row2, " ")
measured_pct_alloc = ∑b > 0 ? prettypercent(∑b, Δb; dolpad = false) : " -%"
alloc_measured = "$(prettymemory(Δb)) / $measured_pct_alloc"
if !compact
push!(row2, MultiColumn(3, alloc_measured))

else
push!(row2, alloc_measured)
end
end
print(io, sec_ncalls, time_headers)
allocations && print(io, " ", alloc_headers)
print(io, "\n")
print(io, midrule^total_table_width, "\n")
else
printstyled(io, topbottomrule^total_table_width; bold = true)
end
end

function _print_timer(io::IO, to::TimerOutput, ∑t::Integer, ∑b::Integer, indent::Integer, name_length, allocations, sortby, compact)
accum_data = to.accumulated_data
t = accum_data.time
b = accum_data.allocs
# Row 3: Empty line
total_cols = 5 + (compact ? 0 : 1) + (allocations ? (2 + (compact ? 0 : 1)) : 0)
row3 = fill("", total_cols)

row4 = ["Section", "ncalls", "time", "%tot"]
if !compact
push!(row4, "avg")
end
if allocations
push!(row4, " ")
append!(row4, ["alloc", "%tot"])
if !compact
push!(row4, "avg")
end
end

name = truncdots(to.name, name_length - indent)
nc = accum_data.ncalls
print(io, " "^indent, rpad(name, name_length + 2 - indent))
print(io, lpad(prettycount(nc), 5, " "))
column_labels = [row1, row2, row3, row4]
end

print(io, " ", lpad(prettytime(t), 6, " "))
print(io, " ", lpad(prettypercent(t, ∑t), 5, " "))
!compact && print(io, " ", rpad(prettytime(t / nc), 6, " "))
table_format = TextTableFormat(;
@text__no_vertical_lines
)

alignment_array = [:l, :r, :r, :r]
if !compact
push!(alignment_array, :r)
end
if allocations
print(io, " ", rpad(prettymemory(b), 9, " "))
print(io, rpad(prettypercent(b, ∑b), 5, " "))
!compact && print(io, " ", lpad(prettymemory(b / nc), 5, " "))
push!(alignment_array, :c) # empty col
push!(alignment_array, :r)
push!(alignment_array, :r)
if !compact
push!(alignment_array, :r)
end
end
print(io, "\n")

rev = !in(sortby, [:name, :firstexec])
by(x) = sortf(x, sortby)
for timer in sort!(collect(values(to.inner_timers)); rev = rev, by = by)
_print_timer(io, timer, ∑t, ∑b, indent + 2, name_length, allocations, sortby, compact)
end
return
return pretty_table(
io, table_data;
column_labels = column_labels,
merge_column_label_cells = :auto,
show_omitted_cell_summary = false,
alignment = alignment_array,
table_format = table_format,
title = !isempty(title) ? title : ""
)
end

function sortf(x, sortby)
sortby == :time && return x.accumulated_data.time
sortby == :ncalls && return x.accumulated_data.ncalls
sortby == :allocations && return x.accumulated_data.allocs
sortby == :name && return x.name
sortby == :firstexec && return x.accumulated_data.firstexec
error("internal error")
end
Loading