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

NHDaly · 2021-08-18T20:16:02Z

This PR reopens @IanButterworth's PR #39138, because in the meantime we've discovered a bug in the @time macro that needs a mechanism like this in order to solve it.

I'll describe the bug below. But first, some context:

Time macros: use tryfinally macro approach #39138 was originally closed because tryfinally is an intermediate form that shouldn't be used in source ASTs.
There is another PR, Add noscope macro to make try blocks evaluate in the local scope #39217, which is in-progress, which will provide the correct way to solve that problem, but that PR is currently stalled.

Since the @time macro is currently broken without this change, and since we know that there is a mechanism on the way (via #39217) that will replace this, it seems to me (and @Sacha0) that this is an expedient solution to the existing bug, without baking-in a reference to the internal intermediate form that we need to maintain. I've left a note in the code that directly states that this macro is deprecated and should not be used, and that a replacement is coming. I've renamed it to @_tryfinally to discourage its use. Hopefully that seems like a reasonable tradeoff to allow us to fix the bug in @time compilation measurement?

Thanks! :)

The PR description follows:

Use a _tryfinally macro to ensure compile timer is closed, while maintaining scope.

This fixes a bug where an exception thrown anywhere, on any Task on
any thread, completely disables the compilation time measurement for any
concurrently executing @time blocks, without warning the user about it.

Here are some examples of the current, broken behavior:

Throwing (and catching) an exception disables compilation time
measurement, even though the exception didn't escape, without warning
the user - note 0 compilation time reported:

julia> @time begin
          # The following exception disables compilation time measurement
          try throw("ha HAH!") catch end
          @eval module M ; f(x) = 2*x ; end
          @eval M.f(2)
      end
  0.003950 seconds (2.17 k allocations: 170.093 KiB)
4

Throwing an exception while the first task is sleeping disables
compilation time measurement, so this ends up incorrectly reporting 0
compilation time:

julia> f(n) = begin
          # while we're sleeping, someone throws an exception somewhere else :'(
          sleep(n)
          @eval module M ; f(x) = 2*x ; end
          @eval M.f(2)
      end
f (generic function with 1 method)

julia> f(0) # warmup
WARNING: replacing module M.
4

julia> @async @time f(5)
Task (runnable) @0x000000010f2c0780

julia> throw("oh no sad")
ERROR: "oh no sad"
Stacktrace:
[1] top-level scope
  @ REPL[9]:1

WARNING: replacing module M.
  5.008401 seconds (1.92 k allocations: 120.515 KiB)

After this commit, both of those examples correctly report their
compilation time.

NHDaly · 2021-08-18T20:29:03Z

For a more complete history:

Show any compile time spent in time and timev macros #37678: originally added a global cumulative_compile_time counter that tracked all compilation time.
- this was determined to be too slow on FreeBSD, since apparently just getting the current time is slow there due to a bug (Excessive clock queries causing slowdown on freebsd #38877).
Measure compile time only when using time macros #38885: So here, Ian introduced the _before() and _after() functions to enable/disable measurement.
- But this meant an exception in the code under @time would leave the flag constantly enabled.
Measure compile time only when using time macros pt.2: handling when code under test throws and make compile timing thread-local #38915: So this PR introduced a try / finally block to disable the flag when an exception is thrown out of the @time block.
- But this didn't work because try-blocks introduce a new scope, so this broke some user code that called @time inside functions. 😞
Remove try from at-time and close compile timer during throw #39133: SO, finally, we removed the try / finally, and just always disable the timing reporting whenever an exception is thrown.

BUT, multithreading / concurrency of course is here to make everything worse.

The approach taken in #39133 was reasonable if there's only ever a single Task on a single Thread. If you're in the middle of a @time block, and someone throws an exception, it's probably reasonable to assume that wasn't intended and just disable the timing. (Although you might get it wrong if the exception was intended, and would have been handled.)

But in a multithreaded world, where people are putting @time statements into functions being executed on different threads (as we do at RelationalAI), an exception anywhere disables the timing for all tasks, which seems definitely bad.

In the following two PRs, we attempted to fix this by using a different version of try / finally that don't introduce scope:

@JeffBezanson said we would prefer the second approach, since :tryfinally is an internal intermediate form and shouldn't be used in source ASTs. But the second PR has stalled, and so I've re-opened the first one now that we are aware of this bug.

If we think we can make progress on #39217 in a relatively short timescale, that's excellent! :) But in the meantime, this PR attempts to fix the bug in an expedient way that we know will currently work, while we wait for the better solution.

Does that sound reasonable?

Thanks for your help! :)

