Julia: `include` adds a significant amount of precompilation + loadtime
This was noticed by @staticfloat, I just open an issue so it doesn't get forgotten.
I created two packages, the only difference is that one includes an empty file. The exact content is
~/JuliaTests
❯ cat WithInclude/src/WithInclude.jl
module WithInclude
greet() = print("Hello World!")
include("empty_file.jl")
end # module
~/JuliaTests
❯ cat WithoutInclude/src/WithoutInclude.jl
module WithoutInclude
greet() = print("Hello World!")
end # module
Note the difference in precompilation time and load time:
julia> @time using WithInclude
[ Info: Precompiling WithInclude [340fb7d0-984a-41ca-a84d-fb4cd995b2f7]
0.420415 seconds (1.09 M allocations: 54.171 MiB, 3.04% gc time)
julia> @time using WithoutInclude
[ Info: Precompiling WithoutInclude [ae1e2670-1d00-45e9-b642-4c2c397d7467]
0.175426 seconds (12.03 k allocations: 705.531 KiB)
# New session
julia> @time using WithInclude
0.019881 seconds (28.70 k allocations: 2.533 MiB)
julia> @time using WithoutInclude
0.002217 seconds (10.29 k allocations: 599.969 KiB)
Also, note the difference in file size:
~/JuliaTests
❯ ls -lh ~/.julia/compiled/v1.5/WithInclude
Permissions Size User Date Modified Name
.rw-rw-r-- 99k kc 13 Aug 17:24 zUB7m_G5Cwl.ji
~/JuliaTests
❯ ls -lh ~/.julia/compiled/v1.5/WithoutInclude
Permissions Size User Date Modified Name
.rw-rw-r-- 3.0k kc 13 Aug 17:24 Qtu7B_G5Cwl.ji
@JeffBezanson suggests adding an inference barrier to cut the backedges to the module specific include.
latency
KristofferC
All 9 comments
Are these literally
module WithInclude
include("empty_file.jl")
end
and
module WithoutInclude
end
?
timholy
on 13 Aug 2020
~/JuliaTests
❯ cat WithInclude/src/WithInclude.jl
module WithInclude
greet() = print("Hello World!")
include("empty_file.jl") # this is an empty file
end # module
~/JuliaTests
❯ cat WithoutInclude/src/WithoutInclude.jl
module WithoutInclude
greet() = print("Hello World!")
end # module
I update the first post with this.
KristofferC
on 13 Aug 2020
👍1
It seems to pretty well saturate at one include. On my machine WithInclude0 has no include, WithInclude has one include, and WithInclude2 includes two different empty files. My drive is also SSD, in case that's relevant.
Before these have been precompiled (julians is short for julia --startup-file=no):
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude0'
0.241857 seconds (92.04 k allocations: 5.425 MiB)
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude'
0.295327 seconds (110.41 k allocations: 7.336 MiB)
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude2'
0.299110 seconds (110.55 k allocations: 7.345 MiB)
and after compilation
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude0'
0.000974 seconds (4.31 k allocations: 256.844 KiB)
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude'
0.014208 seconds (22.70 k allocations: 2.351 MiB)
tim@diva:/tmp/pkgs$ julians -e 'push!(LOAD_PATH, "."); @time using WithInclude2'
0.014501 seconds (22.84 k allocations: 2.361 MiB)
Yeah, I didn't mean to give the impression that it scaled linearly or something like that. But with jll packages that are small and there's quite many of them, even these 0.015s per package adds up.
KristofferC
on 13 Aug 2020
👍1
File change detection?
yuyichao
on 13 Aug 2020
We're pretty sure it's just all backedges, so having more include() calls wouldn't scale up very much, I don't think.
staticfloat
on 13 Aug 2020
Assuming this was from JLL modules, might be worthwhile using baremodule, to prevent the automatic addition of the local include and eval functions
vtjnash
on 13 Aug 2020
👍1
Here's a profile with no include calls:
julia> Profile.print(C=true, noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
╎4 /home/tim/src/julia-master/julia:?; _start
╎ 4 /lib/x86_64-linux-gnu/libc.so.6:?; __libc_start_main
╎ 4 /home/tim/src/julia-master/ui/repl.c:227; main
╎ 4 /home/tim/src/julia-master/ui/repl.c:106; true_main
╎ 4 /home/tim/src/julia-master/ui/../src/julia.h:1752; jl_apply
╎ 4 /home/tim/src/julia-master/usr/lib/julia/sys.so:?; jfptr__start_21750
╎ ╎ 4 @Base/client.jl:484; _start()
╎ ╎ 4 @Base/client.jl:301; exec_options(opts::Base.JLOptions)
╎ ╎ 4 @Base/client.jl:371; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
╎ ╎ 4 @Base/essentials.jl:717; invokelatest
╎ ╎ 4 @Base/essentials.jl:718; #invokelatest#2
╎ ╎ ╎ 4 /home/tim/src/julia-master/src/builtins.c:705; jl_f__apply_latest
╎ ╎ ╎ 4 /home/tim/src/julia-master/src/builtins.c:655; do_apply
╎ ╎ ╎ 4 /home/tim/src/julia-master/src/julia.h:1752; jl_apply
╎ ╎ ╎ 4 /home/tim/src/julia-master/usr/lib/julia/sys.so:?; jfptr_YY.840_20318
╎ ╎ ╎ 4 @Base/client.jl:386; (::Base.var"#840#842"{Bool,Bool,Bool})(REPL::Module)
╎ ╎ ╎ ╎ 4 @REPL/src/REPL.jl:299; run_repl(repl::REPL.AbstractREPL, consumer::Any)
╎ ╎ ╎ ╎ 4 @REPL/src/REPL.jl:311; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
╎ ╎ ╎ ╎ 4 @REPL/src/REPL.jl:180; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
╎ ╎ ╎ ╎ 4 @REPL/src/REPL.jl:195; repl_backend_loop(backend::REPL.REPLBackend)
╎ ╎ ╎ ╎ 4 @REPL/src/REPL.jl:134; eval_user_input(ast::Any, backend::REPL.REPLBackend)
╎ ╎ ╎ ╎ ╎ 4 @Base/boot.jl:344; eval(m::Module, e::Any)
╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:881; jl_toplevel_eval_in
╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:788; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:838; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/interpreter.c:659; jl_interpret_toplevel_thunk
╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/interpreter.c:491; eval_body
╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/interpreter.c:530; eval_body
╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:680; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:460; eval_import_path
╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/toplevel.c:423; call_require
╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/julia.h:1752; jl_apply
╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 @Base/loading.jl:923; require(into::Module, mod::Symbol)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 @Base/loading.jl:928; require(uuidkey::Base.PkgId)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 @Base/loading.jl:1007; _require(pkg::Base.PkgId)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 @Base/loading.jl:782; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 @Base/loading.jl:697; _include_from_serialized(path::String, depmods::Vector{Any})
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/gf.c:2336; jl_apply_generic
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/gf.c:2145; _jl_invoke
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/gf.c:1841; jl_compile_method_internal
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/gf.c:1890; jl_compile_method_internal
╎1 [unknown stackframe]
Total snapshots: 5
and here's one with:
julia> Profile.print(C=true, noisefloor=2)
Overhead ╎ [+additional indent] Count File:Line; Function
=========================================================
╎97 /home/tim/src/julia-master/julia:?; _start
╎ 97 /lib/x86_64-linux-gnu/libc.so.6:?; __libc_start_main
╎ 97 /home/tim/src/julia-master/ui/repl.c:227; main
╎ 97 /home/tim/src/julia-master/ui/repl.c:106; true_main
╎ 97 /home/tim/src/julia-master/ui/../src/julia.h:1752; jl_apply
╎ 97 /home/tim/src/julia-master/usr/lib/julia/sys.so:?; jfptr__start_21750
╎ ╎ 97 @Base/client.jl:484; _start()
╎ ╎ 97 @Base/client.jl:301; exec_options(opts::Base.JLOptions)
╎ ╎ 97 @Base/client.jl:371; run_main_repl(interactive::Bool, quiet::Bool, banner::Bool, history_file::Bool, color_set::Bool)
╎ ╎ 97 @Base/essentials.jl:717; invokelatest
╎ ╎ 97 @Base/essentials.jl:718; #invokelatest#2
╎ ╎ ╎ 97 /home/tim/src/julia-master/src/builtins.c:705; jl_f__apply_latest
╎ ╎ ╎ 97 /home/tim/src/julia-master/src/builtins.c:655; do_apply
╎ ╎ ╎ 97 /home/tim/src/julia-master/src/julia.h:1752; jl_apply
╎ ╎ ╎ 97 /home/tim/src/julia-master/usr/lib/julia/sys.so:?; jfptr_YY.840_20318
╎ ╎ ╎ 97 @Base/client.jl:386; (::Base.var"#840#842"{Bool,Bool,Bool})(REPL::Module)
╎ ╎ ╎ ╎ 97 @REPL/src/REPL.jl:299; run_repl(repl::REPL.AbstractREPL, consumer::Any)
╎ ╎ ╎ ╎ 97 @REPL/src/REPL.jl:311; run_repl(repl::REPL.AbstractREPL, consumer::Any; backend_on_current_task::Bool)
╎ ╎ ╎ ╎ 97 @REPL/src/REPL.jl:180; start_repl_backend(backend::REPL.REPLBackend, consumer::Any)
╎ ╎ ╎ ╎ 97 @REPL/src/REPL.jl:195; repl_backend_loop(backend::REPL.REPLBackend)
╎ ╎ ╎ ╎ 97 @REPL/src/REPL.jl:134; eval_user_input(ast::Any, backend::REPL.REPLBackend)
╎ ╎ ╎ ╎ ╎ 97 @Base/boot.jl:344; eval(m::Module, e::Any)
╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:881; jl_toplevel_eval_in
╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:788; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:838; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/interpreter.c:659; jl_interpret_toplevel_thunk
╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/interpreter.c:491; eval_body
╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/interpreter.c:530; eval_body
╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:680; jl_toplevel_eval_flex
╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:460; eval_import_path
╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/toplevel.c:423; call_require
╎ ╎ ╎ ╎ ╎ ╎ ╎ 97 /home/tim/src/julia-master/src/julia.h:1752; jl_apply
╎ ╎ ╎ ╎ ╎ ╎ ╎ 97 @Base/loading.jl:923; require(into::Module, mod::Symbol)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 97 @Base/loading.jl:928; require(uuidkey::Base.PkgId)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 97 @Base/loading.jl:1007; _require(pkg::Base.PkgId)
╎ ╎ ╎ ╎ ╎ ╎ ╎ 94 @Base/loading.jl:782; _require_search_from_serialized(pkg::Base.PkgId, sourcepath::String)
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 71 @Base/loading.jl:681; _include_from_serialized(path::String, depmods::Vector{Any})
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 71 /home/tim/src/julia-master/src/dump.c:2530; jl_restore_incremental
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 28 /home/tim/src/julia-master/src/dump.c:2480; _jl_restore_incremental
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 27 /home/tim/src/julia-master/src/dump.c:2398; jl_recache_other
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 11 /home/tim/src/julia-master/src/dump.c:2376; jl_recache_other_
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 11 /home/tim/src/julia-master/src/dump.c:2347; jl_recache_method
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 11 /home/tim/src/julia-master/src/dump.c:2337; jl_lookup_method
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 14 /home/tim/src/julia-master/src/dump.c:2381; jl_recache_other_
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 10 /home/tim/src/julia-master/src/dump.c:2361; jl_recache_method_instance
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 8 /home/tim/src/julia-master/src/subtype.c:3317; jl_type_intersection_env_s
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 7 /home/tim/src/julia-master/src/subtype.c:1883; jl_subtype_env
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 7 /home/tim/src/julia-master/src/subtype.c:1452; forall_exists_subtype
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 6 /home/tim/src/julia-master/src/subtype.c:1424; exists_subtype
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/subtype.c:1280; subtype
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/subtype.c:837; subtype_unionall
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 4 /home/tim/src/julia-master/src/subtype.c:712; with_tvar
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 32 /home/tim/src/julia-master/src/dump.c:2487; _jl_restore_incremental
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 28 /home/tim/src/julia-master/src/dump.c:1867; jl_insert_backedges
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 27 /home/tim/src/julia-master/src/dump.c:1834; jl_verify_edges
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 27 /home/tim/src/julia-master/src/gf.c:1813; jl_matching_methods
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/gf.c:2671; ml_matches
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 13 /home/tim/src/julia-master/src/typemap.c:518; jl_typemap_intersection_visitor
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 23 @Base/loading.jl:697; _include_from_serialized(path::String, depmods::Vector{Any})
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 23 /home/tim/src/julia-master/src/gf.c:2336; jl_apply_generic
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 23 /home/tim/src/julia-master/src/gf.c:2145; _jl_invoke
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 23 /home/tim/src/julia-master/src/gf.c:1841; jl_compile_method_internal
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 23 /home/tim/src/julia-master/src/gf.c:1890; jl_compile_method_internal
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 18 /home/tim/src/julia-master/src/jitlayers.cpp:313; jl_generate_fptr
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/jitlayers.cpp:132; _jl_compile_codeinst
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/jitlayers.cpp:1015; jl_add_to_ee
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/jitlayers.cpp:993; jl_add_to_ee
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/jitlayers.cpp:949; jl_add_to_ee
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 16 /home/tim/src/julia-master/src/jitlayers.cpp:655; addModule
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 15 ...sr/include/llvm/ExecutionEngine/Orc/IRCompileLayer.h:93; addModule
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 15 /home/tim/src/julia-master/src/jitlayers.cpp:531; operator()
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 15 ...e/tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZN4llvm6legacy15PassManagerImpl3runERNS_6ModuleE
╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 11 .../tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZN4llvm13FPPassManager11runOnModuleERNS_6ModuleE
1╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ ╎ 11 .../tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZN4llvm13FPPassManager13runOnFunctionERNS_8FunctionE
1╎1 /home/tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZN4llvm12SelectionDAG11getRegisterEjNS_3EVTE
1╎1 /home/tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZN4llvm16MetadataTracking7untrackEPvRNS_8MetadataE
1╎1 /home/tim/src/julia-master/usr/bin/../lib/libLLVM-9jl.so:?; _ZNK4llvm13PMDataManager16dumpPreservedSetEPKNS_4PassE
╎6 [unknown stackframe]
Total snapshots: 106
So the breakdown is roughly:
- 10%
jl_recache_method, which is almost entirelyjl_lookup_method; - 10%
jl_recache_method_instance - 30%
jl_insert_backedges - 25%
jl_compile_method_internal(not sure what's being compiled here...) - 25% other
timholy
on 13 Aug 2020
Was this page helpful?
0 / 5 - 0 ratings
Related issues
helgee
·
3Comments
ararslan
·
3Comments
musm
·
3Comments
StefanKarpinski
·
3Comments
arshpreetsingh
·
3Comments