Show any compile time spent in time and timev macros #37678

IanButterworth · 2020-09-21T00:57:51Z

Adds a report of any compilation time to the @time and @timev macros, as a % of total time

julia> x = rand(10,10);

julia> @time x * x;
  0.606588 seconds (2.19 M allocations: 116.555 MiB, 3.75% gc time, 99.94% compilation time)

julia> @time x * x;
  0.000009 seconds (1 allocation: 896 bytes)

I was wondering if compiler_start_time should be set earlier than it is here, to catch more compiler-related time?

base/timing.jl

DilumAluthge · 2020-09-21T01:34:39Z

This will be a great feature to have!

quinnj · 2020-09-21T01:48:09Z

I agree; this seems like a great idea to help understand where time is being spent.

DilumAluthge · 2020-09-21T02:53:54Z

Question: for the cases in which there was no compilation, does it make sense to print 0% compilation time just for completeness and consistency? Or would that just be noise?

My instinct is that it would be unnecessary. But I just wanted to throw the idea out there.

IanButterworth · 2020-09-21T02:54:17Z

I have an uncommitted macro to return the actual value in seconds, if it's useful? I wasn't sure given the dedicated more detailed timing information that's available as a build option

julia> @compiletime x * x
0.54208595

julia> @compiletime x * x
0.0

DilumAluthge · 2020-09-21T02:55:03Z

Also, is it too late to get this feature into 1.6? I have lost track of time and I have no idea when the feature freeze deadline is for 1.6.

Personally I hope we can get this into 1.6.

DilumAluthge · 2020-09-21T03:00:08Z

I have an uncommitted macro to return the actual value in seconds, if it's useful? I wasn't sure given the dedicated more detailed timing information that's available as a build option
julia> @compiletime x * x
0.54208595

julia> @compiletime x * x
0.0

Nah... I don't think I can come up with a use case in which I would ask for this.

I think the approach you currently have in this PR is more useful.

ericphanson · 2020-09-21T13:05:35Z

I have an uncommitted macro to return the actual value in seconds, if it's useful? I wasn't sure given the dedicated more detailed timing information that's available as a build option

I think it's useful to be able to easily access that info (say, as part of CI to test that compile time didn't explode), but maybe it could be part of @timed instead of a new macro? It seems consistent to put it there anyway, since it has the gc info that @time sometimes shows.

IanButterworth · 2020-09-21T13:27:26Z

I thought about adding it to the end of the output of @timed but it would increase the length of the output tuple, which might be a breaking change?

ericphanson · 2020-09-21T13:33:57Z

True, good question. In #34149 it was made a NamedTuple instead of a Tuple and @StefanKarpinski commented in #34147 (comment) that this was OK since it iterated the values the same. That reasoning would still hold here for unpacking like value, time, bytes, gctime, gcdiff = @timed(...) (since Julia will just drop the last element if you don't iterate it) but maybe this is a bigger change still since if you did something like (1.0, @timed(...)...) for some reason then you'd get a different result now whereas #34149 wouldn't have broken that .

IanButterworth · 2020-09-21T14:03:16Z

wrt. @timed, perhaps it's better to play safe and add a TODO for 2.0? Until then, we could either add @compiletime or the non-exported underlying function could be used:

julia> begin
           before = Base.cumulative_compile_time_ns()
           x - x    # thing to test
           comptime_s =  (Base.cumulative_compile_time_ns() - before) / 1e9
       end
0.072066702
...
0.0

Edit: This is actually an inaccurate approach for timing compilation, as discussed below

IanButterworth · 2020-09-22T14:19:42Z

I guess needs review by @vtjnash / @JeffBezanson ?

IanButterworth · 2020-09-26T23:47:05Z

I've added the @compiletime macro so all ideas here can be reviewed

base/timing.jl

New function added.

This reverts commit 5747bb4.

IanButterworth · 2020-09-28T03:17:37Z

Friendly bump for review/merge 🙏

Note that the additional function add has been reverted

