inference/LLVM codegen/native codegen time split

[bkamins]

If I understand things correctly SnoopCompile.jl currently allows to dig into inference timings. It would be great to be able to similarly dig into LLVM codegen and native codegen timings.

This is relevant for packages like DataFrames.jl, where in many cases it is LLVM codegen and/or native codegen timing a chief time of running some functions (and this is unavoidable since for many functions users pass anonymous functions as an argument).

An example of such a case is here: JuliaData/DataFrames.jl#2806

[NHDaly]

@bkamins you already currently can dig into LLVM optimization and native codegen timings, via @snoopl and @snoopc.

We haven't written big blog posts about those yet, I think, but there is at least some information in the documentation site:

• Snoopc: https://timholy.github.io/SnoopCompile.jl/stable/snoopc/
• Snoopl currently only has these two docstrings:
  • https://timholy.github.io/SnoopCompile.jl/stable/reference/#SnoopCompileCore.@snoopl
  • https://timholy.github.io/SnoopCompile.jl/stable/reference/#SnoopCompile.read_snoopl

Part of the difficultly, though, is that the signal you get from those two measurements is less useful than the signal you get from @snoopi_deep.

This is because for inference, julia currently performs type inference via a depth-first traversal, so by measuring trace spans, we get a nice flamegraph that you can look at, to understand both inclusive and exclusive inference timings.

For LLVM optimization on the other hand, we pass functions through LLVM optimization in a somewhat random order, batched together arbitrarily, which makes it more difficult to account optimization time to individual functions. @snoopl currently emits:

1. An array of Pairs of: the amount of time compiling each "batch", or module, and the type signature for the method instances in that module.
2. A Dict of before/after statistics about each method instance in the module, mapping type signature to stats like number of instructions before/after optimization.

And finally, I believe @snoopc provides a mapping of the time to codegen each method instance.

---

Hope that's helpful! :) If you find any of of that useful, documentation PRs are always welcome ❤️ :)

[bkamins]

you already currently can dig into LLVM optimization and native codegen timings, via @snoopl and @snoopc.

The problem is that they start a new Julia session and I need to run them in an already running session so that I do not measure the cost of first compilation. I am interested only in consecutive compilation times. Is this possible?

[bkamins]

