include adds a significant amount of precompilation + loadtime

[KristofferC]

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.

[timholy]

Are these literally

module WithInclude
include("empty_file.jl")
end

and

module WithoutInclude
end

?

[KristofferC]

~/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.

[timholy]

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)

[KristofferC]

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.

[yuyichao]

File change detection?

[staticfloat]

We're pretty sure it's just all backedges, so having more include() calls wouldn't scale up very much, I don't think.

[vtjnash]

Assuming this was from JLL modules, might be worthwhile using baremodule, to prevent the automatic addition of the local include and eval functions

[timholy]

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

[timholy]

So the breakdown is roughly:

• 10% jl_recache_method, which is almost entirely jl_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