Importing Plots increasing garbage collection

General Usage
1

It seems that importing Plots is significantly increasing the mean % garbage collection time when executing this function motif2. Does anyone know why, and how to prevent it?

julia> using BenchmarkTools

julia> function motif2(v::Vector{Vector{Float64}})     
           out = Vector{Float64}(undef, sum(length, v))
           offset = 0
           for vect in v
               for i ∈ eachindex(vect)
                   @inbounds out[offset + i] = vect[i] 
               end
               offset += lastindex(vect)
           end
           out
       end
motif2 (generic function with 1 method)

julia> vects = [rand(10) for i = 1:10];

julia> @benchmark motif2($vects)
BenchmarkTools.Trial: 10000 samples with 984 evaluations.
 Range (min … max):  54.675 ns …  1.503 μs  ┊ GC (min … max): 0.00% … 63.57%
 Time  (median):     76.321 ns              ┊ GC (median):    0.00%
 Time  (mean ± σ):   97.977 ns ± 78.032 ns  ┊ GC (mean ± σ):  6.96% ±  9.13%

   ▆█▆▄▄▃▃▃▂▂▁▁                                               ▂
  ██████████████▇█▇██▇██▆█▇▇▆▆▆▆▅▅▄▅▃▄▁▄▅▅▆▆▅▅▆▆▄▅▄▄▃▅▄▄▄▅▆▅▅ █
  54.7 ns      Histogram: log(frequency) by time       539 ns <

 Memory estimate: 896 bytes, allocs estimate: 1.

julia> using Plots

julia> @benchmark motif2($vects)
BenchmarkTools.Trial: 7273 samples with 978 evaluations.
 Range (min … max):   69.734 ns … 44.415 μs  ┊ GC (min … max):  0.00% … 99.23%
 Time  (median):      87.628 ns              ┊ GC (median):     0.00%
 Time  (mean ± σ):   704.629 ns ±  4.747 μs  ┊ GC (mean ± σ):  77.36% ± 11.30%

  █                                                            ▁
  █▆▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▇ █
  69.7 ns       Histogram: log(frequency) by time      41.4 μs <

 Memory estimate: 896 bytes, allocs estimate: 1.

julia> versioninfo()
Julia Version 1.8.2
Commit 36034abf26 (2022-09-29 15:21 UTC)
Platform Info:
  OS: Windows (x86_64-w64-mingw32)
  CPU: 16 × 11th Gen Intel(R) Core(TM) i7-11800H @ 2.30GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-13.0.1 (ORCJIT, tigerlake)
  Threads: 16 on 16 virtual cores
Environment:
  JULIA_EDITOR = code
  JULIA_NUM_THREADS = 16

This is partially replicable, e.g. on a remote (linux) machine I see an increase in % GC time, though not quite to the extent I’m seeing on my local machine (the example above):

julia> using BenchmarkTools

julia> function motif2(v::Vector{Vector{Float64}})
           out = Vector{Float64}(undef, sum(length, v))
           offset = 0
           for vect in v
               for i ∈ eachindex(vect)
                   @inbounds out[offset + i] = vect[i]
               end
               offset += lastindex(vect)
           end
           out
       end
motif2 (generic function with 1 method)

julia> vects = [rand(10) for i = 1:10];

julia> @benchmark motif2($vects)
BenchmarkTools.Trial: 10000 samples with 719 evaluations.
 Range (min … max):  150.026 ns …  15.705 μs  ┊ GC (min … max): 0.00% … 0.00%
 Time  (median):     198.854 ns               ┊ GC (median):    0.00%
 Time  (mean ± σ):   242.629 ns ± 289.033 ns  ┊ GC (mean ± σ):  4.84% ± 7.61%

  ▄█▇▆▅▃▁                                                       ▂
  ███████▇▇▇▇▇▆▅▅▆▅▅▅▅▅▆▆▆▄▅▃▄▁▃▄▃▁▃▁▄▄▃▄▅▄▅▅▅▆▆▅▄▆▅▅▆▅▄▅▆▆▄▄▄▅ █
  150 ns        Histogram: log(frequency) by time       1.52 μs <

 Memory estimate: 896 bytes, allocs estimate: 1.

julia> using Plots

julia> @benchmark motif2($vects)
BenchmarkTools.Trial: 10000 samples with 695 evaluations.
 Range (min … max):  156.403 ns …  11.613 μs  ┊ GC (min … max):  0.00% … 0.00%
 Time  (median):     202.976 ns               ┊ GC (median):     0.00%
 Time  (mean ± σ):   293.527 ns ± 390.842 ns  ┊ GC (mean ± σ):  11.85% ± 9.58%

  █▇▅▅▃▁    ▁▂▂▂                                                ▂
  ██████▆▇▆▆██████▇▇▇▇▆▅▁▁▁▃▃▁▁▁▁▁▁▁▁▃▁▁▁▁▁▁▁▁▁▁▁▃▁▁▁▁▁▁▄▄▅▅▅▅▅ █
  156 ns        Histogram: log(frequency) by time       2.81 μs <

 Memory estimate: 896 bytes, allocs estimate: 1.

julia> @benchmark motif2($vects)
BenchmarkTools.Trial: 10000 samples with 888 evaluations.
 Range (min … max):  167.446 ns …  12.581 μs  ┊ GC (min … max):  0.00% …  0.00%
 Time  (median):     196.846 ns               ┊ GC (median):     0.00%
 Time  (mean ± σ):   272.220 ns ± 340.188 ns  ┊ GC (mean ± σ):  12.18% ± 10.38%

  █▇          ▁▃▂▂                                              ▁
  ███▇▇▇▆▆▆▆▆▇█████▄▄▁▁▁▁▁▁▁▁▁▁▃▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▁▄▄▄▅▅▅▆▅▆▆▆ █
  167 ns        Histogram: log(frequency) by time       2.43 μs <

 Memory estimate: 896 bytes, allocs estimate: 1.

julia> versioninfo()
Julia Version 1.8.2
Commit 36034abf260 (2022-09-29 15:21 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 4 × Intel(R) Xeon(R) CPU E5-2640 v4 @ 2.40GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-13.0.1 (ORCJIT, broadwell)
  Threads: 1 on 4 virtual cores
Environment:
  LD_LIBRARY_PATH = /apps/system/easybuild/software/Julia/1.8.2-linux-x86_64/lib

Although % GC is quantitatively quite different on the two machines, it seems that there’s a consistent increase after importing Plots. Any ideas as to why?

2

Worth noting that removing and re-adding Plots has no effect, on either machine

3

It looks like this could be due to a single slow run where the GC was triggered and might have done a full sweep. If you look at the second benchmark, the maximum time is about 10x larger than the median time, this will have a large effect on the mean. The median is probably a more robust estimator here.

There still appears to be somewhat of a difference though, since all times have increased slightly.

4

Yeah I think the fact there’s an increase across the board is perplexing