Significant GC collection time in Pkg.add (and other performance related things)

[KristofferC]

julia> @time Pkg.add("Plots")
   Resolving package versions...
  No Changes to `~/.julia/environments/v1.11/Project.toml`
  No Changes to `~/.julia/environments/v1.11/Manifest.toml`
  0.785516 seconds (4.85 M allocations: 359.270 MiB, 24.80% gc time)

julia> @time Pkg.add("Plots")
   Resolving package versions...
  No Changes to `~/.julia/environments/v1.11/Project.toml`
  No Changes to `~/.julia/environments/v1.11/Manifest.toml`
  0.767055 seconds (4.85 M allocations: 359.259 MiB, 23.82% gc time)

20%+ GC time. Should not be needed...

Tangentially, the no-op precompile check in the end of Pkg.add is a quite significant contributor to the timing above:

julia> ENV["JULIA_PKG_PRECOMPILE_AUTO"] = 0
0

julia> @time Pkg.add("Plots")
   Resolving package versions...
  No Changes to `/tmp/jl_lIIjwR/Project.toml`
  No Changes to `/tmp/jl_lIIjwR/Manifest.toml`
  0.538715 seconds (4.05 M allocations: 271.299 MiB, 33.17% gc time)

[vchuravy]

Should not be needed...

Tough to say, on the other hand the code allocates ~360MiB to do "nothing" and someone needs to pay the cost of cleaning that up. I don't find it surprising that the code hits at least one GC pause.

[KristofferC]

Tough to say, on the other hand the code allocates ~360MiB to do "nothing"

Yeah, the point is not to blame the GC but to say we shouldn't need to allocate so much temp stuff (5M allocations...).

[KristofferC]

I added a branch here https://github.com/JuliaLang/Pkg.jl/tree/kc/timeroutput to do some TimerOutputting:

julia> @time Pkg.add("Plots")
   Resolving package versions...
No packages added to or removed from `/tmp/jl_2HO1zH/Project.toml`
No packages added to or removed from `/tmp/jl_2HO1zH/Manifest.toml`
───────────────────────────────────────────────────────────────────────────────────────────────
                                                      Time                    Allocations      
                                             ───────────────────────   ────────────────────────
              Tot / % measured:                   676ms /  99.5%            291MiB /  99.2%    

Section                              ncalls     time    %tot     avg     alloc    %tot      avg
───────────────────────────────────────────────────────────────────────────────────────────────
add                                       1    673ms  100.0%   673ms    289MiB  100.0%   289MiB
  add                                     1    673ms  100.0%   673ms    289MiB  100.0%   289MiB
    download_artifacts                    1    353ms   52.5%   353ms   75.8MiB   26.3%  75.8MiB
    _resolve                              1    312ms   46.4%   312ms    206MiB   71.3%   206MiB
      tiered_resolve                      1    312ms   46.4%   312ms    206MiB   71.3%   206MiB
        targeted_resolve                  1    312ms   46.4%   312ms    206MiB   71.3%   206MiB
          resolve_versions!               1    312ms   46.4%   312ms    206MiB   71.3%   206MiB
            deps_graph                    1    160ms   23.8%   160ms    169MiB   58.7%   169MiB
              Resolve.Graph               1    140ms   20.9%   140ms    136MiB   47.2%   136MiB
            Resolve.simplify_graph        1    152ms   22.5%   152ms   36.0MiB   12.5%  36.0MiB
            collect_fixed!                1   33.2μs    0.0%  33.2μs   13.6KiB    0.0%  13.6KiB
            Resolve.resolve               1   18.7μs    0.0%  18.7μs   66.3KiB    0.0%  66.3KiB
            collect_developed             1    546ns    0.0%   546ns   1.66KiB    0.0%  1.66KiB
    download_source                       1    377μs    0.1%   377μs    222KiB    0.1%   222KiB
    update_manifest!                      1    148μs    0.0%   148μs    250KiB    0.1%   250KiB
    _auto_precompile                      1   1.64μs    0.0%  1.64μs     32.0B    0.0%    32.0B
───────────────────────────────────────────────────────────────────────────────────────────────
  0.676781 seconds (4.29 M allocations: 291.008 MiB, 32.78% gc time)

download_artifacts taking 353ms and 75MB to do nothing feels excessive.

Also the Resolve.Graph allocates 136 MB.

[KristofferC]

The download_artifacts is taken care of by #4117.