# Making sense of output of Snoopcompile

**URL:** <https://discourse.julialang.org/t/making-sense-of-output-of-snoopcompile/67562>\
**Category:** Tooling\
**Created:** [September 2, 2021, 10:38am UTC](https://discourse.julialang.org/t/making-sense-of-output-of-snoopcompile/67562 "2021-09-02T10:38:08Z")\
**Posts on this page:** 1\
**Page:** 1

<div class="post-metadata">

**Author:** ![Tomas\_Pevny](https://sea2.discourse-cdn.com/julialang/user_avatar/discourse.julialang.org/tomas_pevny/32/25466_2.png) [@Tomas\_Pevny](https://discourse.julialang.org/u/Tomas_Pevny)\
**Post date:** [September 2, 2021, 10:38am UTC](https://discourse.julialang.org/t/making-sense-of-output-of-snoopcompile/67562/1 "2021-09-02T10:38:08Z")

</div>

Dear All,

we have created a micro-service explaining our Mill.jl, unfortunately the service runs very slowly. Surprisingly slowly. One culprit I had in mind are precompilation times, since the data samples accepted by a single models can be o different type, since different parts of samples can be missing which makes it a different types.

I have therefore run a snoop-compile as

```julia
tinf = @snoopi_deep simulate_server(...)

```

and the visualize the results by

```julia
accumulate_by_source(SnoopCompile.flatten(tinf))

```

But I am puzzled by the results, since the most time consuming is

```julia
 (1661.059199338, ROOT() in Core.Compiler.Timings at compiler/typeinfer.jl:73)

```

after then, most of the things are realtively fast

> **more of the output**
>
> ```julia
> (1.4325971610000003, merge(a::NamedTuple{an, T} where T<:Tuple, b::NamedTuple{bn, T} where T<:Tuple) where {an, bn} in Base at namedtuple.jl:242)
> (1.4500268580000004, removeone!(f, flatmask, ii) in ExplainMill at /home/tomas.pevny/.julia/packages/ExplainMill/OI20s/src/pruning/utils.jl:113)
> (1.4561869859999998, Base.Generator(f::F, iter::I) where {I, F} in Base at generator.jl:32)
> (1.503079966000002, Base.Generator{I, F}(f, iter) where {I, F} in Base at generator.jl:32)
> (1.5185066880000004, select_rule(s::ServerCommons.AbstractSource, fs::ClusteringServer.RuleGen.FatSample, fc::ClusteringServer.RuleGen.FatClass, rules::Vector{T} where T) in ClusteringServer.RuleGen at /home/tomas.pevny/julia/Avast/hmil-server/ClusteringServer/src/rulegen/rulegen.jl:216)
> (1.559974971, getindex(ds::typename(ProductNode){…}, mk::ExplainMill.ProductMask, presentobs) where {T<:NamedTuple, M} in ExplainMill at /home/tomas.pevny/.julia/packages/ExplainMill/OI20s/src/masks/nodemasks/product.jl:44)
> (1.6183364590000007, indexed_iterate(t::Tuple, i::Int64, state) in Base at tuple.jl:86)
> (1.6234585009999987, set(obj, l::Setfield.PropertyLens{field}, val) where field in Setfield at /home/tomas.pevny/.julia/packages/Setfield/NshXm/src/lens.jl:108)
> (1.6596654549999998, addone!(f, flatmask) in ExplainMill at /home/tomas.pevny/.julia/packages/ExplainMill/OI20s/src/pruning/utils.jl:87)
> (1.7985840000000002, var"#baseline_generate#11"(max_rules, max_time, kwargs, ::typeof(ClusteringServer.RuleGen.baseline_generate), s::ServerCommons.AbstractSource, fm::ClusteringServer.RuleGen.FatModel, fs::ClusteringServer.RuleGen.FatSample, fc::ClusteringServer.RuleGen.FatClass) in ClusteringServer.RuleGen at /home/tomas.pevny/julia/Avast/hmil-server/ClusteringServer/src/rulegen/rulegen.jl:113)
> (1.863511771, var"#mapreducedim!#319"(init, ::typeof(GPUArrays.mapreducedim!), f::F, op::OP, R::CUDA.AnyCuArray{T, N} where N, A::Union{Base.Broadcast.Broadcasted, AbstractArray}) where {F, OP, T} in CUDA at /home/tomas.pevny/.julia/packages/CUDA/kKJoe/src/mapreduce.jl:140)
> (1.9225557329999985, (::Mill.var"#95#96")(x) in Mill at /home/tomas.pevny/.julia/packages/Mill/GN4LN/src/datanodes/productnode.jl:6)
> (1.9225557329999985, (::Mill.var"#95#96")(x) in Mill at /home/tomas.pevny/.julia/packages/Mill/GN4LN/src/datanodes/productnode.jl:6)
> (2.460045623999997, in(x, itr) in Base at operators.jl:1129)
> (2.5342526809999995, map(f, A::AbstractArray) in Base at abstractarray.jl:2294)
> (2.5873207800000007, _collect(c, itr, ::Base.EltypeUnknown, isz::Union{Base.HasLength, Base.HasShape}) in Base at array.jl:690)
> (2.740906448000001, iterate(g::Base.Generator, s...) in Base at generator.jl:42)
> (3.1267156070000013, var"#levelbylevelsearch!#293"(levelsearch!, fine_tuning::Bool, random_removal::Bool, ::typeof(ExplainMill.levelbylevelsearch!), f, mk::ExplainMill.AbstractStructureMask) in ExplainMill at /home/tomas.pevny/.julia/packages/ExplainMill/OI20s/src/pruning/levelbylevel.jl:65)
> (3.234713302000001, collect(itr::Base.Generator) in Base at array.jl:672)
> (3.289312171999996, getproperty(x, f::Symbol) in Base at Base.jl:33)
> (4.185053459, show_delim_array(io::IO, itr::Union{Core.SimpleVector, AbstractArray}, op, delim, cl, delim_one, i1, l) in Base at show.jl:1079) (4.503720626, _adjustmask(mk, source::Symbol) in SampleTweakers at /home/tomas.pevny/.julia/packages/SampleTweakers/tfy3D/src/explainmill.jl:103)
> (4.817237094999997, env_override_minlevel(group, _module) in Base.CoreLogging at logging.jl:519)
> (5.06188595, eltype(x) in Base at abstractarray.jl:187)
> (5.173634224000002, setproperty!(x, f::Symbol, v) in Base at Base.jl:34)
> (5.555816859999996, collect_to_with_first!(dest::AbstractArray, v1, itr, st) in Base at array.jl:699)
> (6.172039743, run_inference(model::ClusteringServer.RuleGen.FatModel, sample::ClusteringServer.RuleGen.FatSample) in ClusteringServer.RuleGen at /home/tomas.pevny/julia/Avast/hmil-server/ClusteringServer/src/rulegen/fat_model.jl:25)
> (8.950478434000004, _adjustmask(mk, ituples, lead_follow) in SampleTweakers at /home/tomas.pevny/.julia/packages/SampleTweakers/tfy3D/src/explainmill.jl:74)
> (13.634319394000002, collect_to!(dest::AbstractArray{T, N} where N, itr, offs, st) where T in Base at array.jl:719)
> (14.870875715, (m::typename(ProductModel){…})(x::typename(ProductNode){…}) where {P<:NamedTuple, T, MS<:NamedTuple, M} in Mill at /home/tomas.pevny/.julia/packages/Mill/GN4LN/src/modelnodes/productmodel.jl:30)
> (21.661553732, setindex_widen_up_to(dest::AbstractArray{T, N} where N, el, i) where T in Base at array.jl:710)
> (1661.059199338, ROOT() in Core.Compiler.Timings at compiler/typeinfer.jl:73)
> 
> ```

It is true that the precompilation list is long

```julia
julia> length(SnoopCompile.flatten(tinf))
292724

```

so it might well be that all my precompilation sums to 1661s, which is the top root and then the rest sums to it. But it does not sum up, as

```julia
julia> finf = SnoopCompile.flatten(tinf);
julia> sum(r.exclusive_time for r in finf[1:end-1])
231.98690968600127

julia> finf[end].exclusive_time
1661.059199338

```

which means I am loosing somewhere `1430s`, which is quite a bit to my taste. In the server, we use a lot of `@elapsed` macro to measure the time. I wonder if this cannot somehow interfere with the type inference, but as I understand, macro should not have such effect.

I am very confused by this any hint is very appreciated.