Measure cpu-time and real-time and report both #94

vchuravy · 2018-01-18T22:07:53Z

This still needs some cleanup and the history is a bit messy.
In essence this measures both the time actually spend running on the cpu
and the time passed. If the OS migrates a process the cpu-time won't increase,
while real-time will. Similar for other things like calling into the kernel.

Update docs

jrevels · 2018-01-18T22:20:31Z

src/execution.jl

@@ -314,21 +314,24 @@ function generate_benchmark_definition(eval_module, out_vars, setup_vars, core,
            $(setup)
            __evals = __params.evals
            __gc_start = Base.gc_num()
-            __start_time = time_ns()
+            __start_realtime = BenchmarkTools.Timers.realtime()
+            __start_cputime = BenchmarkTools.Timers.cputime()


Interpolate BenchmarkTools here.

Also, this is awesome!

ararslan · 2018-01-18T22:30:54Z

src/timers/darwin.jl

+const RUSAGE_SELF = Cint(0)
+const RUSAGE_CHILDREN = Cint(-1)
+
+struct timeval


This and rusage should use the standard Julia naming convention of CamelCase for types. So this should be TimeVal and the other should be RUsage.

vchuravy · 2018-01-19T01:35:14Z

src/execution.jl

@@ -409,7 +412,7 @@ macro btime(args...)
        $trialmin = $BenchmarkTools.minimum($trial)
        $trialallocs = $BenchmarkTools.allocs($trialmin)
        println("  ",
-                $BenchmarkTools.prettytime($BenchmarkTools.time($trialmin)),
+                $BenchmarkTools.prettytime($BenchmarkTools.realtime($trialmin)),


Should we print cputime here as well? or cpuratio?

cpuratio seems like a good idea

vchuravy · 2018-01-19T01:35:38Z

src/groups.jl

@@ -81,7 +81,10 @@ Base.median(group::BenchmarkGroup) = mapvals(median, group)
 Base.min(groups::BenchmarkGroup...) = mapvals(min, groups...)
 Base.max(groups::BenchmarkGroup...) = mapvals(max, groups...)

-Base.time(group::BenchmarkGroup) = mapvals(time, group)
+import Base: time
+@deprecate time(group::BenchmarkGroup) realtime(group)


The @deprecate should be moved to a central location

vchuravy · 2018-01-19T01:36:44Z

src/trials.jl

@@ -4,53 +4,59 @@

 mutable struct Trial
    params::Parameters
-    times::Vector{Float64}
+    realtimes::Vector{Float64} #TODO: rename to realtimes


remove todo

vchuravy · 2018-01-19T01:36:51Z

src/timers/windows.jl

+
+    err = ccall(:GetProccessTimes, Cint, (HANDLE, Ref{FileTime}, Ref{FileTime}, Ref{FileTime}, Ref{FileTime}), 
+                                proc, creation_time, exit_time, kernel_time, user_time)
+    # TODO: Error handling


add error handling

vchuravy · 2018-01-19T01:37:02Z

src/timers/windows.jl

+end
+
+@inline function realtime()
+    # counter = Ref{UInt64}()


delete dead code

vchuravy · 2018-01-19T01:37:18Z

src/timers/darwin.jl

+@inline function cputime()
+    ru = Ref{rusage}()
+    err = ccall(:getrusage, Cint, (Cint, Ref{rusage}), RUSAGE_SELF, ru)
+    # TODO error check


add error handling

vchuravy · 2018-01-19T01:39:28Z

src/trials.jl

    memory::Symbol
 end

 function TrialJudgement(r::TrialRatio)
    ttol = params(r).time_tolerance
    mtol = params(r).memory_tolerance
-    return TrialJudgement(r, judge(time(r), ttol), judge(memory(r), mtol))
+    return TrialJudgement(r, judge(realtime(r), ttol), judge(cputime(r), ttol), judge(memory(r), mtol))


@jrevels I think using the same tolerance for cputime and realtime should be ok, right?

Sure, the tolerance is a fudge number anyway.

vchuravy · 2018-01-19T01:41:21Z

src/BenchmarkTools.jl

@@ -10,7 +10,13 @@ if VERSION >= v"0.7.0-DEV.3052"
    using Printf
 end

-const BENCHMARKTOOLS_VERSION = v"0.2.2"
+const BENCHMARKTOOLS_VERSION = v"0.3.0"


@ararslan Note that I think this is a big enough change the we should bump the minor number, but I can remove this from this PR.

I think it's fine to have in this PR. Even though this is recorded in the JSON stuff used by Nanosoldier, the version isn't actually used by anything AFAIK. Thanks for the heads up!

vchuravy · 2018-01-19T01:48:46Z

src/trials.jl

-Base.show(io::IO, t::TrialEstimate) = print(io, "TrialEstimate(", prettytime(time(t)), ")")
-Base.show(io::IO, t::TrialRatio) = print(io, "TrialRatio(", prettypercent(time(t)), ")")
-Base.show(io::IO, t::TrialJudgement) = print(io, "TrialJudgement(", prettydiff(time(ratio(t))), " => ", time(t), ")")
+Base.show(io::IO, t::Trial) = print(io, "Trial(", prettytime(realtime(t)), ")")


Should these show methods include cputime?

maybe cpuratio

On playing with it I think it is not necessary.

vchuravy · 2018-01-19T18:20:53Z

The code in timers is mostly taken from google/benchmark and that is under Apache v2.0. The code is fairly basic, but in order to make sure I retained the copyright notice as mandated by the Apache License.
So the whole Timers module is under Apache v2

ararslan · 2018-01-19T18:54:57Z

I don't think the Apache license mandates that derived works be licensed under Apache; as I understand it it's like MIT in that you just need to preserve the original license when distributing the original code (in whole or in part). So in this case I think it's worth acknowledging that the code is derived from Google stuff but I don't think it requires a separate license.

vchuravy · 2018-01-19T19:17:29Z

The Apache license does mandate that derived works keep the license notice intact and include a copy of the license and mention all modifications...

"Derivative Works" shall mean any work, whether in Source or Object form, that is based on (or derived from) the Work and for which the editorial revisions, annotations, elaborations, or other modifications represent, as a whole, an original work of authorship. For the purposes of this License, Derivative Works shall not include works that remain separable from, or merely link (or bind by name) to the interfaces of, the Work and Derivative Works thereof.

a; You must give any other recipients of the Work or Derivative Works a copy of this License; and
b; You must cause any modified files to carry prominent notices stating that You changed the files; and
c; You must retain, in the Source form of any Derivative Works that You distribute, all copyright, patent, trademark, and attribution notices from the Source form of the Work, excluding those notices that do not pertain to any part of the Derivative Works; and

So yeah, I would go for the conservative option and consider a translation of code a derivative work.

ararslan · 2018-01-19T19:19:14Z

Right, we just need to include or link to their license, we don't have to license our own under Apache.

vchuravy · 2018-01-19T21:06:50Z

That is contrarian to my understanding of the license.

I translated code under the Apache license to Julia, therefore creating a derivative work. According to the license I must a; keep the license notice, b; include a prominent notice that I changed the files and c; I must give any recipient a copy of the license.

So the code under src/timers is Apache licensed and everything else is MIT.

ararslan · 2018-01-19T21:09:46Z

It's not a copyleft license; derivative works don't need to bear the same license. See https://www.whitesourcesoftware.com/whitesource-blog/top-10-apache-license-questions-answered/.

vchuravy · 2018-01-19T22:05:46Z

Ok, changed the license to MIT, while complying with the Apache requirement of retaining the license notices.
This is pretty much ready to merge from my side.

ararslan

Looks good to me. Thanks Valentin, this is really exciting!

vchuravy · 2018-01-19T22:26:35Z

I would appreciate if people on arcane platforms like Windows or Mac could give this I try. This should work on more reasonable platforms like a current FreeBSD.
But I personally have only tested this on Linux 64bit.

src/timers/windows.jl

vchuravy · 2018-01-19T23:41:03Z

Let's hold merging this for now. I got a report that this reports odd things on Windows.

doc/manual.md

ararslan · 2018-01-20T00:03:32Z

Confirmed that tests pass on current Julia master on FreeBSD 11.1.

KristofferC · 2018-01-22T09:05:52Z

doc/manual.md

@@ -96,11 +110,11 @@ returns the minimum time in seconds.

 ```julia
 julia> @btime sin(1)
-  13.612 ns (0 allocations: 0 bytes)


I wonder if the GC percentage is worth showing when there are 0 allocations

This code is based on the `google/benchmarks` repository. - `realtime` is a monotonic high-resolution clock provided by the kernel. In most cases this is equivalent to `time_ns` in `Base`. - `cputime` is the time that the process was actually running on a processor. This excludes time spend in the kernel and time spend descheduled. The `Timers` module includes a fair-amount of platform specific code so the implementation is split between a generic *unix* implementation based on the high-resoltion clocked provided through `clock_gettime`. On *darwin* prior to 10.12.0 the kernel only provides `CLOCK_MONOTONIC` making it less useful and we have to fallback onto `getRUsage`. We intentional don't do error handling for the timer calls. Which may or may not be a wise choice.

Renames `times` and `time` to `realtime` and `realtimes` throughout and adds `cputime` and `cputimes`. Real-time is the actual monotonic run time of the code and cpu-time is the time spend in userspace running on processor. ``` julia> @Btime sin(1) 7.572 ns [100.00% CPU, 0.00% GC] (0 allocations: 0 bytes) 0.8414709848078965 julia> @Btime sleep(1) 1.002 s [0.01% CPU, 0.00% GC] (5 allocations: 192 bytes) ```

`:GetProcessTimes` has a resolution of `100ns` which is much worse than the resolution of the high-precision clock.

vchuravy · 2018-01-23T01:32:34Z

Ok hunted down the Windows issue and updated the docs. It turns out the accuracy of the windows counters is only 100ns and so the information becomes fairly useless for short functions.
Jarrett and I discussed a variety of possibilities to deal with this, but in the end we decided to simply turn off printing for cpu-time on Windows.

vchuravy · 2018-01-23T15:29:55Z

I was informed that I missed https://msdn.microsoft.com/en-us/library/windows/desktop/ms684929(v=vs.85).aspx (https://msdn.microsoft.com/en-us/library/windows/desktop/dn553408(v=vs.85).aspx) and so there is hope that we get accurate timings on windows after all.

vchuravy · 2018-01-24T22:59:47Z

So I am currently blocked on converting the cycles to a reasonable time.

tsc_invariant/tsc_constant are necessary http://oliveryang.net/2015/09/pitfalls-of-TSC-usage/
tsc_invariant is on Nehalem-and-later
Getting the TSC frequency is tricky.
Reading MSR_PLATFORM_INFO [15:8] through the rdmsr instruction, which can't be executed in user-space.
Reading through the Intel Manual I noticed that there is a section for cpuid Time Stamp Counter and Nominal Core Crystal Clock Information Leaf which has the necessary information sometimes...

function cpuid(infoType)
         info = Ref{NTuple{4, UInt32}}()
         ccall(:jl_cpuid, Cvoid, (Ref{NTuple{4, UInt32}}, UInt32), info, infoType)
         info[]
end
tsc_invariant() = cpuid(0x80000007)[4] == 0x00000100
function tsc_freq()
          info = cpuid(0x15)
          if info[1] == 0 || info[3] == 0
            return nothing
          else
             return info[2] / info[1] * info[3]
          end
end

and on my machine info[3] == 0
The manual specifies:

TSC_Value = (ART_Value * CPUID.15H:EBX[31:0] )/ CPUID.15H:EAX[31:0] + K

jrevels · 2018-01-25T16:05:33Z

So I am currently blocked on converting the cycles to a reasonable time.

We can always merge this without the Windows-specific improvements (and just print N/A or w/e for cpu-time on Windows), and include the improvements in a future PR once they're ready.

a `Measurement` is a a given timestamp (which can measure multiple things) a `MeasurementDelta` is the difference between two `Measurements` and currently trackes real-time and the ratio of cpu-time/real-time. All the conversion and calculation is part of MeasurementDelta so that it is 'cheap' to obtain a Measurement. As an example currently we convert every `time_ns` to Float64 which we can delay using this notion of a MeasurementDelta.

vchuravy · 2018-01-25T17:13:34Z

I have to double check that the frequency of QueryProcessCycleTime and QueryPerformanceCounter are the same, but otherwise I found a workable solution for Windows.

I will let this stew for a bit and focus other work.

vchuravy · 2018-01-25T17:14:05Z

src/timers/windows.jl

+    function Measurement()
+        proc = currentprocess()
+        time = perfcounter()
+        cpu = cpucycles()


cpucyles(proc)

goretkin · 2020-01-27T20:20:17Z

This feature is very exciting. Is there any technical issue that is preventing this PR from being merged?

It seems even as far as CPU Time goes, there may be multiple measures in certain OSes (e.g. https://linux.die.net/man/2/getrusage mentions RUSAGE_THREAD) for measuring per-thread times, too, which might suggest there's room for more features in future PRs.

vchuravy · 2022-01-20T17:08:16Z

This feature is very exciting. Is there any technical issue that is preventing this PR from being merged?

I think I got annoyed at Windows, but I don't recall the details anymore.

gdalle · 2023-06-13T05:23:57Z

Hey @vchuravy, you made me a maintainer, now you deal with the fallout 😈
This is a pretty old PR with a lot of unresolved conversations, how mergeable do you think it is (provided we can update the branch)?
If the Windows version is not ready, I agree with what @jrevels said:

We can always merge this without the Windows-specific improvements (and just print N/A or w/e for cpu-time on Windows), and include the improvements in a future PR once they're ready.

vchuravy · 2023-06-14T01:09:07Z

I think having something like this would still be valuable, over the years I have been debating what the best level of integrations might be, experimenting with LIKWID.jl and LinuxPerf.jl (@carstenbauer ) might have opinions as well.

You can see this PR as an item on my to-do list (but its pretty much at the bottom of the priority queue), or as an invitation and initial stub for someone else to implement it.

willow-ahrens · 2024-05-10T20:03:30Z

What's the difference between Timers and https://github.com/schmrlng/CPUTime.jl ?

willow-ahrens · 2024-05-10T20:05:02Z

@Zentrik what do you think of this PR?

vchuravy · 2024-05-11T15:01:23Z

What's the difference between Timers and https://github.com/schmrlng/CPUTime.jl ?

The code here precedes that package, and looking at the details my old code here should have lower overhead than the code in CPUTime.jl

willow-ahrens · 2024-05-11T16:06:54Z

Would there be a maintainability difference? Should we contribute this code to that package?

giordano · 2024-12-12T16:41:35Z

I think having something like this would still be valuable

For what is worth, these days I've been looking into bad scaling observed on certain system and using code from this PR to measure cpu-time vs real-time was very useful to gain more insights about was going on.

jrevels reviewed Jan 18, 2018

View reviewed changes

ararslan reviewed Jan 18, 2018

View reviewed changes

vchuravy commented Jan 19, 2018

View reviewed changes

vchuravy force-pushed the vc/timer branch from ea06cfa to c618a2d Compare January 19, 2018 18:06

vchuravy force-pushed the vc/timer branch from 2fc2383 to 6b6559a Compare January 19, 2018 20:53

vchuravy changed the title ~~[RFC/WIP] Measure cpu-time and real-time and report both~~ Measure cpu-time and real-time and report both Jan 19, 2018

vchuravy mentioned this pull request Jan 19, 2018

update to BenchmarkTools v0.3.0 JuliaCI/Nanosoldier.jl#45

Closed

vchuravy force-pushed the vc/timer branch from 6b6559a to 4846b04 Compare January 19, 2018 22:04

ararslan approved these changes Jan 19, 2018

View reviewed changes

amellnik reviewed Jan 19, 2018

View reviewed changes

src/timers/windows.jl Outdated Show resolved Hide resolved

vchuravy commented Jan 19, 2018

View reviewed changes

doc/manual.md Outdated Show resolved Hide resolved

KristofferC reviewed Jan 22, 2018

View reviewed changes

vchuravy added 7 commits January 22, 2018 19:20

update internal version to v0.3.0 due to API change

8d0dc17

update manual

2d18443

add license notice to files under src/

e4c3ce8

Update docs and disable printing of cpu-time

b6ae23c

`:GetProcessTimes` has a resolution of `100ns` which is much worse than the resolution of the high-precision clock.

add simple sanity checks

d7db0bf

vchuravy force-pushed the vc/timer branch from dd07bff to d7db0bf Compare January 23, 2018 00:20

vchuravy commented Jan 25, 2018

View reviewed changes

vchuravy mentioned this pull request Oct 6, 2018

Missing benchmark output explanation #120

Open

vchuravy mentioned this pull request Oct 30, 2018

stop printing "humanized" time units #125

Open

vchuravy mentioned this pull request Nov 14, 2018

[RFC/WIP] Tools for measuring cycles and cpu_times and tricking out LLVM #92

Draft

vchuravy mentioned this pull request Apr 19, 2020

make sure that nullfunc is not ellided #164

Merged

This was referenced Oct 24, 2022

counting cycles in GC JuliaCI/GCBenchmarks#50

Closed

observability: add CPU time counter to tasks JuliaLang/julia#47351

Closed

gdalle marked this pull request as draft June 14, 2023 05:27

Measure cpu-time and real-time and report both #94

Are you sure you want to change the base?

Measure cpu-time and real-time and report both #94

Conversation

vchuravy commented Jan 18, 2018 • edited Loading

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

vchuravy commented Jan 19, 2018

ararslan commented Jan 19, 2018 • edited Loading

vchuravy commented Jan 19, 2018

ararslan commented Jan 19, 2018

vchuravy commented Jan 19, 2018

ararslan commented Jan 19, 2018

vchuravy commented Jan 19, 2018

ararslan left a comment

Choose a reason for hiding this comment

vchuravy commented Jan 19, 2018

vchuravy commented Jan 19, 2018

ararslan commented Jan 20, 2018

Choose a reason for hiding this comment

vchuravy commented Jan 23, 2018 • edited Loading

vchuravy commented Jan 23, 2018

vchuravy commented Jan 24, 2018 • edited by ararslan Loading

jrevels commented Jan 25, 2018

vchuravy commented Jan 25, 2018

Choose a reason for hiding this comment

goretkin commented Jan 27, 2020

vchuravy commented Jan 20, 2022

gdalle commented Jun 13, 2023

vchuravy commented Jun 14, 2023 • edited Loading

willow-ahrens commented May 10, 2024

willow-ahrens commented May 10, 2024

vchuravy commented May 11, 2024 • edited Loading

willow-ahrens commented May 11, 2024

giordano commented Dec 12, 2024

vchuravy commented Jan 18, 2018 •

edited

Loading

ararslan commented Jan 19, 2018 •

edited

Loading

vchuravy commented Jan 23, 2018 •

edited

Loading

vchuravy commented Jan 24, 2018 •

edited by ararslan

Loading

vchuravy commented Jun 14, 2023 •

edited

Loading

vchuravy commented May 11, 2024 •

edited

Loading