DilumAluthge · 2020-09-28T03:20:42Z

@yuyichao Is this ready to go?

IanButterworth · 2020-09-28T20:57:42Z

I can’t assign reviewers, so if this needs more review can someone please assign the appropriate people

yuyichao

This can probably use a bit more mention in the doc and the C++ code can also use += to be a bit more concise. Neither of these are blocking issues for the PR.

IanButterworth · 2020-09-28T21:31:02Z

Good point. The docstring now reads:

@time

A macro to execute an expression, printing the time it took to execute, the number of
allocations, and the total number of bytes its execution caused to be allocated, before
returning the value of the expression. If the time reported includes time spent doing
garbage collection (gc) or compilation, that will also be highlighted as a %.

See also @timev, @timed, @elapsed, and @allocated.

!!! note
For more serious benchmarking, consider the @btime macro from the BenchmarkTools.jl
package which among other things evaluates the function multiple times in order to
reduce noise.

julia> x = rand(10,10);

julia> @time x * x;
  0.606588 seconds (2.19 M allocations: 116.555 MiB, 3.75% gc time, 99.94% compilation time)

julia> @time x * x;
  0.000009 seconds (1 allocation: 896 bytes)

julia> @time begin
           sleep(0.3)
           1+1
       end
  0.301395 seconds (8 allocations: 336 bytes)
2

DilumAluthge · 2020-09-28T21:33:59Z

@ianshmean Perhaps you could also add a compilation time example to the docstring for the @timev macro?

IanButterworth · 2020-09-29T01:11:29Z

Should be good to go now

base/timing.jl

KristofferC · 2020-09-29T14:23:08Z

Needs whitespace fix.

IanButterworth · 2020-09-29T22:08:48Z

Failures seem unrelated?

KristofferC · 2020-09-30T06:12:52Z

🎉

@eval

As discussed in the comments for JuliaLang#37678, the `% compilation time` metric added to `@time` is not an accurate measurement of the total compilation time. It is in fact excluding any top-level compilation time, which may in fact be quite expensive if the body of your block is fully type stable and inferrable. This change adds a final print to the report for the top-level compilation time that was spent compiling your block. For example: ```julia julia> @eval function f(a) $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end) $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end) return a end f (generic function with 1 method) julia> @time f(2) 0.000000 seconds + 0.474445 seconds top-level compilation time -2.53151813758841e205 julia> x = 2 2 julia> @time f(x) # Inferring with a non-const is slower, but does not happen at top-level, since x is a global whose type cannot be known until runtime. 1.212882 seconds (129.51 k allocations: 4.811 MiB, 100.00% compilation time) -2.53151813758841e205 julia> @time f(x) # But now, subsequent invocations have no compilation time since it's already compiled. 0.000006 seconds (1 allocation: 16 bytes) -2.53151813758841e205 ``` Without this change, the `@time f(2)` call, would have reported `0.0 seconds` with no other context. The following example shows both types of compilation time reported: ```julia julia> @time peakflops() 0.803850 seconds (2.26 M allocations: 181.699 MiB, 4.90% gc time, 84.81% compilation time) + 0.017840 seconds top-level compilation time 1.5840888414049457e11 ``` ---- This change is fairly complex. Here's why: The trouble with the `@time` macro is that the user's code is compiled as _part of_ compiling the enclosing block, so the naive implementation of this change would report _every invocation_ as having some compilation time. To address this, we use a heuristic: we record the time to compile an _empty block_ that simply times an empty statement, and subtract that empty block compilation time from the time to compile the user's block, to get the true user compilation time. We also subtract the inner, dynamic compilation time (the number used to report the percentage), to get the top-level compilation time. Finally, we only report the top-level compilation time if it is suffiently larger than the empty block's compilation time by a ratio threshold, to prevent reporting compilation time due to noisy variance. It's annoyingly tricky, but we think it works, and achieves the best of all the above worlds regarding reporting these metrics. :) The user won't be fooled by `@time` reporting a much shorter time than the actual wall time because we actually spent 5 min inferring the code (this has happened to me in real life, and confused me for days). And the user _also_ won't be confused to see top-level compilation time where they don't expect it. And the total runtime reported remains only the time to execute their function, which is what they likely expect. It's complex, but we think this is a nice balance. :) Co-Authored-By: Valentin Churavy <[email protected]>

