diff --git a/Project.toml b/Project.toml index 9f2c120..394ac73 100644 --- a/Project.toml +++ b/Project.toml @@ -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] diff --git a/src/TimerOutput.jl b/src/TimerOutput.jl index 99f5244..4749657 100644 --- a/src/TimerOutput.jl +++ b/src/TimerOutput.jl @@ -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 diff --git a/src/TimerOutputs.jl b/src/TimerOutputs.jl index 759677a..5172767 100644 --- a/src/TimerOutputs.jl +++ b/src/TimerOutputs.jl @@ -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, diff --git a/src/show.jl b/src/show.jl index 1edb68b..2b6b208 100644 --- a/src/show.jl +++ b/src/show.jl @@ -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 diff --git a/src/utilities.jl b/src/utilities.jl index 4687cca..60bad49 100644 --- a/src/utilities.jl +++ b/src/utilities.jl @@ -55,7 +55,7 @@ function prettymemory(b) return lpad(str, 7, " ") end -function prettypercent(nominator, denominator) +function prettypercent(nominator, denominator; dolpad = true) value = nominator / denominator * 100 if denominator == 0 && nominator == 0 @@ -65,7 +65,7 @@ function prettypercent(nominator, denominator) else str = string(@sprintf("%.1f", value), "%") end - return lpad(str, 6, " ") + return dolpad ? lpad(str, 6, " ") : str end function prettycount(t::Integer) @@ -89,19 +89,6 @@ function prettycount(t::Integer) return str end -function rpad( - s::Union{AbstractChar, AbstractString}, - n::Integer, - p::Union{AbstractChar, AbstractString} = ' ', - )::String - n = Int(n)::Int - m = signed(n) - Int(textwidth(s))::Int - m ≤ 0 && return string(s) - l = textwidth(p) - q, r = divrem(m, l) - return r == 0 ? string(s, p^q) : string(s, p^q, first(p, r)) -end - ################# # Serialization # #################