Type inference and abstract interpretation

General Usage Performance
1

Hi,

For pedagogical purposes, I wrote a Scheme interpreter in Julia, which I then updated to become a toy Julia interpreter written in Julia. So far, everything OK, without any relevant performance problems, despite being written in a highly recursive style. Then, I converted the interpreter to continuation-passing style (using closures as continuations) and noticed huge performance slowdowns even for the simplest examples, such as interpreting 1+2. Subsequent executions run very efficiently, but the first attempt at evaluating 1+2 takes around 30 secs before the result is returned. As the complexity of the evaluated code increases, execution times start to take minutes, then hours, and then, sometimes, I get a serious exception and Julia dies. Note that the expressions being evaluated by the interpreter are quite trivial. For example, ((x,y)->x+y)(1,2) is instantly evaluated when the evaluator is written in direct style but, when the interpreter is written in continuation-passing style, more than one hour later (and the amount of RAM used oscillating between 7 GB and 20 GB), the result is not yet available (although I can see through my logging that the interpreter is (very slowly) making progress).

I tried to create a MWE but failed to do so: as I start to remove unnecessary code, the performance problems disappear. BTW, it seems that this is related to the interaction of several functions, as redefining just one of them does not cause any performance problems. However, redefining a few at the same time then causes the massive slowdown at the next use of the evaluator.

Profiling the code shows that most of the time, type inference and abstract interpretation are the culprit, as the following flat profile shows:

