Report any recompilation in time macro

[IanButterworth]

It may be helpful if @time indicates if any of the compilation time was recompilation, i.e. of invalidated methods. If the % is high the user could use the SnoopCompile tooling to see what's happening, for instance.

I'm not sure the heuristic is correct or broad-enough here Updated after review. It appears to work with the example from the SnoopCompile manual.

Note the final report here (updated)

julia> f(::Real) = 1; callf(container) = f(container[1]); call2f(container) = callf(container);

julia> c64  = [1.0]; c32 = [1.0f0]; cabs = AbstractFloat[1.0];

julia> @time call2f(c64)
  0.003696 seconds (1.50 k allocations: 104.287 KiB, 99.54% compilation time)
1

julia> @time call2f(c32)
  0.004363 seconds (1.49 k allocations: 102.053 KiB, 99.48% compilation time)
1

julia> @time call2f(cabs)
  0.005143 seconds (1.94 k allocations: 133.236 KiB, 99.63% compilation time)
1

julia> f(::Float64) = 2;

julia> @time call2f(c64)
  0.004225 seconds (1.48 k allocations: 101.584 KiB, 99.80% compilation time: 100% of which was recompilation)
2

[IanButterworth]

Currently the report is a little wordy. But the two %'s need explaining, given the 2nd is % of the first

99.80% compilation time of which 100% was recompilation

It could just be two separate categories, so the above would show as

99.80% recompilation time

And in an imaginary case, one might have

89.00% compilation time, 10.80% recompilation time

[timholy]

I like your alternative display proposal and would recommend switching to it, but other than that and a little small stuff, this LGTM.

[IanButterworth]

Updated to two separate categories for compilation and recompilation

  0.004748 seconds (1.94 k allocations: 133.236 KiB, 99.59% compilation time)
  0.004283 seconds (1.48 k allocations: 101.584 KiB, 99.84% recompilation time)
  0.004283 seconds (1.48 k allocations: 101.584 KiB, 57.04% compilation time, 24.23% recompilation time)

They are a little visually similar, especially when only one shows. I guess if that turns out to be confusing some formatting can be added

[IanButterworth]

An example for Flux v0.13.0:

julia> @time @eval using Flux
 13.176179 seconds (21.10 M allocations: 1.468 GiB, 3.85% gc time, 26.20% compilation time, 29.37% recompilation time)

(requires an update to ChainRules, which uses an internal that changed here)

[antoine-levitt]

Very cool change! The new wording feels more confusing than the former to me, because recompilation is compilation, and so it's not clear whether the second number is a percentage of the first or not. The "of which" makes that clearer. "X% precompilation, Y% recompilation" could disambiguate, but it risks confusion with the (somewhat orthogonal if I understand correctly) notion of package precompilation

[IanButterworth]

Perhaps the refined alternative is

julia> @time @eval using Flux
 13.176179 seconds (21.10 M allocations: 1.468 GiB, 3.85% gc time, 55.57% compilation time of which 52% was recompilation)

[vtjnash]

seems a reasonable approximation

[vchuravy]

13.176179 seconds (21.10 M allocations: 1.468 GiB, 3.85% gc time, 55.57% compilation time of which 52% was recompilation)

52% of total or 52% of 55.57%?

[IanButterworth]

52% of 55.57%

Yeah, there must be a concise way to express this clearly..

[IanButterworth]

Best I can come up with is

13.176179 seconds (21.10 M allocations: 1.468 GiB, 3.85% gc time, 55.57% compilation time: 52% of which was recompilation)

i.e. ~half of the compile time was recompilation

[gbaraldi]

This last option seems very concise but also clear IMO

[IanButterworth]

Great. I think I might make 100% print as "all".

13.176179 seconds (21.10 M: 1.468 GiB, 3.85% gc time, 55.57% compilation time: all of which was recompilation)

And 0% just

13.176179 seconds (21.10 M: 1.468 GiB, 3.85% gc time, 55.57% compilation time)

[IanButterworth]

Maybe this is just as clear? The : may be doing the heavy lifting.

13.176179 seconds (21.10 M: 1.468 GiB, 3.85% gc time, 55.57% compilation time: all recompilation)

13.176179 seconds (21.10 M: 1.468 GiB, 3.85% gc time, 55.57% compilation time: 52% recompilation)

13.176179 seconds (21.10 M: 1.468 GiB, 3.85% gc time, 55.57% compilation time)

[antoine-levitt]

Or get rid of the outer parentheses to use them here:

13.176179 seconds, 21.10 M (1.468 GiB) allocs, 3.85% gc time, 55.57% compilation time (52% recompilation)

Still not completely clear to me whether the 52% is of the 55% or of 100... Not sure adding "of which" takes up that much more space (there would be value in staying within 80 columns, but there's no chance of that happening with the extra information)

[gbaraldi]

I wouldn't use the word all, I think keeping the printing as consistent as possible is better, so 100%

[IanButterworth]

There seems to be slightly more support for the current format over others, so I'll merge and adjustments can be made if improvements are identified in the wild.

[NHDaly]

@IanButterworth: doesn't this need to call cumulative_compile_timing(true) here as well, to enable compilation timing?

Otherwise, I think this is currently wrong: i think the transformation here isn't enabling compilation time tracking, so you'll probably always see 0 compilation time, unless compilation time tracking is already enabled?

I guess we must not have any tests for this, specifically? :(

[IanButterworth]

Ah yes. My bad. Fix here. Haven't run the tests yet, might need work #46100

[NHDaly]

@IanButterworth this is super cool! :) 🎉

It seems like maybe there's a small bug here, where we aren't disabling is_recompile when compiling the transitive dependency that actually caused the invalidation?

Notice how in this example, both of the last two compilations of foo() are 100% of which was recompilation, whereas in the last example, actually half of its time its compiling bar(), which isn't technically recompilation, but rather regular compilation, right? At least, it's treated as regular compilation when just compiling @eval bar() directly. So i think they should be consistent, and the last one should be something like 50% recompilation!

julia> foo() = bar()
foo (generic function with 1 method)

julia> bar() = 2
bar (generic function with 1 method)

julia> @time @eval foo()
  0.000281 seconds (805 allocations: 52.906 KiB, 48.30% compilation time)
2

julia> bar() = 3
bar (generic function with 1 method)

julia> @time @eval bar()
  0.000241 seconds (392 allocations: 26.141 KiB, 31.56% compilation time)
3

julia> @time @eval foo()
  0.000379 seconds (454 allocations: 28.562 KiB, 50.04% compilation time: 100% of which was recompilation)
3

julia> bar() = 4
bar (generic function with 1 method)

julia> @time @eval foo()
  0.000293 seconds (798 allocations: 52.406 KiB, 47.01% compilation time: 100% of which was recompilation)
4

What do you think? Should I open a separate issue to discuss this?

[IanButterworth]

Seems worth an issue, yeah

[NHDaly]

Thanks. Opened #46101.