@eval

As discussed in the comments for JuliaLang#37678, the `% compilation time` metric added to `@time` is not an accurate measurement of the total compilation time. It is in fact excluding any top-level compilation time, which may in fact be quite expensive if the body of your block is fully type stable and inferrable. This change adds a final print to the report for the top-level compilation time that was spent compiling your block. For example: ```julia julia> @eval function f(a) $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end) $(quote $([:(a = a + a * 10 + (a > 0 ? $i : 0.2)) for i in 1:100]...) end) return a end f (generic function with 1 method) julia> @time f(2) 0.000000 seconds + 0.474445 seconds top-level compilation time -2.53151813758841e205 julia> x = 2 2 julia> @time f(x) # Inferring with a non-const is slower, but does not happen at top-level, since x is a global whose type cannot be known until runtime. 1.212882 seconds (129.51 k allocations: 4.811 MiB, 100.00% compilation time) -2.53151813758841e205 julia> @time f(x) # But now, subsequent invocations have no compilation time since it's already compiled. 0.000006 seconds (1 allocation: 16 bytes) -2.53151813758841e205 ``` Without this change, the `@time f(2)` call, would have reported `0.0 seconds` with no other context. The following example shows both types of compilation time reported: ```julia julia> @time peakflops() 0.803850 seconds (2.26 M allocations: 181.699 MiB, 4.90% gc time, 84.81% compilation time) + 0.017840 seconds top-level compilation time 1.5840888414049457e11 ``` ---- This change is fairly complex. Here's why: The trouble with the `@time` macro is that the user's code is compiled as _part of_ compiling the enclosing block, so the naive implementation of this change would report _every invocation_ as having some compilation time. To address this, we use a heuristic: we record the time to compile an _empty block_ that simply times an empty statement, and subtract that empty block compilation time from the time to compile the user's block, to get the true user compilation time. We also subtract the inner, dynamic compilation time (the number used to report the percentage), to get the top-level compilation time. Finally, we only report the top-level compilation time if it is suffiently larger than the empty block's compilation time by a ratio threshold, to prevent reporting compilation time due to noisy variance. It's annoyingly tricky, but we think it works, and achieves the best of all the above worlds regarding reporting these metrics. :) The user won't be fooled by `@time` reporting a much shorter time than the actual wall time because we actually spent 5 min inferring the code (this has happened to me in real life, and confused me for days). And the user _also_ won't be confused to see top-level compilation time where they don't expect it. And the total runtime reported remains only the time to execute their function, which is what they likely expect. It's complex, but we think this is a nice balance. :) Co-Authored-By: Valentin Churavy <[email protected]>

IanButterworth added 2 commits September 20, 2020 20:42

show any compile time spent in at-time macro

4b22d7d

update at-timev

7c2bd81

yuyichao requested changes Sep 21, 2020

View reviewed changes

base/timing.jl Outdated Show resolved Hide resolved

remove reset_cumulative_compile_time

876e48e

tie timing to codegen locks

bdce083

IanButterworth mentioned this pull request Sep 21, 2020

Update performance tips to be explicit about compilation time practices #37663

Closed

update relevant time reports in docs

306c407

IanButterworth changed the title ~~Show any compile time spent in at-time macro~~ Show any compile time spent in time and timev macros Sep 21, 2020

IanButterworth requested a review from yuyichao September 22, 2020 14:15

yuyichao previously approved these changes Sep 22, 2020

View reviewed changes

add compiletime macro

5747bb4

yuyichao reviewed Sep 26, 2020

View reviewed changes

base/timing.jl Outdated Show resolved Hide resolved

Revert "add compiletime macro"

e1d09a8

This reverts commit 5747bb4.

