Package CI performance regression

[LilithHafner]

This NFC PR to Chairmarks apparently made CI on nightly substantially (>2x) slower. I suspect the regression is due to a change in Julia.

Fast (https://github.com/LilithHafner/Chairmarks.jl/actions/runs/8147371039/job/22267929268)

Julia Version 1.12.0-DEV.124
Commit 0311aa4caf (2024-03-04 16:34 UTC)

Slow (https://github.com/LilithHafner/Chairmarks.jl/actions/runs/8174911720/job/22350814940)

Julia Version 1.12.0-DEV.138
Commit 90d84d4ab00 (2024-03-06 00:32 UTC)

Diff
https://github.com/JuliaLang/julia/compare/0311aa4caf..90d84d4ab00

See also: #53439

[Zentrik]

Bisected to fb71a5d

Bisect Script

using Downloads, CodecZlib, Tar, LibGit2

start_sha = "0311aa4caf461d05fb408de67dafc582e2ada9a0"
end_sha = "90d84d4ab00a34cd9c75b06b77925aaf8afbabfd"

bisect_command = raw"""
using Pkg, Test
Pkg.add("Chairmarks")
t = @timed try
    Pkg.test("Chairmarks")
catch
end
t.time
"""

function run_commit(file, commit, os, arch)
    version_full = read(`contrib/commit-name.sh $commit`, String)
    major_minor_version = split(version_full, '.')[1:2] |> x->join(x, '.')

    binary_url = "https://julialangnightlies-s3.julialang.org/bin/$os/$arch/$major_minor_version/julia-$(commit[1:10])-$os-$arch.tar.gz"
    download_path = Downloads.download(binary_url)

    result = mktempdir() do binary_dir
        # extract
        open(download_path) do io
            stream = GzipDecompressorStream(io)
            Tar.extract(stream, binary_dir)
        end

        read(Cmd(
            `$binary_dir/julia-$(commit[1:10])/bin/julia --project=$binary_dir -E include\(\"$(file[1])\"\)`,
            ignorestatus=true
            ), String
        )
    end

    parse(Float64, result)
end

function bisect_perf(bisect_command, start_sha, end_sha, factor=1.5, os="linux", arch="x86_64")
    dir = mktempdir()
    cd(dir)
    repo = LibGit2.clone("https://github.com/JuliaLang/julia.git", dir)

    # Get the start and end commit objects
    start_commit = LibGit2.GitCommit(repo, start_sha)
    end_commit = LibGit2.GitCommit(repo, end_sha)

    # Get the commit range
    commit_range::Vector{String} = LibGit2.with(LibGit2.GitRevWalker(repo)) do walker
        LibGit2.map((oid, repo)->string(oid), walker; range=string(LibGit2.GitHash(start_commit))*".."*string(LibGit2.GitHash(end_commit)), by=LibGit2.Consts.SORT_REVERSE)
    end
    pushfirst!(commit_range, start_sha)

    # Test script, makes it easy to run bisect command
    file = mktemp()
    write(file[1], bisect_command)

    original_time = run_commit(file, start_sha, os, arch)
    println("Starting commit took $original_time")

    left = 1
    right = length(commit_range)
    i = 0
    while left < right
        i = (left + right) ÷ 2
        commit = commit_range[i]

        result = run_commit(file, commit, os, arch)
        
        println("Commit $commit " * (result <= factor * original_time ? "succeeded" : "failed") * " in $result")

        if result <= factor * original_time
            left = i + 1
        else
            right = i
        end
    end

    return left, commit_range[left]
end

bisect_perf(bisect_command, start_sha, end_sha)

[LilithHafner]

Thanks for the bisection! I don't suppose I could tempt you into figuring out which of the PRs to Pkg is responsible? There are only 4 candidates (listed here) and I suspect that JuliaLang/Pkg.jl#3820 is the culprit but it would be nice to know for sure.

[IanButterworth]

What is the latest master version tested here? There's been some instability

[LilithHafner]

As of today (LilithHafner/Chairmarks.jl#77)

Julia Version 1.12.0-DEV.154
Commit 53048b2ab1e (2024-03-09 10:44 UTC)

Chairmarks still takes about 2x longer to test on nightly than on 1.10.

[IanButterworth]

Would you mind looking into the log line times to see where the main regressions are? Currently I'm looking into Base precompile sysimage/pkgimage coverage regression

[KristofferC]

Pkg is not loaded into the process doing the testing and

Test Summary: |   Pass  Broken   Total     Time
Chairmarks    | 632151       7  632158  2m10.5s

shows that it is the testing itself that is slower?

So the only impact I can see from Pkg directly is the precompile files it generates. And the commits in that list touch that. So maybe it has something to do with that. Or something completely different.

[LilithHafner]

In the OP

• julia-buildpkg went from 5s to 42s
• cache went from 5s to 17s
• julia-processcoverage went from 4s to 47s
• julia-runtest went from 100s to 187s (+87s)
• testing itself (a subset of julia-runtest) went from 89s to 131s (+42s)

It looks like a combination of most parts of the pipeline getting slower.

[Zentrik]

I only bisected the testing itself, so it's possible that the other slowdowns are from some other commit.

I don't suppose I could tempt you into figuring out which of the PRs to Pkg is responsible?

I think to test the different commits I'm supposed to just do add https://github.com/JuliaLang/Pkg.jl/commit/e7d740ac82fa4c289bb58f9acb6e60eebb6d8a8e.
If that's true, the timings I was getting were far too noisy to work out what was going on.

[LilithHafner]

To be honest, I don't know what the best way to bisect this within Pkg.jl is. Rebuilding Julia from source using a different Pkg version would probably do it, but I'm guessing that's a bit involved. It might be best to hand if over to @KristofferC who authored all 4 of those commits.

[giordano]

I don't know what the best way to bisect this within Pkg.jl is.

Did you try to follow: https://github.com/JuliaLang/Pkg.jl/blob/e0821116e9f4364a2b37a77183e93d055a111f4d/README.md#using-the-development-version-of-pkgjl?

[IanButterworth]

You don't need to change the UUID anymore, just set --project to the Pkg repo on startup