PrecompileTools causes runtime performance lost

[Moelf]

• [Julia] go back to manual warmup and use String instead of Symbol jinyus/related_post_gen#376

on top of this PR, if I include back a precompile workload:

@compile_workload begin
    print("Precompiling main workload: ")
    main()
end

I can see that the time recorded at run time becomes worse:

Processing time (w/o IO): 19 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 19 milliseconds

to

Processing time (w/o IO): 25 milliseconds
Processing time (w/o IO): 26 milliseconds
Processing time (w/o IO): 25 milliseconds

what's the mechanism for this?

[mkitti]

Maybe it is faster to compile to memory than load from disk?

[LilithHafner]

This really shouldn't happen. Precompiled methods should be loaded from disk into memory on package load.

I also can't reproduce this locally. Can you provide detailed reproduction instructions and/or a smaller MWE?

This is how I tried and failed to reproduce this performance loss

x@x dev % git clone github.com/Moelf/related_post_gen PrecompileTools33
fatal: repository 'github.com/Moelf/related_post_gen' does not exist
x@x dev % git clone https://github.com/Moelf/related_post_gen PrecompileTools33
[...]
x@x dev % cd PrecompileTools33/julia/Related/                                                 
x@x PrecompileTools33 % git checkout julia_restore_perf
[...]
x@x Related % julia --project -e 'import Pkg; Pkg.instantiate()'
    Updating registry at `~/.julia/registries/General.toml`
    ...
x@x Related % for VARIABLE in 1 2 3                             
do
    julia --project -e 'using Related; main()'
done
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
x@x Related % code src/Related.jl 
x@x Related % git diff
diff --git a/julia/Related/src/Related.jl b/julia/Related/src/Related.jl
index 8482654..1842242 100644
--- a/julia/Related/src/Related.jl
+++ b/julia/Related/src/Related.jl
@@ -109,5 +109,10 @@ function main()
     end
 end
 
+using PrecompileTools
+@compile_workload begin
+    print("Precompiling main workload: ")
+    main()
+end
 
 end # module Related
x@x Related % for VARIABLE in 1 2 3
do
    julia --project -e 'using Related; main()'
done
Precompiling main workload: Processing time (w/o IO): 382 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 19 milliseconds
Processing time (w/o IO): 19 milliseconds

This is an entirely unedited version

x@x dev % git clone github.com/Moelf/related_post_gen PrecompileTools33
fatal: repository 'github.com/Moelf/related_post_gen' does not exist
x@x dev % git clone https://github.com/Moelf/related_post_gen PrecompileTools33
Cloning into 'PrecompileTools33'...
remote: Enumerating objects: 4892, done.
remote: Counting objects: 100% (428/428), done.
remote: Compressing objects: 100% (199/199), done.
remote: Total 4892 (delta 218), reused 380 (delta 211), pack-reused 4464
Receiving objects: 100% (4892/4892), 11.69 MiB | 5.34 MiB/s, done.
Resolving deltas: 100% (2597/2597), done.
x@x dev % cd PrecompileTools33                                                 
x@x PrecompileTools33 % git checkout julia_restore_perf
branch 'julia_restore_perf' set up to track 'origin/julia_restore_perf'.
Switched to a new branch 'julia_restore_perf'
x@x PrecompileTools33 % cd julia/Related/  
x@x Related % for VARIABLE in 1 2 3                                                
do
    julia --project -e 'using Related; main()'
done
ERROR: LoadError: ArgumentError: Package JSON3 [0f8b85d8-7281-11e9-16c2-39a750bddbf1] is required but does not seem to be installed:
 - Run `Pkg.instantiate()` to install all recorded dependencies.

Stacktrace:
 [1] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1774
 [2] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [3] macro expansion
   @ ./loading.jl:1648 [inlined]
 [4] macro expansion
   @ ./lock.jl:267 [inlined]
 [5] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
 [6] include
   @ ./Base.jl:457 [inlined]
 [7] include_package_for_output(pkg::Base.PkgId, input::String, depot_path::Vector{String}, dl_load_path::Vector{String}, load_path::Vector{String}, concrete_deps::Vector{Pair{Base.PkgId, UInt128}}, source::Nothing)
   @ Base ./loading.jl:2049
 [8] top-level scope
   @ stdin:3
