GC and multithreading. Strange behaviour.

[sgaure]

While investigating some strange slowdowns I've disovered a behaviour of the GC I do not understand.

Here is a MWE. It's a bit complicated. I have 500000 short vectors which I take a large sample from (50 million, with replacement). Then there's an alternative where the individual vectors are replaced by a struct containing two references to the vector.

When I do an operation on the vector of vectors, it's all like I would expect. The GC is exercised, but nothing too extreme. When it's a vector of structs, and in addition the actual work is done in a single @spawn which is immediately fetched, I sometimes get up to 20 seconds of GC activity. This is on master. On 1.10.2 it's up to 50 seconds. With more vectors, the GC may run for several minutes.

I see no intuitive reason for this behaviour which only appears when a fetch(@spawn work(v)) is done, not with work(v). I have a 64GB 12 core AMD, with 24 virtual cores. If I run with -t 12 this strange behaviour does not seem happen. It does however happen with -t 24 --gcthreads=4, with GC time up to 40 seconds.

using Base.Threads: @spawn
using InteractiveUtils: versioninfo
using StatsBase: sample

struct Astruct
    v1::Vector{Float64}
    v2::Vector{Float64}
    Astruct(v) = new(v,v)
end
Base.getindex(as::Astruct, i) = as.v1[i]

function work(vvec)
    x = 0.0
    for v in vvec
        x += v[1]
    end
    return x
end


fun(v, par) = par ? fetch(@spawn work(v))::Float64 : work(v)

test(v, N) = @time "serial" fun(sample(v, N), false)

partest(v, N) = @time "parallel" fun(sample(v, N), true)


versioninfo()

const N = 500_000
const v = [rand(10) for _ in 1:N]
const as = Astruct.(v)


println("***** Vector *****")
GC.gc()
for _ in 1:10
    test(v, 100N)
end
GC.gc()
for _ in 1:10
    partest(v, 100N)
end

println("\n***** Astruct *****")
GC.gc()
for _ in 1:10
    test(as, 100N)
end
GC.gc()
for _ in 1:10
    partest(as, 100N)
end

Output:

Julia Version 1.12.0-DEV.383
Commit 903ffff167* (2024-04-22 04:40 UTC)
Platform Info:
  OS: Linux (x86_64-linux-gnu)
  CPU: 24 × AMD Ryzen Threadripper PRO 5945WX 12-Cores
  WORD_SIZE: 64
  LLVM: libLLVM-16.0.6 (ORCJIT, znver3)
Threads: 24 default, 0 interactive, 24 GC (on 24 virtual cores)
Environment:
  JULIA_NUM_THREADS = auto
***** Vector *****
serial: 0.790318 seconds (3 allocations: 381.470 MiB, 0.55% gc time)
serial: 0.820720 seconds (3 allocations: 381.470 MiB, 4.01% gc time)
serial: 0.823082 seconds (3 allocations: 381.470 MiB, 3.90% gc time)
serial: 0.812152 seconds (3 allocations: 381.470 MiB, 3.73% gc time)
serial: 0.811470 seconds (3 allocations: 381.470 MiB, 3.76% gc time)
serial: 0.803246 seconds (3 allocations: 381.470 MiB, 3.78% gc time)
serial: 0.815217 seconds (3 allocations: 381.470 MiB, 3.75% gc time)
serial: 0.815175 seconds (3 allocations: 381.470 MiB, 3.79% gc time)
serial: 0.807833 seconds (3 allocations: 381.470 MiB, 3.76% gc time)
serial: 0.821069 seconds (3 allocations: 381.470 MiB, 3.67% gc time)
parallel: 0.847207 seconds (3.33 k allocations: 381.640 MiB, 0.28% gc time, 0.93% compilation time)
parallel: 0.850981 seconds (9 allocations: 381.470 MiB, 1.21% gc time)
parallel: 0.886037 seconds (9 allocations: 381.470 MiB, 12.49% gc time)
parallel: 0.776483 seconds (9 allocations: 381.470 MiB)
parallel: 0.962529 seconds (9 allocations: 381.470 MiB, 14.78% gc time)
parallel: 0.985055 seconds (9 allocations: 381.470 MiB, 19.63% gc time)
parallel: 0.831015 seconds (9 allocations: 381.470 MiB, 4.25% gc time)
parallel: 0.840257 seconds (9 allocations: 381.470 MiB, 4.67% gc time)
parallel: 0.838799 seconds (9 allocations: 381.470 MiB, 4.48% gc time)
parallel: 0.859712 seconds (9 allocations: 381.470 MiB, 4.76% gc time)