Sacha0

This patch strikes me as a good stopgap solution and seems ready to go. (I am a bit biased though, having been involved in the scheming of this patch, so perhaps at least one neutral party should sign off as well. And perhaps Jeff in particular, given he had reservations about committing a patch like this previously. Maybe @vchuravy would like to take a look, what with #41762 (comment)? :))

Sacha0 · 2021-08-27T15:55:34Z

Looks like a conflict has crept in --- perhaps rebase @NHDaly? :)

base/timing.jl

NHDaly · 2021-09-02T20:23:04Z

I've marked this PR for #triage, given that @JeffBezanson had concerns with this approach the first time around, since ":tryfinally is an internal intermediate form and shouldn't be used in source ASTs."

Please see my description in the comment above, which explains why we are trying this approach again:
#41923 (comment)

Thanks!

JeffBezanson · 2021-09-16T19:17:44Z

base/timing.jl

-        elapsedtime = time_ns() - elapsedtime
+        local val = @__tryfinally($(esc(ex)),
+            (elapsedtime = time_ns() - elapsedtime;
+            compile_elapsedtime = cumulative_compile_time_ns_after() - compile_elapsedtime)


Should the order of these be switched to avoid the possibility of compile time being more than 100%?

Ok, Oscar made the point that we care more about an accurate elapsed time than about compile time fraction, so maybe it's ok.

JeffBezanson · 2021-09-16T19:20:02Z

Ok, I will stop being a purist about this and this can be merged :)

NHDaly · 2021-09-16T19:31:31Z

Awesome, thanks @JeffBezanson! Sorry I didn't make #triage today. Thanks for the flexibility 😊

Sacha0 · 2021-09-16T21:34:44Z

tester_freebsd64 is doing its thing, i.e. failing in various seemingly unrelated ways. The tester_linux32 failures seem to be Profile-related; not sure what to make of those.

@time

Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time. Rename `@tryfinally` to `@_tryfinally` since it shouldn't be used. And add note that it's deprecated and should not be used

Sacha0 · 2021-09-16T21:38:15Z

I hope you don't mind Nathan: I took the liberty of rebasing this pull request (in anticipation of merge) given it's a couple weeks stale and to check whether the tester_linux32 failure occurs again :).

NHDaly · 2021-09-17T01:47:20Z

_amazing_ - not at all. Thank you Sacha, I really appreciate it! :)

…

On Thu, Sep 16, 2021, 5:38 PM Sacha Verweij ***@***.***> wrote: I hope you don't mind Nathan: I took the liberty of rebasing this pull request (in anticipation of merge) given it's a couple weeks stale and to check whether the tester_linux32 failure occurs again :). — You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub <#41923 (comment)>, or unsubscribe <https://github.com/notifications/unsubscribe-auth/AAMCIELOJZLSTVPYBBRLMCLUCJPVFANCNFSM5CMYWHPA> . Triage notifications on the go with GitHub Mobile for iOS <https://apps.apple.com/app/apple-store/id1477376905?ct=notification-email&mt=8&pt=524675> or Android <https://play.google.com/store/apps/details?id=com.github.android&referrer=utm_campaign%3Dnotification-email%26utm_medium%3Demail%26utm_source%3Dgithub>.

@time