in expression starting at /Users/x/.julia/dev/PrecompileTools33/julia/Related/src/Related.jl:1
in expression starting at stdin:3
ERROR: Failed to precompile Related [892d0954-52c7-4a59-ae8f-9a164aba3227] to "/Users/x/.julia/compiled/v1.9/Related/jl_YnxgbR".
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] compilecache(pkg::Base.PkgId, path::String, internal_stderr::IO, internal_stdout::IO, keep_loaded_modules::Bool)
   @ Base ./loading.jl:2300
 [3] compilecache
   @ ./loading.jl:2167 [inlined]
 [4] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1805
 [5] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [6] macro expansion
   @ ./loading.jl:1648 [inlined]
 [7] macro expansion
   @ ./lock.jl:267 [inlined]
 [8] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
ERROR: LoadError: ArgumentError: Package JSON3 [0f8b85d8-7281-11e9-16c2-39a750bddbf1] is required but does not seem to be installed:
 - Run `Pkg.instantiate()` to install all recorded dependencies.

Stacktrace:
 [1] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1774
 [2] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [3] macro expansion
   @ ./loading.jl:1648 [inlined]
 [4] macro expansion
   @ ./lock.jl:267 [inlined]
 [5] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
 [6] include
   @ ./Base.jl:457 [inlined]
 [7] include_package_for_output(pkg::Base.PkgId, input::String, depot_path::Vector{String}, dl_load_path::Vector{String}, load_path::Vector{String}, concrete_deps::Vector{Pair{Base.PkgId, UInt128}}, source::Nothing)
   @ Base ./loading.jl:2049
 [8] top-level scope
   @ stdin:3
in expression starting at /Users/x/.julia/dev/PrecompileTools33/julia/Related/src/Related.jl:1
in expression starting at stdin:3
ERROR: Failed to precompile Related [892d0954-52c7-4a59-ae8f-9a164aba3227] to "/Users/x/.julia/compiled/v1.9/Related/jl_7j44x4".
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] compilecache(pkg::Base.PkgId, path::String, internal_stderr::IO, internal_stdout::IO, keep_loaded_modules::Bool)
   @ Base ./loading.jl:2300
 [3] compilecache
   @ ./loading.jl:2167 [inlined]
 [4] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1805
 [5] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [6] macro expansion
   @ ./loading.jl:1648 [inlined]
 [7] macro expansion
   @ ./lock.jl:267 [inlined]
 [8] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
ERROR: LoadError: ArgumentError: Package JSON3 [0f8b85d8-7281-11e9-16c2-39a750bddbf1] is required but does not seem to be installed:
 - Run `Pkg.instantiate()` to install all recorded dependencies.

Stacktrace:
 [1] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1774
 [2] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [3] macro expansion
   @ ./loading.jl:1648 [inlined]
 [4] macro expansion
   @ ./lock.jl:267 [inlined]
 [5] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
 [6] include
   @ ./Base.jl:457 [inlined]
 [7] include_package_for_output(pkg::Base.PkgId, input::String, depot_path::Vector{String}, dl_load_path::Vector{String}, load_path::Vector{String}, concrete_deps::Vector{Pair{Base.PkgId, UInt128}}, source::Nothing)
   @ Base ./loading.jl:2049
 [8] top-level scope
   @ stdin:3