10324 …CPSEvaluator.jl 38 eval_expr(::Expr)
14971 .\compiler\typeinfer.jl 574 typeinf_ext(::Core.MethodInstance, ::Core.Compiler.Params)
14971 .\compiler\typeinfer.jl 605 typeinf_ext(::Core.MethodInstance, ::UInt64)
14988 .\loading.jl 1075 include_string(::Module, ::String, ::String)
14988 .\logging.jl 491 with_logger
14988 .\logging.jl 395 with_logstate(::Atom.var"##117#122"{String,Int64,String}, ::Base.CoreLoggin…
14988 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 92 #116
14988 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 93 #117
14988 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 94 (::Atom.var"##118#123"{String,Int64,String})()
14988 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 46 withpath(::Function, ::String)
14988 C:\Users\aml.julia\packages\Atom\Wouyw\src\repl.jl 75 hideprompt(::Atom.var"##116#121"{String,Int64,String})
14988 C:\Users\aml.julia\packages\CodeTools\xGemk\src\eval.jl 30 include_string(::Module, ::String, ::String, ::Int64)
14988 C:\Users\aml.julia\packages\CodeTools\xGemk\src\utils.jl 30 withpath(::Atom.var"##118#123"{String,Int64,String}, ::String)
14989 .\task.jl 333 (::Atom.var"##19#21"{Array{Any,1}})()
14989 C:\Users\aml.julia\packages\Atom\Wouyw\src\comm.jl 164 handlemsg(::Dict{String,Any}, ::Dict{String,Any})
14989 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 86 (::Atom.var"##115#120")(::Dict{String,Any})
14989 C:\Users\aml.julia\packages\Atom\Wouyw\src\eval.jl 91 macro expansion
14989 C:\Users\aml.julia\packages\Media\ItEPc\src\dynamic.jl 24 macro expansion
60721 .\compiler\abstractinterpretation.jl 21 abstract_call_gf_by_type(::Any, ::Array{Any,1}, ::Any, ::Core.Compiler.Infe…
60757 .\compiler\abstractinterpretation.jl 873 abstract_eval_call(::Array{Any,1}, ::Array{Any,1}, ::Array{Any,1}, ::Core.C…
279725 .\compiler\abstractinterpretation.jl 846 abstract_call(::Any, ::Nothing, ::Array{Any,1}, ::Array{Any,1}, ::Core.Comp…
281133 .\compiler\abstractinterpretation.jl 875 abstract_eval_call(::Array{Any,1}, ::Array{Any,1}, ::Array{Any,1}, ::Core.C…
281136 .\compiler\abstractinterpretation.jl 636 abstract_call(::Any, ::Array{Any,1}, ::Array{Any,1}, ::Array{Any,1}, ::Core…
332732 .\compiler\typeinfer.jl 488 typeinf_edge(::Method, ::Any, ::Core.SimpleVector, ::Core.Compiler.Inferenc…
336843 .\compiler\abstractinterpretation.jl 396 abstract_call_method(::Method, ::Any, ::Core.SimpleVector, ::Bool, ::Core.C…
338689 .\compiler\abstractinterpretation.jl 93 abstract_call_gf_by_type(::Any, ::Array{Any,1}, ::Any, ::Core.Compiler.Infe…
341973 .\compiler\abstractinterpretation.jl 945 abstract_eval(::Any, ::Array{Any,1}, ::Core.Compiler.InferenceState)
342067 .\compiler\abstractinterpretation.jl 1204 typeinf_local(::Core.Compiler.InferenceState)
342781 .\compiler\abstractinterpretation.jl 1260 typeinf_nocycle(::Core.Compiler.InferenceState)
343472 .\compiler\typeinfer.jl 12 typeinf(::Core.Compiler.InferenceState)

BTW, I noticed similar behavior in Julia 1.1.0, 1.2.0, and 1.3.0-rc1.
Do you have any suggestions for understanding what is going on?

Thanks.

1 Like
2

Hard to say without the code, but it could be that you are overtaxing type inference. Perhaps inspect low-level functions with @code_warntype, then do this gradually for higher-level building blocks.

3

Just as an extra bit of information, here is the results from SnoopCompiler during the evaluation of the expression 1+2. The first number is the time spent on type inference for each method instance.

(0.0010001659393310547, MethodInstance for (::var"##69#72"{Expr,Environment,typeof(identity)})(::Function))
(0.003999948501586914, MethodInstance for string(::String, ::Function, ::Vararg{Any,N} where N))
(0.9099998474121094, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(0.945000171661377, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##71#74"{typeof(+),Environment,typeof(identity)}))
(0.9659998416900635, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(+),Environment,typeof(identity)}}))
(0.9729998111724854, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,typeof(identity)}}))
(0.992999792098999, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,typeof(identity)}}}))
(1.0, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,typeof(identity)}}}))
(4.052999973297119, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##69#72"{Expr,Environment,typeof(identity)}))
(20.30400013923645, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

If, after that evaluation, I experiment the slightly more complex expression (2+3)*(4+5), the SnoopCompiler reports the following timings:

(0.0, MethodInstance for (::var"##69#72"{Expr,Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}})(::Function))
(0.0, MethodInstance for (::var"##69#72"{Expr,Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}})(::Function))
(0.1400001049041748, MethodInstance for (::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}}})(::Array{Any,1}))
(0.18499994277954102, MethodInstance for (::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}})(::Array{Any,1}))
(1.0130000114440918, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##71#74"{typeof(),Environment,typeof(identity)}))
(1.3149998188018799, MethodInstance for (::var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}})(::Array{Int64,1}))
(1.315000057220459, MethodInstance for (::var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}})(::Array{Int64,1}))
(1.3329999446868896, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}))
(1.4030001163482666, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}}))
(1.4250001907348633, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}))
(1.625, MethodInstance for (::var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}})(::Array{Int64,1}))
(1.6429998874664307, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}))
(1.7599999904632568, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}))
(1.7750000953674316, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}}))
(1.8369998931884766, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}))
(1.8799998760223389, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}}))
(1.9270000457763672, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}))
(2.2740001678466797, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}))
(2.3519999980926514, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}}))
(2.4149999618530273, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##76#78"{Int64,var"##71#74"{typeof(+),Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}}))
(8.088000059127808, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##69#72"{Expr,Environment,var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}}))
(10.25, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##69#72"{Expr,Environment,var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}}))
(51.46599984169006, MethodInstance for eval_expr(::Expr, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##71#74"{typeof(),Environment,typeof(identity)}}))
(66.16199994087219, MethodInstance for eval_expr(::Expr, ::Environment, ::var"##75#77"{Array{Any,1},Environment,var"##76#78"{Int64,var"##71#74"{typeof(),Environment,typeof(identity)}}}))

Just for comparison, when the interpreter is written in direct style, it evaluates the same expressions instantly (even on first try) and the SnoopCompiler produces empty arrays of results.

Given that the most significant change between direct style and continuation-passing style is the extra parameter for the continuation, it seems that the problem is the different closures being passed as arguments. Is there some documentation on the type inferencer that helps understand this behavior?

Thanks.

4

I’m still trying to create a MWE but I’m not there yet, as the behavior changes significantly just by removing one (unused) method. However, I can share some additional weirdness: I found that the compiler is getting slower and slower as time goes by. The experiment was to repeatedly redefine a small set of methods (but always using the exact same definitions) and then make the same function call. Below, you see the result from the use of SnoopCompile. Note that these results came from Julia 1.3.0-rc1 but similar results are produced by Julia 1.2.0.

julia> @snoopi eval_expr(jl"1+2")
9-element Array{Tuple{Float64,Core.MethodInstance},1}:
(0.0009999275207519531, MethodInstance for (::var"##132#135"{Expr,Environment,typeof(identity)})(::Function))
(0.9350001811981201, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(0.9459998607635498, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##134#137"{typeof(+),Environment,typeof(identity)}))
(0.9729998111724854, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##138#140"{Array{Any,1},Environment,var"##134#137"{typeof(+),Environment,typeof(identity)}}))
(0.9820001125335693, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##139#141"{Int64,var"##134#137"{typeof(+),Environment,typeof(identity)}}))
(0.996999979019165, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##138#140"{Array{Any,1},Environment,var"##139#141"{Int64,var"##134#137"{typeof(+),Environment,typeof(identity)}}}))
(1.0250000953674316, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##139#141"{Int64,var"##139#141"{Int64,var"##134#137"{typeof(+),Environment,typeof(identity)}}}))
(4.327000141143799, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##132#135"{Expr,Environment,typeof(identity)}))
(21.383999824523926, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

julia> @snoopi eval_expr(jl"1+2")
9-element Array{Tuple{Float64,Core.MethodInstance},1}:
(0.0, MethodInstance for (::var"##153#156"{Expr,Environment,typeof(identity)})(::Function))
(1.5920000076293945, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##155#158"{typeof(+),Environment,typeof(identity)}))
(1.5950000286102295, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##160#162"{Int64,var"##155#158"{typeof(+),Environment,typeof(identity)}}))
(1.6010000705718994, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(1.627000093460083, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##159#161"{Array{Any,1},Environment,var"##160#162"{Int64,var"##155#158"{typeof(+),Environment,typeof(identity)}}}))
(1.6389999389648438, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##160#162"{Int64,var"##160#162"{Int64,var"##155#158"{typeof(+),Environment,typeof(identity)}}}))
(1.746000051498413, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##159#161"{Array{Any,1},Environment,var"##155#158"{typeof(+),Environment,typeof(identity)}}))
(7.213000059127808, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##153#156"{Expr,Environment,typeof(identity)}))
(36.96399998664856, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

julia> @snoopi eval_expr(jl"1+2")
9-element Array{Tuple{Float64,Core.MethodInstance},1}:
(0.0009999275207519531, MethodInstance for (::var"##174#177"{Expr,Environment,typeof(identity)})(::Function))
(2.450000047683716, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(2.4700000286102295, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##181#183"{Int64,var"##181#183"{Int64,var"##176#179"{typeof(+),Environment,typeof(identity)}}}))
(2.5329999923706055, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##180#182"{Array{Any,1},Environment,var"##181#183"{Int64,var"##176#179"{typeof(+),Environment,typeof(identity)}}}))
(2.627000093460083, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##181#183"{Int64,var"##176#179"{typeof(+),Environment,typeof(identity)}}))
(2.7730000019073486, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##180#182"{Array{Any,1},Environment,var"##176#179"{typeof(+),Environment,typeof(identity)}}))
(2.9240000247955322, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##176#179"{typeof(+),Environment,typeof(identity)}))
(11.061000108718872, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##174#177"{Expr,Environment,typeof(identity)}))
(58.40000009536743, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

julia> @snoopi eval_expr(jl"1+2")
9-element Array{Tuple{Float64,Core.MethodInstance},1}:
(0.0009999275207519531, MethodInstance for (::var"##195#198"{Expr,Environment,typeof(identity)})(::Function))
(3.4579999446868896, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(3.4579999446868896, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##197#200"{typeof(+),Environment,typeof(identity)}))
(3.4809999465942383, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##201#203"{Array{Any,1},Environment,var"##197#200"{typeof(+),Environment,typeof(identity)}}))
(3.506999969482422, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##201#203"{Array{Any,1},Environment,var"##202#204"{Int64,var"##197#200"{typeof(+),Environment,typeof(identity)}}}))
(3.5219998359680176, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##202#204"{Int64,var"##202#204"{Int64,var"##197#200"{typeof(+),Environment,typeof(identity)}}}))
(3.5260000228881836, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##202#204"{Int64,var"##197#200"{typeof(+),Environment,typeof(identity)}}))
(15.73799991607666, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##195#198"{Expr,Environment,typeof(identity)}))
(84.14100003242493, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

julia> @snoopi eval_expr(jl"1+2")
9-element Array{Tuple{Float64,Core.MethodInstance},1}:
(0.0009999275207519531, MethodInstance for (::var"##216#219"{Expr,Environment,typeof(identity)})(::Function))
(4.763000011444092, MethodInstance for eval_call(::Expr, ::Environment, ::Function))
(4.828999996185303, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##222#224"{Array{Any,1},Environment,var"##218#221"{typeof(+),Environment,typeof(identity)}}))
(4.8420000076293945, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##218#221"{typeof(+),Environment,typeof(identity)}))
(4.843000173568726, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##223#225"{Int64,var"##218#221"{typeof(+),Environment,typeof(identity)}}))
(4.875999927520752, MethodInstance for eval_exprs(::Array{Any,1}, ::Environment, ::var"##223#225"{Int64,var"##223#225"{Int64,var"##218#221"{typeof(+),Environment,typeof(identity)}}}))
(4.960999965667725, MethodInstance for eval_expr(::Int64, ::Environment, ::var"##222#224"{Array{Any,1},Environment,var"##223#225"{Int64,var"##218#221"{typeof(+),Environment,typeof(identity)}}}))
(22.026999950408936, MethodInstance for eval_expr(::Symbol, ::Environment, ::var"##216#219"{Expr,Environment,typeof(identity)}))
(118.52999997138977, MethodInstance for eval_expr(::Expr, ::Environment, ::typeof(identity)))

As is visible, the time it takes to recompile the same stuff increases considerably. Is this expected?