Reproducible example on Julia nightly:

               _
   _       _ _(_)_     |  Documentation: https://docs.julialang.org
  (_)     | (_) (_)    |
   _ _   _| |_  __ _   |  Type "?" for help, "]?" for Pkg help.
  | | | | | | |/ _` |  |
  | | |_| | | | (_| |  |  Version 1.8.0-DEV.262 (2021-07-24)
 _/ |\__'_|_|_|\__'_|  |  Commit 0cbb6850fb (0 days old master)
|__/                   |

julia> using DataFrames, SnoopCompile, Statistics

julia> d = DataFrame(n = 1:20, x = [3, 3, 3, 3, 1, 1, 1, 2, 1, 1,
                                    2, 1, 1, 2, 2, 2, 3, 1, 1, 2]);

julia> g = groupby(d, :x);

julia> subset(g,  :n => (n -> n .> mean(n))); # compile

julia> select(g,  :n => (n -> n .> mean(n))); # compile

julia> @snoopi_deep begin
           subset(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.117688/0.189961 on Core.Compiler.Timings.ROOT() with 15 direct children

julia> @snoopi_deep begin
           subset(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.111079/0.182713 on Core.Compiler.Timings.ROOT() with 15 direct children

julia> @snoopi_deep begin
           subset(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.113283/0.185833 on Core.Compiler.Timings.ROOT() with 15 direct children

julia> @snoopi_deep begin
           subset(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.112419/0.182522 on Core.Compiler.Timings.ROOT() with 15 direct children

julia> @snoopi_deep begin
           select(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.085624/0.144820 on Core.Compiler.Timings.ROOT() with 7 direct children

julia> @snoopi_deep begin
           select(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.082723/0.141071 on Core.Compiler.Timings.ROOT() with 7 direct children

julia> @snoopi_deep begin
           select(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.081279/0.139118 on Core.Compiler.Timings.ROOT() with 7 direct children

julia> @snoopi_deep begin
           select(g,  :n => (n -> n .> mean(n)))
       end
InferenceTimingNode: 0.081399/0.132495 on Core.Compiler.Timings.ROOT() with 7 direct children

And I am discussing the difference between ~0.11 for subset and ~0.08 for select (the first number reported; I do not care now about inference). I would like to know how to diagnose what causes the difference. Thank you!

[NHDaly]

Ah, I understand! Yes, I fully agree!! I actually have a branch on my laptop that adds support for this, but never pushed it up for some dumb reason...

I'm out for the day, but when I get home tomorrow I'll push the branch up and open a PR, and maybe you can help me wrap it up and get it over the finish line? :)

Basically it's just adding flag to all those functions that control whether to run the measurements in a separate process or in the current one.

And then I had a mega-function, I think I called it @snoo_all which runs all the analyses together in the same process. :)

Will find it and push it up tomorrow!

[bkamins]

Excellent. Thank you! Please ping me in the PR.

[timholy]

There's definitely some weird recompilation going on.

@snoopi_deep begin
              select(g,  :n => (n -> n .> mean(n)))
          end

seems to reinfer

mean(::SubArray{Int64, 1, Vector{Int64}, Tuple{SubArray{Int64, 1, Vector{Int64}, Tuple{UnitRange{Int64}}, true}}, false})

every time. It doesn't seem to be constant-prop. However,

julia> function mymean(v)
           s = zero(eltype(v))
           for item in v
               s += item
           end
           return s/length(v)
       end

doesn't show exactly the same thing (the broadcasting part gets reinferred, but not mymean).

[timholy]

(You can display the result in a flamegraph and click on the bars in ProfileView.) You can also find it in print_tree(tinf).

[timholy]

I still don't know what's going on at the level of the compiler, but if I make this change:

~/.julia/dev/DataFrames$ git diff
diff --git a/src/groupeddataframe/callprocessing.jl b/src/groupeddataframe/callprocessing.jl
index 740a9df7..d0c079b4 100644
--- a/src/groupeddataframe/callprocessing.jl
+++ b/src/groupeddataframe/callprocessing.jl
@@ -87,7 +87,7 @@ function do_call(f::Base.Callable, idx::AbstractVector{<:Integer},
     end
 end
 
-function do_call(f::Base.Callable, idx::AbstractVector{<:Integer},
+function do_call(@nospecialize(f::Base.Callable), idx::AbstractVector{<:Integer},
                  starts::AbstractVector{<:Integer}, ends::AbstractVector{<:Integer},
                  gd::GroupedDataFrame, incols::Tuple{AbstractVector}, i::Integer)
     idx = view(idx, starts[i]:ends[i])

then I cut the time roughly in half and I don't recompile mean. Inference profile looks like this:

which is a case in which inference is no longer a substantial bottleneck.

[bkamins]

But if you do @nospecialize here we will have a dynamic dispatch inside this function (and do_call is the only compute intensive part of the whole process).

I think it is better to benchmark the decision about adding @nospecialize using this source data frame:

d = DataFrame(n = 1:100_000_000, x = repeat(1:1_000_000, 100));

as in it we call do_call 10^6 times.

[bkamins]

In this case this indeed improves performance (which is strange):
released version timings

julia> @time select(g,  :n => (n -> n .> mean(n)));
  3.737252 seconds (9.80 M allocations: 2.932 GiB, 19.78% gc time, 5.48% compilation time)

julia> @time select(g,  :n => (n -> n .> mean(n)));
  3.757369 seconds (9.80 M allocations: 2.932 GiB, 18.96% gc time, 5.96% compilation time)

your proposal with @nospecialize timings:

julia> @time select(g,  :n => (n -> n .> mean(n)));
  3.694405 seconds (10.07 M allocations: 2.971 GiB, 16.48% gc time, 3.56% compilation time)

julia> @time select(g,  :n => (n -> n .> mean(n)));
  3.699847 seconds (10.07 M allocations: 2.971 GiB, 19.24% gc time, 3.44% compilation time)

But if we use a simpler function the situation is reversed:
released version timings:

julia> @time select(g,  :n => x -> first(x));
  2.427769 seconds (187.73 k allocations: 3.751 GiB, 18.02% gc time, 6.28% compilation time)

julia> @time select(g,  :n => x -> first(x));
  2.475404 seconds (187.72 k allocations: 3.751 GiB, 22.28% gc time, 5.05% compilation time)

your proposal with @nospecialize timings:

julia> @time select(g,  :n => x -> first(x));
  2.563807 seconds (2.19 M allocations: 3.840 GiB, 20.53% gc time, 4.47% compilation time)

julia> @time select(g,  :n => x -> first(x));
  2.664046 seconds (2.19 M allocations: 3.840 GiB, 20.78% gc time, 4.52% compilation time)

[timholy]

Thanks for specifying a case where the performance might matter. I don't think do_call is such a performance hotspot: it is getting called by dynamic dispatch from within _combine_process_pair, so I don't think it matters if you just defer that runtime dispatch to something within do_call. The ideal circumstance is that you delay runtime dispatch until something that is intrinsically expensive; from what I can tell, do_call just calls f(column_view) and so it's not doing anything element-wise and so shouldn't be performance-sensitive.

I hadn't noticed until I found the caller just by inserting an error that you're using tasks. That may help me figure out a MWE for the compiler issue.

[bkamins]

_combine_process_pair calls it only once so it does not matter, but it gets called in a hot loop in two other places:

• https://github.com/JuliaData/DataFrames.jl/blob/32b86d460f0a77254e4e73af6072ee5109b87885/src/groupeddataframe/complextransforms.jl#L376
• https://github.com/JuliaData/DataFrames.jl/blob/32b86d460f0a77254e4e73af6072ee5109b87885/src/groupeddataframe/complextransforms.jl#L134

and I would assume that these two other places it matters to avoid dynamic dispatch as in both of them do_call should be called by static dispatch (and this is what I understand happens).

The call in _combine_process_pair is only needed to determine the type of result retuned by do_call so that we can choose a proper code processing path later. And these two other call places of do_call actually relate to these paths (one is for processing cases when data with multiple rows is returned by do_call and the other for all cases when do_call returns one row of data).

If you start Julia with multiple threads these operations are supporting multi-threading indeed.

[timholy]

Can you give me a workload that is guaranteed to call those? Maybe this one does, but if so:

julia> using MethodAnalysis

julia> include("select_subset_test.jl")

julia> mctwf = methods(DataFrames._combine_tables_with_first!).ms[1]
_combine_tables_with_first!(first::Union{AbstractDataFrame, NamedTuple{<:Any, <:Tuple{Vararg{AbstractVector}}}}, outcols::Tuple{Vararg{AbstractVector, N}}, idx::Vector{Int64}, rowstart::Integer, colstart::Integer, f::Union{Function, Type}, gd::GroupedDataFrame, incols::Union{Nothing, Tuple, AbstractVector, NamedTuple}, colnames::Tuple{Vararg{Symbol, N}}, firstmulticol::DataFrames.FirstColCount) where N in DataFrames at /home/tim/.julia/dev/DataFrames/src/groupeddataframe/complextransforms.jl:354

julia> methodinstances(mctwf)
3-element Vector{Core.MethodInstance}:
 MethodInstance for DataFrames._combine_tables_with_first!(::NamedTuple{(:x1,), Tuple{BitVector}}, ::Tuple{Vector{Bool}}, ::Vector{Int64}, ::Int64, ::Int64, ::Function, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Tuple{Symbol}, ::DataFrames.FirstSingleCol)
 MethodInstance for DataFrames._combine_tables_with_first!(::NamedTuple{(:x1,), _A} where _A<:Tuple{AbstractVector}, ::Tuple{AbstractVector}, ::Vector{Int64}, ::Int64, ::Int64, ::Function, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Tuple{Symbol}, ::DataFrames.FirstSingleCol)
 MethodInstance for DataFrames._combine_tables_with_first!(::Union{AbstractDataFrame, NamedTuple{<:Any, <:Tuple{Vararg{AbstractVector}}}}, ::Tuple{Vararg{AbstractVector, N}}, ::Vector{Int64}, ::Int64, ::Int64, ::Union{Function, Type}, ::GroupedDataFrame{DataFrame}, ::Union{Nothing, Tuple, NamedTuple, AbstractVector}, ::Tuple{Vararg{Symbol, N}}, ::Union{DataFrames.FirstMultiCol, DataFrames.FirstSingleCol}) where N

so it doesn't seem to specialize on f (easiest to find as the argument after the two Ints) despite the absence of @nospecialize (Julia's heuristics are probably at play). But if I'm not really calling it then this could be misleading. I did comment out DataFrames' precompilation directives just to ensure that all specialization happens by natural dispatch. UPDATE: I ran DataFrames "grouping.jl" test script and then got this:

julia> utyps = Base.IdSet(); for mi in methodinstances(mctwf)
           push!(utyps, Base.unwrap_unionall(mi.specTypes).parameters[7])
       end

julia> utyps
Base.IdSet{Any} with 2 elements:
  Function
  Union{Function, Type}

There were 153 MethodInstances, so this seems likely to be all the type-diversity for that argument.

For the other, it's definitely not being called in this workload (there are no MethodInstances). UPDATE: after running the tests there are 1343 MethodInstances (wow!) with 317 different types for f. So this one is being specialized.

Bottom line, if it's not specialized on the specific function, then runtime dispatch gets used. In such cases there should be no cost to deferring it until you get to actual work performed by the function.

In your benchmarking, be careful of potential confusion from world-splitting. If you have 3 or fewer applicable MethodInstances Julia will use world-splitting, but define a 4th method and it will use runtime dispatch. That can distort your estimate of performance hotspots. You may have to decide whether you want to optimize the very first use or the use case where the user has supplied many different functions in a single session. In the demo above do_call is now over the threshold:

julia> m = methods(DataFrames.do_call).ms[2]
do_call(f::Union{Function, Type}, idx::AbstractVector{<:Integer}, starts::AbstractVector{<:Integer}, ends::AbstractVector{<:Integer}, gd::GroupedDataFrame, incols::Tuple{AbstractVector}, i::Integer) in DataFrames at /home/tim/.julia/dev/DataFrames/src/groupeddataframe/callprocessing.jl:90

julia> methodinstances(m)
5-element Vector{Core.MethodInstance}:
 MethodInstance for DataFrames.do_call(::DataFrames.var"#496#497"{var"#11#12"}, ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)
 MethodInstance for DataFrames.do_call(::Function, ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)
 MethodInstance for DataFrames.do_call(::var"#13#14", ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)
 MethodInstance for DataFrames.do_call(::DataFrames.var"#496#497"{var"#15#16"}, ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)
 MethodInstance for DataFrames.do_call(::var"#17#18", ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)

but isn't if you run fewer tests. However, apply my @nospecialize, restart your session, and do it again and then this is what you get:

julia> methodinstances(m)
2-element Vector{Core.MethodInstance}:
 MethodInstance for DataFrames.do_call(::Function, ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)
 MethodInstance for DataFrames.do_call(::Union{Function, Type}, ::Vector{Int64}, ::Vector{Int64}, ::Vector{Int64}, ::GroupedDataFrame{DataFrame}, ::Tuple{Vector{Int64}}, ::Int64)

This is few enough to ensure that this method of do_call will be called with world-splitting and might actually give some performance advantages.

[timholy]

By the way, when you might want to do "pass through" specialization (outer(f, args...) just passes f down to inner(f, otherargs...) without calling f directly), one way to reduce latency would be to take something like this:

function outer(f, args...)
    for i = 1:n
        # do lots of work (independent of f)
        inner(f, otherargs...)
    end
end

and take the part #do lots of work and move it to a separate @noinline function that doesn't receive f as an argument. That will allow all that work to be compiled many fewer times (without needing to specialize on f, which it doesn't use), and keep outer short and quick-to-compile so that specialization is less painful.