…ro. (#41923) Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time. (cherry picked from commit 08e100b)

NHDaly · 2021-09-26T19:27:23Z

🙏 thanks @KristofferC and @Sacha0!

@time

…ro. (#41923) Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time.

@time

…ro. (JuliaLang#41923) Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time.

@time

…ro. (JuliaLang#41923) Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time.

@time

…ro. (JuliaLang#41923) Use a tryfinally macro to ensure compile timer is closed, while maintaining scope. This fixes a bug where an exception thrown _anywhere_, on any Task on any thread, completely disables the compilation time measurement for any concurrently executing `@time` blocks, without warning the user about it. Here are some examples of the current, broken behavior: - Throwing (and catching) an exception disables compilation time measurement, even though the exception didn't escape, without warning the user - note 0 compilation time reported: ```julia julia> @time begin # The following exception disables compilation time measurement try throw("ha HAH!") catch end @eval module M ; f(x) = 2*x ; end @eval M.f(2) end 0.003950 seconds (2.17 k allocations: 170.093 KiB) 4 ``` - Throwing an exception while the first task is sleeping disables compilation time measurement, so this ends up incorrectly reporting 0 compilation time: ```julia julia> f(n) = begin # while we're sleeping, someone throws an exception somewhere else :'( sleep(n) @eval module M ; f(x) = 2*x ; end @eval M.f(2) end f (generic function with 1 method) julia> f(0) # warmup WARNING: replacing module M. 4 julia> @async @time f(5) Task (runnable) @0x000000010f2c0780 julia> throw("oh no sad") ERROR: "oh no sad" Stacktrace: [1] top-level scope @ REPL[9]:1 WARNING: replacing module M. 5.008401 seconds (1.92 k allocations: 120.515 KiB) ``` After this commit, both of those examples correctly report their compilation time.

NHDaly mentioned this pull request Aug 18, 2021

Make jl_cumulative_compile_time_ns global (and reentrant). #41733

Merged

NHDaly requested review from IanButterworth and JeffBezanson and removed request for IanButterworth August 18, 2021 20:29

Sacha0 mentioned this pull request Aug 27, 2021

Allow for permanent tracking of compilation times #41762

Closed

Sacha0 approved these changes Aug 27, 2021

View reviewed changes

vchuravy approved these changes Aug 27, 2021

View reviewed changes

base/timing.jl Outdated Show resolved Hide resolved

NHDaly force-pushed the nhd/time_tryfinally_macro branch from 2ec7f8d to 0d02c59 Compare September 2, 2021 20:16

NHDaly added the triage This should be discussed on a triage call label Sep 2, 2021

JeffBezanson reviewed Sep 16, 2021

View reviewed changes

JeffBezanson removed the triage This should be discussed on a triage call label Sep 16, 2021

KristofferC added the backport 1.7 label Sep 16, 2021

Sacha0 force-pushed the nhd/time_tryfinally_macro branch from 0d02c59 to 171d7f0 Compare September 16, 2021 21:37

KristofferC mentioned this pull request Sep 23, 2021

release-1.7: Backports for 1.7-rc2 #42255

Merged

84 tasks

KristofferC merged commit 08e100b into master Sep 23, 2021

KristofferC deleted the nhd/time_tryfinally_macro branch September 23, 2021 11:29

KristofferC removed the backport 1.7 label Oct 22, 2021

inkydragon mentioned this pull request Aug 14, 2022

@time in global while loop causes internal error #45600

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

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

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

NHDaly commented Aug 18, 2021

NHDaly commented Aug 18, 2021

Sacha0 left a comment

Sacha0 commented Aug 27, 2021

NHDaly commented Sep 2, 2021

JeffBezanson Sep 16, 2021

JeffBezanson Sep 16, 2021

JeffBezanson commented Sep 16, 2021

NHDaly commented Sep 16, 2021

Sacha0 commented Sep 16, 2021

Sacha0 commented Sep 16, 2021

NHDaly commented Sep 17, 2021 via email

NHDaly commented Sep 26, 2021

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

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

Conversation

NHDaly commented Aug 18, 2021

NHDaly commented Aug 18, 2021

Sacha0 left a comment

Choose a reason for hiding this comment

Sacha0 commented Aug 27, 2021

NHDaly commented Sep 2, 2021

JeffBezanson Sep 16, 2021

Choose a reason for hiding this comment

JeffBezanson Sep 16, 2021

Choose a reason for hiding this comment

JeffBezanson commented Sep 16, 2021

NHDaly commented Sep 16, 2021

Sacha0 commented Sep 16, 2021

Sacha0 commented Sep 16, 2021

NHDaly commented Sep 17, 2021 via email

NHDaly commented Sep 26, 2021

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

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