in expression starting at /Users/x/.julia/dev/PrecompileTools33/julia/Related/src/Related.jl:1
in expression starting at stdin:3
ERROR: Failed to precompile Related [892d0954-52c7-4a59-ae8f-9a164aba3227] to "/Users/x/.julia/compiled/v1.9/Related/jl_Y7ZWeO".
Stacktrace:
 [1] error(s::String)
   @ Base ./error.jl:35
 [2] compilecache(pkg::Base.PkgId, path::String, internal_stderr::IO, internal_stdout::IO, keep_loaded_modules::Bool)
   @ Base ./loading.jl:2300
 [3] compilecache
   @ ./loading.jl:2167 [inlined]
 [4] _require(pkg::Base.PkgId, env::String)
   @ Base ./loading.jl:1805
 [5] _require_prelocked(uuidkey::Base.PkgId, env::String)
   @ Base ./loading.jl:1660
 [6] macro expansion
   @ ./loading.jl:1648 [inlined]
 [7] macro expansion
   @ ./lock.jl:267 [inlined]
 [8] require(into::Module, mod::Symbol)
   @ Base ./loading.jl:1611
x@x Related % julia --project -e 'import Pkg; Pkg.instantiate()'
    Updating registry at `~/.julia/registries/General.toml`
    Updating `~/.julia/dev/PrecompileTools33/julia/Related/Project.toml`
  [0f8b85d8] + JSON3 v1.13.2
  [aea7be01] + PrecompileTools v1.2.0
  [90137ffa] + StaticArrays v1.6.5
  [856f2bd8] + StructTypes v1.10.0
    Updating `~/.julia/dev/PrecompileTools33/julia/Related/Manifest.toml`
  [0f8b85d8] + JSON3 v1.13.2
  [69de0a69] + Parsers v2.7.2
  [aea7be01] + PrecompileTools v1.2.0
  [21216c6a] + Preferences v1.4.1
  [90137ffa] + StaticArrays v1.6.5
  [1e83bf80] + StaticArraysCore v1.4.2
  [856f2bd8] + StructTypes v1.10.0
  [56f22d72] + Artifacts
  [ade2ca70] + Dates
  [8f399da3] + Libdl
  [37e2e46d] + LinearAlgebra
  [a63ad114] + Mmap
  [de0858da] + Printf
  [9a3f8284] + Random
  [ea8e919c] + SHA v0.7.0
  [9e88b42a] + Serialization
  [fa267f1f] + TOML v1.0.3
  [cf7118a7] + UUIDs
  [4ec0a83e] + Unicode
  [e66e0078] + CompilerSupportLibraries_jll v1.0.5+0
  [4536629a] + OpenBLAS_jll v0.3.21+4
  [8e850b90] + libblastrampoline_jll v5.8.0+0
Precompiling project...
  1 dependency successfully precompiled in 1 seconds. 8 already precompiled.
x@x Related % for VARIABLE in 1 2 3                             
do
    julia --project -e 'using Related; main()'
done
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
x@x Related % code src/Related.jl 
x@x Related % for VARIABLE in 1 2 3
do
    julia --project -e 'using Related; main()'
done
Precompiling main workload: Processing time (w/o IO): 382 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 19 milliseconds
Processing time (w/o IO): 19 milliseconds
x@x Related % git diff
diff --git a/julia/Related/src/Related.jl b/julia/Related/src/Related.jl
index 8482654..1842242 100644
--- a/julia/Related/src/Related.jl
+++ b/julia/Related/src/Related.jl
@@ -109,5 +109,10 @@ function main()
     end
 end
 
+using PrecompileTools
+@compile_workload begin
+    print("Precompiling main workload: ")
+    main()
+end
 
 end # module Related
x@x Related % git diff
diff --git a/julia/Related/src/Related.jl b/julia/Related/src/Related.jl
index 8482654..1842242 100644
--- a/julia/Related/src/Related.jl
+++ b/julia/Related/src/Related.jl
@@ -109,5 +109,10 @@ function main()
     end
 end
 
+using PrecompileTools
+@compile_workload begin
+    print("Precompiling main workload: ")
+    main()
+end
 
 end # module Related
x@x Related % 

[Moelf]

https://github.com/jinyus/related_post_gen/compare/main...Moelf:julia_slow_precomp?expand=1

this branch is slow for me. I'm on:

Project Related v0.1.0
Status `/tmp/related_post_gen/julia/Related/Project.toml`
  [0f8b85d8] JSON3 v1.13.2
  [aea7be01] PrecompileTools v1.2.0
  [90137ffa] StaticArrays v1.6.5
  [81625895] StaticCompiler v0.5.3
  [856f2bd8] StructTypes v1.10.0
  [ade2ca70] Dates

julia> versioninfo()
Julia Version 1.10.0-beta3
Commit 404750f8586 (2023-10-03 12:53 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 8 × 11th Gen Intel(R) Core(TM) i5-1135G7 @ 2.40GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-15.0.7 (ORCJIT, tigerlake)
  Threads: 5 on 8 virtual cores

[LilithHafner]

Still not seeing anything.

julia> for _ in 1:10 run(`julia +1.10 --project -e 'using Related; main()'`) end
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds

shell> git checkout julia_slow_precomp
Switched to branch 'julia_slow_precomp'
Your branch is up to date with 'Moelf/julia_slow_precomp'.

julia> for _ in 1:10 run(`julia +1.10 --project -e 'using Related; main()'`) end
Precompiling main workload: Processing time (w/o IO): 352 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 20 milliseconds
Processing time (w/o IO): 19 milliseconds
Processing time (w/o IO): 21 milliseconds
Processing time (w/o IO): 19 milliseconds
Processing time (w/o IO): 21 milliseconds

shell> git diff main
diff --git a/julia/Related/Project.toml b/julia/Related/Project.toml
index 9a0f46e..37ccba8 100644
--- a/julia/Related/Project.toml
+++ b/julia/Related/Project.toml
@@ -8,6 +8,7 @@ Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
 JSON3 = "0f8b85d8-7281-11e9-16c2-39a750bddbf1"
 PrecompileTools = "aea7be01-6a6a-4083-8856-8a6e6704d82a"
 StaticArrays = "90137ffa-7385-5640-81b9-e52037218182"
+StaticCompiler = "81625895-6c0f-48fc-b932-11a18313743c"
 StructTypes = "856f2bd8-1eba-4b0a-8007-ebc267875bd4"
 
 [compat]
diff --git a/julia/Related/src/Related.jl b/julia/Related/src/Related.jl
index 8482654..3bb3242 100644
--- a/julia/Related/src/Related.jl
+++ b/julia/Related/src/Related.jl
@@ -3,6 +3,7 @@ module Related
 using JSON3
 using StructTypes
 using Dates
+using PrecompileTools
 using StaticArrays
 
 const topn = 5
@@ -109,5 +110,11 @@ function main()
     end
 end
 
+@compile_workload begin
+    print("Precompiling main workload: ")
+    main()
+end
+
+
 
 end # module Related

julia> run(`julia +1.10 --project -e 'using InteractiveUtils; versioninfo(); import Pkg; Pkg.status()'`)
Julia Version 1.10.0-beta3
Commit 404750f8586 (2023-10-03 12:53 UTC)
Build Info:
  Official https://julialang.org/ release
Platform Info:
  OS: macOS (arm64-apple-darwin22.4.0)
  CPU: 8 × Apple M2
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-15.0.7 (ORCJIT, apple-m1)
  Threads: 1 on 4 virtual cores
Environment:
  JULIA_EDITOR = code
  JULIA_PYTHONCALL_EXE = python3.11
Project Related v0.1.0
Status `~/.julia/dev/PCT33/julia/Related/Project.toml`
  [0f8b85d8] JSON3 v1.13.2
  [aea7be01] PrecompileTools v1.2.0
  [90137ffa] StaticArrays v1.6.5
  [81625895] StaticCompiler
  [856f2bd8] StructTypes v1.10.0
  [ade2ca70] Dates
Process(`julia +1.10 --project -e 'using InteractiveUtils; versioninfo(); import Pkg; Pkg.status()'`, ProcessExited(0))

[Moelf]

oh well, x86_64-only issue maybe?