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
4 changes: 3 additions & 1 deletion Project.toml
Original file line number Diff line number Diff line change
Expand Up @@ -5,10 +5,12 @@ version = "0.5.12"
[deps]
ExprTools = "e2ba6199-217a-4e67-a87a-7c52f15ade04"
Printf = "de0858da-6303-5e67-8744-51eddeeeb8d7"
Tables = "bd369af6-aec1-5ad0-b16a-f7cc5008161c"

[compat]
julia = "1"
ExprTools = "0.1.0"
Tables = "1"
julia = "1"

[extras]
Test = "8dfed614-e22c-5e08-85e1-65c5234f0b40"
Expand Down
18 changes: 18 additions & 0 deletions README.md
Original file line number Diff line number Diff line change
Expand Up @@ -353,6 +353,24 @@ julia> TimerOutputs.totallocated(to)
7632
```

## Exporting data

The `TimerOutput` type implements the [Tables.jl](https://github.com/JuliaData/Tables.jl)
interface. Thus, it works with various data-processing packages such as DataFrames.jl.
For example, use `DataFrame(to)` (where `to isa TimerOutput`) to create a data frame
containing the timing and GC information.

The output table has the following columns:

* `name`: A tuple of strings. The i-th element is the label of the i-the level.
* `ncalls`: The number of times `@timeit` is evaluated.
* `time`: The time (nanoseconds) spent, excluding inner `@timeit` sections if any.
* `tottime`: The time (nanoseconds) spent, including inner `@timeit` sections if any.
Comment on lines +367 to +368
Copy link
Author

@tkf tkf Sep 26, 2021

Choose a reason for hiding this comment

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

Actually, these descriptions of time and tottime are incorrect? I thought the above were the case, but then with v0.5.13 I get:

julia> to = TimerOutput();

julia> @timeit to "1" begin
           @timeit to "2" sleep(0.1)
           @timeit to "3" sleep(0.2)
           sleep(0.3)
       end;

julia> TimerOutputs.tottime(to)
603860055

julia> TimerOutputs.time(to["1"])
603860055

julia> TimerOutputs.tottime(to["1"])
302451267

julia> TimerOutputs.time(to["1"]["2"])
101178932

julia> TimerOutputs.time(to["1"]["3"])
201272335

It looks like time is already "total time" and tottime is the total time of the inner timers? Or maybe tottime is not supposed to be called with non-root timers? The README only mentions the usage with the root timer.

Copy link
Owner

Choose a reason for hiding this comment

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

I don't really recall what exactly it measures. Would need to read the source code.

* `allocated`: The number of bytes allocated, excluding inner `@timeit` sections if any.
* `totallocated`: The number of bytes allocated, including inner `@timeit` sections if any.
* `isleaf`: `true` if the corresponding `@timeit` does not have inner `@timeit`;
`false` otherwise.

## Default Timer

It is often the case that it is enough to only use one timer. For convenience, there is therefore a version of
Expand Down
6 changes: 6 additions & 0 deletions src/TimerOutputs.jl
Original file line number Diff line number Diff line change
@@ -1,6 +1,7 @@
module TimerOutputs

using ExprTools
import Tables

import Base: show, time_ns
export TimerOutput, @timeit, @timeit_debug, reset_timer!, print_timer, timeit,
Expand All @@ -17,12 +18,17 @@ else
end
end

if !@isdefined(fieldtypes)
fieldtypes(T) = Tuple([fieldtype(T, i) for i in 1:fieldcount(T)])
end

using Printf


include("TimerOutput.jl")
include("show.jl")
include("utilities.jl")
include("tables.jl")

if Base.VERSION >= v"1.4.2"
include("precompile.jl")
Expand Down
43 changes: 43 additions & 0 deletions src/tables.jl
Original file line number Diff line number Diff line change
@@ -0,0 +1,43 @@
Tables.istable(::Type{TimerOutput}) = true
Tables.rowaccess(::Type{TimerOutput}) = true

struct TimerOutputRow
name::Tuple{String,Vararg{String}}
ncalls::Int
time::Int
allocated::Int
totallocated::Int
tottime::Int
isleaf::Bool
end

function foreachrow(f, timer::TimerOutput, prefix::Tuple{Vararg{String}} = ())
for k in sort!(collect(keys(timer.inner_timers)))
to = timer.inner_timers[k]
name = (prefix..., k)
row = TimerOutputRow(
name,
ncalls(to),
time(to),
allocated(to),
totallocated(to),
tottime(to),
isempty(to.inner_timers),
)
f(row)
foreachrow(f, to, name)
end
end

function Tables.rows(to::TimerOutput)
table = TimerOutputRow[]
foreachrow(to) do row
push!(table, row)
end
return table
end

const TABLE_SCHEMA =
Tables.Schema{fieldnames(TimerOutputRow),Tuple{fieldtypes(TimerOutputRow)...}}()

Tables.schema(::TimerOutput) = TABLE_SCHEMA
49 changes: 49 additions & 0 deletions test/runtests.jl
Original file line number Diff line number Diff line change
@@ -1,5 +1,6 @@
using TimerOutputs
using Test
using Tables

import TimerOutputs: DEFAULT_TIMER, ncalls, flatten,
prettytime, prettymemory, prettypercent, prettycount
Expand Down Expand Up @@ -621,3 +622,51 @@ end
@test !in("3.1.1", collect(keys(to32.inner_timers)))

end

@testset "Tables.jl interface" begin
to = TimerOutput()

@timeit to "1" sleep(0.1)

@timeit to "2" begin
@timeit to "2.1" sleep(0.1)
@timeit to "2.2" sleep(0.1)
@timeit to "2.3" sleep(0.1)
end

@timeit to "3" begin
@timeit to "3.1" begin
@timeit to "3.1.1" sleep(0.1)
@timeit to "3.1.2" sleep(0.1)
@timeit to "3.1.3" sleep(0.1)
end
@timeit to "3.2" begin
@timeit to "3.2.1" sleep(0.1)
@timeit to "3.2.2" sleep(0.1)
@timeit to "3.2.3" sleep(0.1)
end
end

table = Tables.columntable(to)
@test table.name == [
("1",),
("2",),
("2", "2.1"),
("2", "2.2"),
("2", "2.3"),
("3",),
("3", "3.1"),
("3", "3.1", "3.1.1"),
("3", "3.1", "3.1.2"),
("3", "3.1", "3.1.3"),
("3", "3.2"),
("3", "3.2", "3.2.1"),
("3", "3.2", "3.2.2"),
("3", "3.2", "3.2.3"),
]
@test all(==(1), table.ncalls)
@test table.isleaf == [
match(r"^(1|2\.[0-9]|3\.[0-9]\.[0-9])$", name[end]) !== nothing for name in table.name
]
@test Tables.schema(table) == Tables.schema(to)
end