Allow for permanent tracking of compilation times #41762

janrous-rai · 2021-08-02T19:47:04Z

In situations where we run long-running server that spends non-trivial amount of time in the compilation we are happy to pay the cost to have this instrumentation always on.

This PR allows us to enable permanent tracking (effectively switching the before/after switches moot) by calling jl_track_compile_time_permanently() method, and then providing jl_cumulative_compile_time_ns_total() to return the total time.

janrous-rai · 2021-08-02T21:23:23Z

fyi @vchuravy, @vtjnash and @IanButterworth who were reviewing Nathan's original re-entrancy PR

NHDaly · 2021-08-26T20:58:56Z

Okay, now that #41733 is merged, i think we can come back to this one. I'll put a bit of work into rebasing this over #41733, since i did touch a bunch of related places.

NHDaly · 2021-08-26T21:33:13Z

Okay, I think i've merged in latest master.

@janrous-rai: I was thinking more about this, and after the changes in #41733, I think this PR now provides two separate things:

Always-on compile time tracking + the ability to fetch the total cumulative time
Restoring the ability to also track per-thread compilation time in addition to the global time we created in Make jl_cumulative_compile_time_ns global (and reentrant). #41733.

For 1., my feeling is: 💯% a great idea, golden, ship it
For 2.: I think i'm also supportive of this? I know that it's probably a bit less useful since 1.7 will be doing task migration, but I also feel like MOAR METRICS, you know? :) I can't think of immediately obvious uses for it, but if it's easy, it seems worth adding.

BUT the main thing i realized is that those two things can be merged separately, since feature 1. is both easier and more excellent. So i'm going to rebase this PR on master, and strip everything out except "Always-on compile time tracking + the ability to fetch the total cumulative time," and then push up a new PR based on this one for feature 2., and we can see how hard that is and whether we want to push on it.

EDIT: I've opened #42018 for 2.

In situations where we run long-running server that spends non-trivial amount of time in the compilation we are happy to pay the cost to have this instrumentation always on. This PR allows us to enable permanent tracking (effectively switching the before/after switches moot) by calling `jl_track_compile_time_permanently()` method, and then providing `jl_cumulative_compile_time_ns_total()` to return the total time. Co-Authored-By: janrous-rai <jan.rous@relational.ai>

… track_compile_time_permanently()

NHDaly

I love it! 😁

At this point, I've written most of it, so probably good to have another set of eyes on it, but yeah, this LGTM!

Thanks for the initial idea, @janrous-rai - i think this is a solid improvement. 👍

Sacha0 · 2021-08-26T22:32:24Z

base/timing.jl

+
+Permanently enable tracking of time spent in compilation by Julia.
+
+Julia has the ability to measure the amount of time spent during compilation (including


during -> on maybe? 🤔

Sacha0 · 2021-08-26T22:33:01Z

base/timing.jl

+Permanently enable tracking of time spent in compilation by Julia.
+
+Julia has the ability to measure the amount of time spent during compilation (including
+type-inference, optimization, llvm optimizaiton, codegen, etc). However, on some systems


type-inference -> type inference I think, and optimizaiton -> optimization? :)

Sacha0 · 2021-08-26T22:33:18Z

base/timing.jl

+
+Julia has the ability to measure the amount of time spent during compilation (including
+type-inference, optimization, llvm optimizaiton, codegen, etc). However, on some systems
+(FreeBSD-based systems are the known problems), this measurment can be too expensive, so


problems -> problem I think? :)

Sacha0 · 2021-08-26T22:34:39Z

base/timing.jl

+
+Calling this function will globally enable tracking the cumulative compilation time.
+
+You can fetch the current total cumulative time spent in compilation by calling:


total cumulative -> cumulative? 🤔

Sacha0 · 2021-08-26T22:35:46Z

base/timing.jl

