methodswith 10x slower since v1.0

[rfourquet]

julia> struct X end

julia> @time methodswith(X) # v1.0
  0.559031 seconds (580.24 k allocations: 31.137 MiB, 19.37% gc time)

julia> @time methodswith(X) # v1.6
  0.949839 seconds (669.04 k allocations: 37.711 MiB, 0.87% gc time, 23.56% compilation time)

julia> @time methodswith(X) # v1.7.0
  8.769690 seconds (23.11 M allocations: 1.209 GiB, 1.77% gc time, 90.11% compilation time)

julia> @time methodswith(X) # Version 1.8.0-DEV.1152 (2021-12-17)
  8.110175 seconds (21.86 M allocations: 1.142 GiB, 2.15% gc time, 89.80% compilation time)

[ufechner7]

You seam to have a very fast computer. This is what I see:

julia> @time methodswith(X)
 32.524852 seconds (115.35 M allocations: 6.100 GiB, 2.80% gc time, 90.78% compilation time)

julia> versioninfo()
Julia Version 1.7.0
Commit 3bf9d17731 (2021-11-30 12:12 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i7-7700K CPU @ 4.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.1 (ORCJIT, skylake)
Environment:
  JULIA_PKG3_PRECOMPILE = enable
  JULIA_NUM_THREADS = 4

[ToucheSir]

32 seconds seems pathological, I get just under 5 on a similar machine:

julia> @time methodswith(X)
  4.821725 seconds (23.77 M allocations: 1.244 GiB, 2.47% gc time, 89.88% compilation time)

julia> versioninfo()
Julia Version 1.7.0
Commit 3bf9d17731 (2021-11-30 12:12 UTC)
Platform Info:
  OS: Linux (x86_64-pc-linux-gnu)
  CPU: Intel(R) Core(TM) i7-7700K CPU @ 4.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-12.0.1 (ORCJIT, skylake)

[rfourquet]

You seam to have a very fast computer. This is what I see:

It's a 6-yo laptop, intel dual core i5, so not that fast :) but your @time call shows a lot more allocations than mine, which indeed seems "pathological". Did you start julia with --startup-file=no ?

[LilithHafner]

Thanks to @jakobnissen the regression for the first call is down to about 2x on my computer which I think is acceptable given that there are many more methods to sift through.

Shoutout to juliaup and @davidanthoff for making it incredibly easy for me to test out Julia 1.0:

juliaup add 1.0
julia +1.0

The time for subsequent calls, though, still has a 10x regression.

julia> struct X end

julia> @time methodswith(X);
# 1.0
  0.367881 seconds (580.20 k allocations: 31.340 MiB, 1.89% gc time)
  0.075684 seconds (75.90 k allocations: 5.041 MiB)
  0.081371 seconds (75.90 k allocations: 5.041 MiB, 12.62% gc time)
  0.075804 seconds (75.90 k allocations: 5.041 MiB)

# 1.9
  0.849289 seconds (877.66 k allocations: 48.833 MiB, 1.54% gc time, 4.94% compilation time)
  0.830985 seconds (844.64 k allocations: 46.564 MiB, 2.58% gc time)
  0.771522 seconds (844.64 k allocations: 46.564 MiB, 0.88% gc time)
  0.779156 seconds (844.64 k allocations: 46.564 MiB, 0.50% gc time)

[jakobnissen]

it seems like the bottleneck is calling methods(::Any), which has become 10x slower, despite there being only ~40% more total methods to check. Nearly all this time is spent in Base._methods_by_ftype.

[xgdgsc]

When implementing julia-vscode/julia-vscode#3240 . I find methodswith could be really slow (more than 10 seconds on a decent server) when using a lot of modules on simple common Dict types. Is it possible to fix the performance. Or add a methodswith argument firstonly=true that only return the first argument matching methods?

[jakobnissen]

@xgdgsc is that with Julia 1.9? It should be much faster on that version

[xgdgsc]

That was on 1.8. Test 1.9 it still uses similar time, although first time call after precompiling is much faster. I guess it 's because most code is already in C. Would adding the firstonly search help the performance for this particular use case? Or is there room for performance improvements in the C code?

# before using any package
julia> @time methodswith(Dict,supertypes=true);
  0.765192 seconds (902.67 k allocations: 48.375 MiB, 1.91% gc time, 3.95% compilation time)
julia> @time methodswith(Vector,supertypes=true);
  0.733430 seconds (878.95 k allocations: 46.914 MiB, 2.95% gc time)
# after using a lot of packages
julia> @time methodswith(Dict,supertypes=true);
  8.364217 seconds (12.23 M allocations: 1.005 GiB, 2.69% gc time)
julia> @time methodswith(Vector,supertypes=true);
  8.363283 seconds (12.24 M allocations: 1.006 GiB, 2.70% gc time)

if you use more than 30 modules. A reference Project.toml :

[deps]
BSON = "fbb218c0-5317-5bc6-957e-2ee96dd4b1f0"
BenchmarkTools = "6e4b80f9-dd63-53aa-95a3-0cdb28fa8baf"
CSV = "336ed68f-0bac-5ca0-87d4-7b16caf5d00b"
Clustering = "aaaa29a8-35af-508c-8bc3-b662a17a0fe5"
Conda = "8f4d0f93-b110-5947-807f-2305c1781a2d"
DataFrames = "a93c6f00-e57d-5684-b7b6-d8193f3e46c0"
DataFramesMeta = "1313f7d8-7da2-5740-9ea0-a2ca25f37964"
Dates = "ade2ca70-3891-5945-98fb-dc099432e06a"
Distances = "b4f34e82-e78d-54a5-968a-f98e89d6e8f7"
EvoTrees = "f6006082-12f8-11e9-0c9c-0d5d367ab1e5"
GLM = "38e38edf-8417-5370-95a0-9cbb8c7f171a"
HMMBase = "b2b3ca75-8444-5ffa-85e6-af70e2b64fe7"
HypothesisTests = "09f84164-cd44-5f33-b23f-e6b0d136a0d5"
IJulia = "7073ff75-c697-5162-941a-fcdaad2a7d2a"
Impute = "f7bf1975-0170-51b9-8c5f-a992d46b9575"
Interact = "c601a237-2ae4-5e1e-952c-7a85b0c7eef1"
JDF = "babc3d20-cd49-4f60-a736-a8f9c08892d3"
JLD2 = "033835bb-8acc-5ee8-8aae-3f567f8a3819"
JLSO = "9da8a3cd-07a3-59c0-a743-3fdc52c30d11"
JSON = "682c06a0-de6a-54ab-a142-c8b1cf79cde6"
Jfire = "3f49405f-012b-5ae6-ad9b-9087b1131e69"
LoopVectorization = "bdcacae8-1622-11e9-2a5c-532679323890"
MLJ = "add582a8-e3ab-11e8-2d5e-e98b27df1bc7"
MLJBase = "a7f614a8-145f-11e9-1d2a-a57a1082229d"
MLJGLMInterface = "caf8df21-4939-456d-ac9c-5fefbfb04c0c"
MLJLinearModels = "6ee0df7b-362f-4a72-a706-9e79364fb692"
MLJXGBoostInterface = "54119dfa-1dab-4055-a167-80440f4f7a91"
MaxMinFilters = "be03bc56-bb7c-4dbf-b252-c57e9365e4bb"
Missings = "e1d29d7a-bbdc-5cf2-9ac0-f12de2c33e28"
Mmap = "a63ad114-7e13-5084-954f-fe012c677804"
MultivariateStats = "6f286f6a-111f-5878-ab1e-185364afe411"
MySQL = "39abe10b-433b-5dbd-92d4-e302a9df00cd"
OrderedCollections = "bac558e1-5e72-5ebc-8fee-abe8a469f55d"
Peaks = "18e31ff7-3703-566c-8e60-38913d67486b"
PlotlyJS = "f0f68f2c-4968-5e81-91da-67840de0976a"
PlotlyLight = "ca7969ec-10b3-423e-8d99-40f33abb42bf"
Plots = "91a5bcdd-55d7-5caf-9e0b-520d859cae80"
Pluto = "c3e4b0f8-55cb-11ea-2926-15256bba5781"
ProgressMeter = "92933f4c-e287-5a05-a399-4b506db050ca"
PyCall = "438e738f-606a-5dbb-bf0a-cddfbfd45ab0"
PythonCall = "6099a3de-0909-46bc-b1f4-468b9a2dfc0d"
RDatasets = "ce6b1742-4840-55fa-b093-852dadbb1d8b"
Reexport = "189a3867-3050-52da-a836-e630ba90ab69"
RemoteREPL = "1bd9f7bb-701c-4338-bec7-ac987af7c555"
Revise = "295af30f-e4ad-537b-8983-00126c2a3abe"
RollingFunctions = "b0e4dd01-7b14-53d8-9b45-175a3e362653"
ShiftedArrays = "1277b4bf-5013-50f5-be3d-901d8477a67a"
Statistics = "10745b16-79ce-11e8-11f9-7d13ad32a3b2"
StatsBase = "2913bbd2-ae8a-5f71-8c99-4fb6c76f3a91"
Tables = "bd369af6-aec1-5ad0-b16a-f7cc5008161c"
ThreadSafeDicts = "4239201d-c60e-5e0a-9702-85d713665ba7"
WebIO = "0f1e0344-ec1d-5b48-a673-e5cf874b6c29"
XGBoost = "009559a3-9522-5dbb-924b-0b6ed2b22bb9"

[jakobnissen]

I see two ways to make it faster:

• The current algorithm is to examine every single name defined in Main, including in any modules defined in Main (i.e., all constants, functions, and types) and extract their methods. This is a terrible algorithm, but I'm not sure how to do better.
• For each name, the C function jl_matching_methods is eventually called. This has become several times slower since 1.6. Speeding that up may be an option.

[timholy]

This is a terrible algorithm, but I'm not sure how to do better.

Presumably it would be possible with the correct data structures (e.g., an IdDict with keys for every supertype), but if that were automatically built (e.g., gets updated every time you add a new method) I am guessing it would lead to an unacceptably-large increase in the system image size.

However, one option would be to define a method to create such a structure, which might be useful to speed up cases where you're making multiple methodswith queries. It would have to be made clear that it can get out-of-date if you define new methods (which includes loading new packages, of course). So I'm not sure how useful this would be.

[xgdgsc]

I workaround this by using supertypes to limit search module range. So it' s not something urgent.

[ViralBShah]

0.1 seconds now. Hope ok to close.

[jakobnissen]

Latency has been improved since #47302, but each call is still 10x slower than in 1.0, so I prefer this remains open

[rfourquet]

@jakobnissen the example in the OP seems to be as fast on 1.10 as on 1.0, do you measure something else?

[jakobnissen]

I measure the same thing on the second run, after JIT compilation:
Julia 1.0.5:

julia> struct X end

julia> methodswith(X);

julia> @time methodswith(X);
  0.097856 seconds (75.95 k allocations: 5.045 MiB)

Julia 1.9.2:

julia> struct X end

julia> methodswith(X);

julia> @time methodswith(X);
  0.678143 seconds (451.91 k allocations: 22.580 MiB, 25.23% gc time)

[ViralBShah]

Interestingly, I don't see the issue on mac (probably because it is using Rosetta for 1.0 on mac aarch64). But on Linux, I do observe a big difference.

[LilithHafner]

I do see this issue on mac

x@x ~ % julia +1.0 -q --startup-file=no
julia> VERSION
v"1.0.5"

julia> struct X end

julia> methodswith(X);

julia> @time methodswith(X);
  0.043441 seconds (75.90 k allocations: 5.041 MiB)

julia> 
x@x ~ % julia -q --startup-file=no 
julia> VERSION
v"1.10.0-alpha1"

julia> struct X end

julia> methodswith(X);

julia> @time methodswith(X);
  0.196974 seconds (319.68 k allocations: 14.455 MiB)

julia> versioninfo()
Julia Version 1.10.0-alpha1
Commit f8ad15f7b16 (2023-07-06 10:36 UTC)
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

[vtjnash]

This is likely intended. The code was not very accurate in v1.0, and now it should be more complete at listing methods.

[xgdgsc]

After using OmniPackage it becomes a bit too slow for IDE feature like julia-vscode/julia-vscode#3240 , enough for use in REPL, though.

[vtjnash]

I don't think users should expect this to be instantaneous-interactive speed. The interactive version is REPLCompletions.complete_any_methods.

[ViralBShah]

Do we have a way to close this with an appropriate label in that case?

[vtjnash]

Sure we can close this. The interactive version is in REPLCompletions, so doesn't seem like anything left to do.

[LilithHafner]

For future reference, the regression in methodswith is real and expected (won't fix).