IanButterworth requested a review from yuyichao September 28, 2020 20:51

yuyichao approved these changes Sep 28, 2020

View reviewed changes

IanButterworth added 2 commits September 28, 2020 17:21

tidy cpp code with +=

27f4c11

replace example in docstring

2eda4e1

update timev example

edcd3a3

KristofferC reviewed Sep 29, 2020

View reviewed changes

base/timing.jl Outdated Show resolved Hide resolved

tweak docstring text and fix whitespace

5362f98

KristofferC added the merge me PR is reviewed. Merge when all tests are passing label Sep 29, 2020

KristofferC merged commit 8ccc4cc into JuliaLang:master Sep 30, 2020

IanButterworth deleted the ib/time_compile_info branch September 30, 2020 11:16

NHDaly mentioned this pull request Oct 8, 2020

Add top-level compile time to at-time report. #37938

Closed

Keno mentioned this pull request Dec 14, 2020

Excessive clock queries causing slowdown on freebsd #38877

Closed

NHDaly mentioned this pull request Dec 15, 2020

🐰 Wrap code in functions to make it faster fonsp/Pluto.jl#720

Merged

DilumAluthge removed the merge me PR is reviewed. Merge when all tests are passing label Jan 11, 2021

NHDaly mentioned this pull request Aug 18, 2021

Fix bug in @time compilation time measurement, using _tryfinally macro. #41923

Merged

IanButterworth mentioned this pull request Jul 3, 2022

add compile times to timed macro #45907

Open

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Show any compile time spent in time and timev macros #37678

Show any compile time spent in time and timev macros #37678

IanButterworth commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020

quinnj commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020 •

edited

Loading

IanButterworth commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020 •

edited

Loading

DilumAluthge commented Sep 21, 2020

ericphanson commented Sep 21, 2020 •

edited

Loading

IanButterworth commented Sep 21, 2020

ericphanson commented Sep 21, 2020

IanButterworth commented Sep 21, 2020 •

edited

Loading

IanButterworth commented Sep 22, 2020

IanButterworth commented Sep 26, 2020

IanButterworth commented Sep 28, 2020 •

edited

Loading

DilumAluthge commented Sep 28, 2020

IanButterworth commented Sep 28, 2020

yuyichao left a comment

IanButterworth commented Sep 28, 2020

DilumAluthge commented Sep 28, 2020

IanButterworth commented Sep 29, 2020

KristofferC commented Sep 29, 2020

IanButterworth commented Sep 29, 2020

KristofferC commented Sep 30, 2020

Show any compile time spent in time and timev macros #37678

Show any compile time spent in time and timev macros #37678

Conversation

IanButterworth commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020

quinnj commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020 • edited Loading

IanButterworth commented Sep 21, 2020

DilumAluthge commented Sep 21, 2020 • edited Loading

DilumAluthge commented Sep 21, 2020

ericphanson commented Sep 21, 2020 • edited Loading

IanButterworth commented Sep 21, 2020

ericphanson commented Sep 21, 2020

IanButterworth commented Sep 21, 2020 • edited Loading

IanButterworth commented Sep 22, 2020

IanButterworth commented Sep 26, 2020

IanButterworth commented Sep 28, 2020 • edited Loading

DilumAluthge commented Sep 28, 2020

IanButterworth commented Sep 28, 2020

yuyichao left a comment

Choose a reason for hiding this comment

IanButterworth commented Sep 28, 2020

DilumAluthge commented Sep 28, 2020

IanButterworth commented Sep 29, 2020

KristofferC commented Sep 29, 2020

IanButterworth commented Sep 29, 2020

KristofferC commented Sep 30, 2020

DilumAluthge commented Sep 21, 2020 •

edited

Loading

DilumAluthge commented Sep 21, 2020 •

edited

Loading

ericphanson commented Sep 21, 2020 •

edited

Loading

IanButterworth commented Sep 21, 2020 •

edited

Loading

IanButterworth commented Sep 28, 2020 •

edited

Loading