+"""
+    Base.cumulative_compile_time_ns_total()
+
+The current total cumulative time Julia has spent in compilation, in nanoseconds.


total cumulative -> cumulative? 🤔

Sacha0 · 2021-08-26T22:37:32Z

base/timing.jl

+Otherwise, this function will only return the total time spent in compilation during calls
+to [`Base.@time`](@ref).


Perhaps

Suggested change

Otherwise, this function will only return the total time spent in compilation during calls

to [`Base.@time`](@ref).

Otherwise, this function will return only the time spent in compilation accumulated during all calls

to [`Base.@time`](@ref).

? :)

Sacha0 · 2021-08-26T22:40:53Z

src/jitlayers.cpp

    return jl_atomic_load_relaxed(&jl_cumulative_compile_time);
 }

+extern "C" JL_DLLEXPORT
+uint64_t jl_cumulative_compile_time_ns_total()


Maybe drop the total, redundant with the cumulative? :)

Sacha0 · 2021-08-26T22:44:17Z

src/task.c

@@ -562,10 +562,14 @@ static void JL_NORETURN throw_internal(jl_task_t *ct, jl_value_t *exception JL_M
    ptls->io_wait = 0;
    // @time needs its compile timer disabled on error,
    // and cannot use a try-finally as it would break scope for assignments
-    // We blindly disable compilation time tracking here, for all running Tasks, even though
-    // it may cause some incorrect measurements. This is a known bug, and is being tracked
-    // here: https://github.com/JuliaLang/julia/pull/39138


I guess till #39138 lands (edit: or rather its solution, i.e. #41923), the separate always_measure_compile_time flag has utility in that it ends up being more robust? 🤔

vchuravy · 2021-08-27T13:58:51Z

src/jitlayers.cpp

 {
-    // Increment the flag to allow reentrant callers to `@time`.
+    jl_always_measure_compile_time = 1;


Why do we need a different flag? My intuition would be that you only need to increment jl_measure_compile_time_enabled and never decrement it.

Ah I see due to the jl_throw behaviour...

That is my understanding as well. Perhaps advancing #41923 is in order? :)

Yeah.... i've marked #41923 for #triage.

Now that we've talked about it, i think that would definitely be the better approach than this one, yeah.

janrous-rai · 2021-08-30T06:44:44Z

Looks good, thanks @NHDaly for working through this. Let me know if you would like me to resolve the feedback on this or you consider yourself the new "owner" of this until approved?

Regarding the suggestions about 1. total compile time tracking and 2. per-thread compile time tracking -- I think that (1) is definitely useful and I'm not really sure if (2) has much value. Yes, generally speaking, more metrics is better, but with task migration, threads become even more "opaque" and not really interesting so I would be completely fine with having just the per-process total.

It might still make sense to measure per-thread (or total) compilation contention (waiting on the lock held by other threads) as this likely may result in observable performance loss, but this is for another PR altogether.

NHDaly · 2021-09-02T20:41:59Z

@janrous-rai - yeah, i'll take it over. sorry for the delay. I think waiting for #41923 is definitely better, but it'll have to wait until triage next week. Thanks and sorry

NHDaly · 2021-09-26T20:01:21Z

OKAY, so, now that #41923 is merged, i think we can actually close this PR! 😮

I think users can globabally and permanently enable compilation time tracking by calling Base.cumulative_compile_time_ns_before(), and that's it! :)

You don't need to worry about it getting turned off on an exception, because we've handled that with the try-catch, so if you manually bump the start count with cumulative_compile_time_ns_before(), it'll never turn off. 😊

This was quite a journey, but I'm glad it's settled.

So I'm going to close this PR now! @janrous-rai let me know if I'm missing anything else!
Thanks @Sacha0 and @vchuravy for the help to get here. 💪

janrous-rai mentioned this pull request Aug 2, 2021

Make jl_cumulative_compile_time_ns global (and reentrant). #41733

Merged

NHDaly mentioned this pull request Aug 26, 2021

Add support for measuring compile time per thread #42018

Closed

NHDaly and others added 2 commits August 26, 2021 17:41

Add julia bindings & tests for cumulative_compile_time_ns_total() and…

e4c5b95

… track_compile_time_permanently()

NHDaly force-pushed the jr-compile-time-always-on branch from c41a590 to e4c5b95 Compare August 26, 2021 21:50

Add docstrings

92635f6

NHDaly approved these changes Aug 26, 2021

View reviewed changes

Sacha0 reviewed Aug 26, 2021

View reviewed changes

vchuravy reviewed Aug 27, 2021

View reviewed changes

NHDaly closed this Sep 26, 2021

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Allow for permanent tracking of compilation times #41762

Allow for permanent tracking of compilation times #41762

janrous-rai commented Aug 2, 2021 •

edited by NHDaly

Loading

janrous-rai commented Aug 2, 2021

NHDaly commented Aug 26, 2021

NHDaly commented Aug 26, 2021 •

edited

Loading

NHDaly left a comment

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021

Sacha0 Aug 26, 2021 •

edited

Loading

vchuravy Aug 27, 2021

vchuravy Aug 27, 2021

Sacha0 Aug 27, 2021

NHDaly Sep 2, 2021

janrous-rai commented Aug 30, 2021

NHDaly commented Sep 2, 2021

NHDaly commented Sep 26, 2021


		Permanently enable tracking of time spent in compilation by Julia.

		Julia has the ability to measure the amount of time spent during compilation (including


		Calling this function will globally enable tracking the cumulative compilation time.

		You can fetch the current total cumulative time spent in compilation by calling:

		Otherwise, this function will only return the total time spent in compilation during calls
		to [`Base.@time`](@ref).

Allow for permanent tracking of compilation times #41762

Allow for permanent tracking of compilation times #41762

Conversation

janrous-rai commented Aug 2, 2021 • edited by NHDaly Loading

janrous-rai commented Aug 2, 2021

NHDaly commented Aug 26, 2021

NHDaly commented Aug 26, 2021 • edited Loading

NHDaly left a 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

Sacha0 Aug 26, 2021 • 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

janrous-rai commented Aug 30, 2021

NHDaly commented Sep 2, 2021

NHDaly commented Sep 26, 2021

janrous-rai commented Aug 2, 2021 •

edited by NHDaly

Loading

NHDaly commented Aug 26, 2021 •

edited

Loading

Sacha0 Aug 26, 2021 •

edited

Loading