search

JuliaTesting / Aqua.jl

Auto QUality Assurance for Julia packages
MIT License
339 stars 25 forks source link

Stale dependencies check prohibitively slow #111

Open KeithWM opened 1 year ago

KeithWM commented 1 year ago

A bit of a long shot to post this here, but maybe others have encountered this issue too and there is something I can to fix it.

When running Aqua locally, the test_stale_deps takes so long that I've never actually seen it complete (even after leaving the machine for several hours). There is no issue when running the same tests in our CI/CD pipeline (on Bitbucket).

Does anyone know what could be the cause of this?

fingolfin commented 1 year ago

Never have encountered this or heard about it (though perhaps this is the same as #30?).

But as long as we cannot reproduce this and in general have no more information than "it hangs", we can't do anything about it. Perhaps you can tell us more:

KeithWM commented 1 year ago

Thanks for the reply. Sorry for not being more verbose in my question, but I managed to reproduce the error locally. I will try to make a MBE that I can share. In the meantime, answers to your questions:

Steps to reproduce:

julia> TestEnv.activate()
julia> import Aqua
julia> import BrokenAqua  # the name of the MBE to follow
julia> Aqua.test_stale_deps(BrokenAqua)

I am quite sure I encountered the error before without using TestEnv, both in a clean ]test and when using ReTest with some manual modifications to the environment.

Ctrl-C:

^C
ERROR: InterruptException:
Stacktrace:
  [1] try_yieldto(undo::typeof(Base.ensure_rescheduled))
    @ Base .\task.jl:871
  [2] wait()
    @ Base .\task.jl:931
  [3] wait(c::Base.GenericCondition{Base.Threads.SpinLock})
    @ Base .\condition.jl:124
  [4] wait_readnb(x::Base.PipeEndpoint, nb::Int64)
    @ Base .\stream.jl:416
  [5] read(stream::Base.PipeEndpoint)
    @ Base .\stream.jl:928
  [6] read(cmd::Cmd)
    @ Base .\process.jl:448
  [7] read(cmd::Cmd, #unused#::Type{String})
    @ Base .\process.jl:458
  [8] _analyze_stale_deps_1(pkg::Base.PkgId; ignore::Vector{Symbol})
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\2aeHf\src\stale_deps.jl:55
  [9] _analyze_stale_deps_1
    @ C:\Users\myerscoughk\.julia\packages\Aqua\2aeHf\src\stale_deps.jl:32 [inlined]
 [10] #30
    @ .\none:0 [inlined]
 [11] iterate
    @ .\generator.jl:47 [inlined]
 [12] collect(itr::Base.Generator{Vector{Base.PkgId}, Aqua.var"#30#31"{Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}}})
    @ Base .\array.jl:787
 [13] analyze_stale_deps
    @ C:\Users\myerscoughk\.julia\packages\Aqua\2aeHf\src\stale_deps.jl:29 [inlined]
 [14] macro expansion
    @ C:\Users\myerscoughk\AppData\Local\Programs\Julia-1.8.3\share\julia\stdlib\v1.8\Test\src\Test.jl:1455 [inlined]
 [15] test_stale_deps(packages::Module; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\2aeHf\src\stale_deps.jl:22
 [16] test_stale_deps(packages::Module)
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\2aeHf\src\stale_deps.jl:21
 [17] top-level scope
    @ REPL[12]:1
fingolfin commented 1 year ago

Excellent, thank you! An MBE would be fantastic

so it is waiting for a subprocess. I guess next we'd need a backtrace for that.

KeithWM commented 1 year ago

https://github.com/KeithWM/BrokenAqua.jl I think this is a breaking example.

fingolfin commented 1 year ago

Thank you! I tried this on macOS, but it "just works", when I do this in a fresh Julia 1.9 session:

import Aqua
import BrokenAqua
Aqua.test_stale_deps(BrokenAqua)

So it would be good to reduce differences to your setup...

fingolfin commented 1 year ago

I've now tried to reproduce this on Windows, with Julia 1.9.0; I also tried it with TestEnv (using the assumption that you did Pkg.activate the (BrokenAqua package). Still couldn't reproduce it.

Waiting now to hear whether you can repo with Julia 1.8.5 and/or 1.9.0

KeithWM commented 1 year ago

For the BrokenAqua.jl repo, I did not need TestEnv nor ReTest for it to fail.

I just tried it on my Mac with Julia 1.8.3, and it passes there too. So it might be a Windows issue more than anything else. And it appears to only happen with PlotlyJS as a dependency.

I will install Julia 1.9 on one of the Windows machine I have access to and try that. (Not to brag 😁 .)

KeithWM commented 1 year ago

Just tried on a Windows 10 system and it also hangs.

After ctrl-c:

(BrokenAqua) pkg> test
     Testing BrokenAqua
      Status `C:\Users\myerscoughk\AppData\Local\Temp\jl_FORm6V\Project.toml` 
  [4c88cf16] Aqua v0.6.2
  [c2512556] BrokenAqua v0.1.0 `C:\Users\myerscoughk\SQM\review\BrokenAqua.jl`
  [8dfed614] Test `@stdlib/Test`
      Status `C:\Users\myerscoughk\AppData\Local\Temp\jl_FORm6V\Manifest.toml`
  [4c88cf16] Aqua v0.6.2
  [bf4720bc] AssetRegistry v0.1.0
  [d1d4a3ce] BitFlags v0.1.7     
  [ad839575] Blink v0.12.7
  [c2512556] BrokenAqua v0.1.0 `C:\Users\myerscoughk\SQM\review\BrokenAqua.jl`
  [944b1d66] CodecZlib v0.7.1
  [35d6a980] ColorSchemes v3.21.0
  [3da002f7] ColorTypes v0.11.4
  [c3611d14] ColorVectorSpace v0.9.10
  [5ae59095] Colors v0.12.10
  [34da2185] Compat v4.6.1
  [f0e56b4a] ConcurrentUtilities v2.2.0
  [9a962f9c] DataAPI v1.15.0
  [e2d170a0] DataValueInterfaces v1.0.0
  [8bb1440f] DelimitedFiles v1.9.1
  [ffbed154] DocStringExtensions v0.9.3
  [53c48c17] FixedPointNumbers v0.8.4
  [de31a74c] FunctionalCollections v0.5.0
  [cd3eb016] HTTP v1.9.6
  [9fb69e20] Hiccup v0.2.2
  [92d709cd] IrrationalConstants v0.2.2
  [82899510] IteratorInterfaceExtensions v1.0.0
  [692b3bcd] JLLWrappers v1.4.1
  [97c1335a] JSExpr v0.5.4
  [682c06a0] JSON v0.21.4
  [b964fa9f] LaTeXStrings v1.3.0
  [50d2b5c4] Lazy v0.15.1
  [2ab3a3ac] LogExpFunctions v0.3.23
  [e6f89c97] LoggingExtras v1.0.0
  [1914dd2f] MacroTools v0.5.10
  [739be429] MbedTLS v1.1.7
  [ffc61752] Mustache v1.0.15
  [a975b10e] Mux v1.0.1
  [510215fc] Observables v0.5.4
  [4d8831e6] OpenSSL v1.4.1
  [bac558e1] OrderedCollections v1.6.0
  [d96e819e] Parameters v0.12.3
  [69de0a69] Parsers v2.5.10
  [fa939f87] Pidfile v1.3.0
  [a03496cd] PlotlyBase v0.8.19
  [f0f68f2c] PlotlyJS v0.18.10
  [aea7be01] PrecompileTools v1.1.1
  [21216c6a] Preferences v1.4.0
  [189a3867] Reexport v1.2.2
  [ae029012] Requires v1.3.0
  [777ac1f9] SimpleBufferStream v1.1.0
  [276daf66] SpecialFunctions v2.2.0
  [3783bdb8] TableTraits v1.0.1
  [bd369af6] Tables v1.10.1
  [62fd8b95] TensorCore v0.1.1
  [3bb67fe8] TranscodingStreams v0.9.13
  [5c2747f8] URIs v1.4.2
  [3a884ed6] UnPack v1.0.2
  [0f1e0344] WebIO v0.8.20
  [104b5d7c] WebSockets v1.6.0
  [cc8bc4a8] Widgets v0.6.6
  [f7e6163d] Kaleido_jll v0.2.1+0
  [458c3c95] OpenSSL_jll v3.0.9+0
  [efe28fd5] OpenSpecFun_jll v0.5.5+0
  [0dad84c5] ArgTools v1.1.1 `@stdlib/ArgTools`
  [56f22d72] Artifacts `@stdlib/Artifacts`
  [2a0f44e3] Base64 `@stdlib/Base64`
  [ade2ca70] Dates `@stdlib/Dates`
  [8ba89e20] Distributed `@stdlib/Distributed`
  [f43a241f] Downloads v1.6.0 `@stdlib/Downloads`
  [7b1f6079] FileWatching `@stdlib/FileWatching`
  [b77e0a4c] InteractiveUtils `@stdlib/InteractiveUtils`
  [b27032c2] LibCURL v0.6.3 `@stdlib/LibCURL`
  [76f85450] LibGit2 `@stdlib/LibGit2`
  [8f399da3] Libdl `@stdlib/Libdl`
  [37e2e46d] LinearAlgebra `@stdlib/LinearAlgebra`
  [56ddb016] Logging `@stdlib/Logging`
  [d6f4376e] Markdown `@stdlib/Markdown`
  [a63ad114] Mmap `@stdlib/Mmap`
  [ca575930] NetworkOptions v1.2.0 `@stdlib/NetworkOptions`
  [44cfe95a] Pkg v1.9.0 `@stdlib/Pkg`
  [de0858da] Printf `@stdlib/Printf`
  [3fa0cd96] REPL `@stdlib/REPL`
  [9a3f8284] Random `@stdlib/Random`
  [ea8e919c] SHA v0.7.0 `@stdlib/SHA`
  [9e88b42a] Serialization `@stdlib/Serialization`
  [6462fe0b] Sockets `@stdlib/Sockets`
  [2f01184e] SparseArrays `@stdlib/SparseArrays`
  [10745b16] Statistics v1.9.0 `@stdlib/Statistics`
  [fa267f1f] TOML v1.0.3 `@stdlib/TOML`
  [a4e569a6] Tar v1.10.0 `@stdlib/Tar`
  [8dfed614] Test `@stdlib/Test`
  [cf7118a7] UUIDs `@stdlib/UUIDs`
  [4ec0a83e] Unicode `@stdlib/Unicode`
  [e66e0078] CompilerSupportLibraries_jll v1.0.2+0 `@stdlib/CompilerSupportLibraries_jll`
  [deac9b47] LibCURL_jll v7.84.0+0 `@stdlib/LibCURL_jll`
  [29816b5a] LibSSH2_jll v1.10.2+0 `@stdlib/LibSSH2_jll`
  [c8ffd9c3] MbedTLS_jll v2.28.2+0 `@stdlib/MbedTLS_jll`
  [14a3606d] MozillaCACerts_jll v2022.10.11 `@stdlib/MozillaCACerts_jll`
  [4536629a] OpenBLAS_jll v0.3.21+4 `@stdlib/OpenBLAS_jll`
  [05823500] OpenLibm_jll v0.8.1+0 `@stdlib/OpenLibm_jll`
  [bea87d4a] SuiteSparse_jll v5.10.1+6 `@stdlib/SuiteSparse_jll`
  [83775a58] Zlib_jll v1.2.13+0 `@stdlib/Zlib_jll`
  [8e850b90] libblastrampoline_jll v5.7.0+0 `@stdlib/libblastrampoline_jll`
  [8e850ede] nghttp2_jll v1.48.0+0 `@stdlib/nghttp2_jll`
  [3f19e933] p7zip_jll v17.4.0+0 `@stdlib/p7zip_jll`
Precompiling project...
  60 dependencies successfully precompiled in 95 seconds. 6 already precompiled.
     Testing Running tests...

     Testing Tests interrupted. Exiting the test process

ERROR: LoadError: InterruptException:
Stacktrace:
  [1] poptask(W::Base.IntrusiveLinkedListSynchronized{Task})
    @ Base .\task.jl:974
  [2] wait()
    @ Base .\task.jl:983
  [3] wait(c::Base.GenericCondition{Base.Threads.SpinLock}; first::Bool)
    @ Base .\condition.jl:130
  [4] wait
    @ .\condition.jl:125 [inlined]
  [5] wait_readnb(x::Base.PipeEndpoint, nb::Int64)
    @ Base .\stream.jl:416
  [6] read(stream::Base.PipeEndpoint)
    @ Base .\stream.jl:930
  [7] read(cmd::Cmd)
    @ Base .\process.jl:448
  [8] read
    @ .\process.jl:458 [inlined]
  [9] _analyze_stale_deps_1(pkg::Base.PkgId; ignore::Vector{Symbol})
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\7PMmc\src\stale_deps.jl:56
 [10] _analyze_stale_deps_1
    @ C:\Users\myerscoughk\.julia\packages\Aqua\7PMmc\src\stale_deps.jl:31 [inlined]
 [11] #30
    @ .\none:0 [inlined]
 [12] iterate
    @ .\generator.jl:47 [inlined]
 [13] collect(itr::Base.Generator{Vector{Base.PkgId}, Aqua.var"#30#31"{Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}}}})
    @ Base .\array.jl:782
 [14] analyze_stale_deps
    @ C:\Users\myerscoughk\.julia\packages\Aqua\7PMmc\src\stale_deps.jl:28 [inlined]
 [15] macro expansion
    @ C:\Users\myerscoughk\AppData\Local\Programs\Julia-1.9.0\share\julia\stdlib\v1.9\Test\src\Test.jl:1609 [inlined] 
 [16] test_stale_deps(packages::Module; kwargs::Base.Pairs{Symbol, Union{}, Tuple{}, NamedTuple{(), Tuple{}}})
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\7PMmc\src\stale_deps.jl:21
 [17] test_stale_deps(packages::Module)
    @ Aqua C:\Users\myerscoughk\.julia\packages\Aqua\7PMmc\src\stale_deps.jl:20
 [18] top-level scope
    @ C:\Users\myerscoughk\SQM\review\BrokenAqua.jl\test\runtests.jl:6
 [19] include(fname::String)
    @ Base.MainInclude .\client.jl:478
 [20] top-level scope
    @ none:6
in expression starting at C:\Users\myerscoughk\SQM\review\BrokenAqua.jl\test\runtests.jl:6

(BrokenAqua) pkg>
KeithWM commented 1 year ago

Tried it on a different Windows machine and there it passes on 1.8.3 and 1.9.0.

I tried it both before and after doing an up and it works in both cases. The only delta in the environment after an up compared to the test for 1.9.0 on the other machine posted above is 

  [2ab3a3ac] LogExpFunctions v0.3.24
  [aea7be01] PrecompileTools v1.1.2

I suspect these two packages happen to have had an update over the past day and a half.

So the issue does seem to be rare. Any ideas/suggestions/requests on other things to try?

fingolfin commented 1 year ago

Hmm... Could you please verify that using PlotlyJS on its own in the REPL works? Does it make a difference if you do it right before starting the Aqua test?

It might help to enable debug logging.

So right before you invoke Aqua, you could do ENV["JULIA_DEBUG"] = "all" and perhaps the additional logging will reveal something helpful.