***** Astruct *****
serial: 0.947084 seconds (3 allocations: 762.940 MiB, 0.39% gc time)
serial: 0.990493 seconds (3 allocations: 762.940 MiB, 5.19% gc time)
serial: 0.978335 seconds (3 allocations: 762.940 MiB, 4.95% gc time)
serial: 0.976766 seconds (3 allocations: 762.940 MiB, 4.94% gc time)
serial: 0.975440 seconds (3 allocations: 762.940 MiB, 5.05% gc time)
serial: 0.977785 seconds (3 allocations: 762.940 MiB, 4.94% gc time)
serial: 0.980397 seconds (3 allocations: 762.940 MiB, 4.95% gc time)
serial: 0.976771 seconds (3 allocations: 762.940 MiB, 4.94% gc time)
serial: 0.982649 seconds (3 allocations: 762.940 MiB, 4.94% gc time)
serial: 0.981036 seconds (3 allocations: 762.940 MiB, 4.92% gc time)
parallel: 0.952661 seconds (3.42 k allocations: 763.113 MiB, 0.23% gc time, 0.77% compilation time)
parallel: 8.064466 seconds (9 allocations: 762.940 MiB, 88.19% gc time)
parallel: 0.940224 seconds (9 allocations: 762.940 MiB)
parallel: 14.162925 seconds (9 allocations: 762.940 MiB, 93.19% gc time)
parallel: 0.930567 seconds (9 allocations: 762.940 MiB)
parallel: 0.926054 seconds (9 allocations: 762.940 MiB)
parallel: 14.008024 seconds (9 allocations: 762.940 MiB, 93.24% gc time)
parallel: 0.942324 seconds (9 allocations: 762.940 MiB)
parallel: 0.938320 seconds (9 allocations: 762.940 MiB)
parallel: 20.819898 seconds (9 allocations: 762.940 MiB, 95.42% gc time)

[gbaraldi]

I can reproduce this failure pretty reliably on my mac

[vchuravy]

Can you change:

function work(vvec)
    x = 0.0
    for v in vvec
        x += v[1]
        GC.safepoint()
    end
    return x
end

x-ref: #53441

@gbaraldi tested locally and it doesn't seem to be TTSP

[sgaure]

I see the same behaviour on my home computer (8-core AMD, 16 virtual, 32GB).

I've added the GC.safepoint(). It then runs a little bit slower, but exhibits the same behaviour. I added a GC.enable_logging() just before the final loop, and get output like this:

GC: pause 2.47ms. collected 2.212631MB. incr 
Heap stats: bytes_mapped 128.03 MB, bytes_resident 125.77 MB,
heap_size 2396.50 MB, heap_target 2857.47 MB, Fragmentation 0.676
parallel: 2.907488 seconds (3.46 k allocations: 763.115 MiB, 0.09% gc time, 0.57% compilation time)

GC: pause 54606.31ms. collected 0.175213MB. incr 
Heap stats: bytes_mapped 128.03 MB, bytes_resident 125.77 MB,
heap_size 3159.47 MB, heap_target 4578.44 MB, Fragmentation 0.754
parallel: 57.575935 seconds (9 allocations: 762.940 MiB, 94.84% gc time)
parallel: 2.794884 seconds (9 allocations: 762.940 MiB)

GC: pause 111046.63ms. collected 0.003555MB. incr 
Heap stats: bytes_mapped 128.03 MB, bytes_resident 125.77 MB,
heap_size 4685.34 MB, heap_target 6295.01 MB, Fragmentation 0.671
parallel: 113.891304 seconds (9 allocations: 762.940 MiB, 97.50% gc time)
parallel: 2.858441 seconds (9 allocations: 762.940 MiB)
parallel: 2.933410 seconds (9 allocations: 762.940 MiB)

GC: pause 109319.78ms. collected 2288.825127MB. full 
Heap stats: bytes_mapped 128.03 MB, bytes_resident 125.77 MB,
heap_size 4685.34 MB, heap_target 6581.12 MB, Fragmentation 0.997
parallel: 112.186802 seconds (9 allocations: 762.940 MiB, 97.44% gc time)
parallel: 2.859512 seconds (9 allocations: 762.940 MiB)
parallel: 2.884207 seconds (9 allocations: 762.940 MiB)

GC: pause 111792.86ms. collected 2670.297150MB. incr 
Heap stats: bytes_mapped 128.03 MB, bytes_resident 125.77 MB,
heap_size 4303.84 MB, heap_target 6199.61 MB, Fragmentation 1.085
parallel: 114.707073 seconds (9 allocations: 762.940 MiB, 97.46% gc time)