27% slow down in inferring Base.init_stdio benchmark due to #53403

[Zentrik]

["inference", "allinference", "Base.init_stdio(::Ptr{Cvoid})"] and ["inference", "abstract interpretation", "Base.init_stdio(::Ptr{Cvoid})"] slowed down and increased memory allocations by ~25% (report).

I bisected the first benchmark to #53403.

[KristofferC]

Could you show the exact code you ran?

#53403 doesn't touch inference and e.g. Base.init_stdio shouldn't reach the added code.

[Zentrik]

The code was essentially just run(BaseBenchmarks.SUITE[["inference", "allinference", "Base.init_stdio(::Ptr{Cvoid})"]]), I did also run ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0 and I used the binaries from BuildKite if that makes a difference.

Full Script

The bisect_command at the end of the script is probably what you care about.

using Downloads, CodecZlib, Tar, GitHub
using HTTP, JSON3

function get_binaryurl(sha)
    url = "https://buildkite.com/julialang/julia-master/builds?commit=$sha"

    r = HTTP.get(url)
    html = String(r.body)

    build_num = match(r"julialang/julia-master/builds/(\d+)", html).captures[1]

    # Could get job using https://buildkite.com/julialang/julia-master/builds/31230.json instead
    build_url = "https://buildkite.com/" * match(r"julialang/julia-master/builds/\d+", html).match * "/waterfall"
    r = HTTP.get(build_url)
    html = String(r.body)

    job_url = match(Regex("""href="(.+)"><span title=":linux: build x86_64-linux-gnu">"""), html).captures[1]
    job = split(job_url, '#')[2]

    artifacts_url = "https://buildkite.com/organizations/julialang/pipelines/julia-master/builds/$build_num/jobs/$job/artifacts"
    return "https://buildkite.com/" * (HTTP.get(artifacts_url).body |> JSON3.read)[1].url
end

function run_commit(file, commit)
    binary_url = get_binaryurl(commit)
    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 --startup-file=no --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)
    julia_repo = repo(Repo("JuliaLang/julia"))
    commit_range = map(x->x.sha, compare(julia_repo, start_sha, end_sha).commits)
    push!(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)
    printstyled("Starting commit took $original_time\n", color=:red)

    end_time = run_commit(file, end_sha)
    printstyled("End commit took $end_time\n", color=:red)

    if end_time <= factor * original_time
        return
    end

    failed_commits = String[]

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

        result = try
            run_commit(file, commit)
        catch
            push!(failed_commits, commit)
            deleteat!(commit_range, i)
            right = right - 1
            continue
        end

        printstyled("Commit $commit " * ((result <= factor * original_time) ? "succeeded" : "failed") * " in $result\n", color=:red)

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

    return commit_range[left], failed_commits
end

bisect_command = raw"""
ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0

using Pkg
Pkg.add(url="https://github.com/JuliaCI/BaseBenchmarks.jl", io=devnull)
using BaseBenchmarks

BaseBenchmarks.load!("inference")
res = run(BaseBenchmarks.SUITE[["inference", "allinference", "Base.init_stdio(::Ptr{Cvoid})"]])

minimum(res).time
"""
bisect_perf(bisect_command, "f66fd47f2daa9a7139f72617d74bbd1efaafd766", "5c7d24493ebab184d4517ca556314524f4fcb47f"; factor=1.2)

Unfortunately, I no longer have the output but it identified 6745160 as the first bad commit with a roughly 20% regression.

Afterwards, to check if the memory allocations regressed due to this commit I ran

bisect_command = raw"""
ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0

using Pkg
Pkg.add(url="https://github.com/JuliaCI/BaseBenchmarks.jl", io=devnull)
using BaseBenchmarks

BaseBenchmarks.load!("inference")
res = run(BaseBenchmarks.SUITE[["inference", "allinference", "Base.init_stdio(::Ptr{Cvoid})"]])

res.memory
"""
bisect_perf(bisect_command, "50114d7a1fce1701cf53dafcfc6bafb193afb2e5", "67451604cf463c912c2325eb5990ad46262468c2"; factor=1.2)

50114d7 returned 1.332281704e9, and 6745160 was around 1.18x that, I don't have the exact number.

[Zentrik]

FWIW, NanoSoldier also shows that it was 6745160 though it only finds a 15% regression. See here noting that 6745160 was the only non-doc commit in that range.

[IanButterworth]

Does this regression still exist on latest master?

[KristofferC]

There was a some comment by @vtjnash that this could happen if the compiler just saw more code so it isn't really a relevant benchmark to look at for things that don't touch the compiler.

[Zentrik]

Should we close this then?