Significant increase in maximum heap size in GCBenchmark #51601

d-netto · 2023-10-05T15:57:50Z

1.9:

bench = "pidigits.jl"
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ total time │ gc time │ mark time │ sweep time │ max GC pause │ time to safepoint │ max heap │ percent gc │
│         │         ms │      ms │        ms │         ms │           ms │                us │       MB │          % │
├─────────┼────────────┼─────────┼───────────┼────────────┼──────────────┼───────────────────┼──────────┼────────────┤
│ minimum │      49572 │     724 │        86 │        595 │           35 │                 0 │      113 │          1 │
│  median │      49572 │     724 │        86 │        595 │           35 │                 0 │      113 │          1 │
│ maximum │      49572 │     724 │        86 │        595 │           35 │                 0 │      113 │          1 │
│   stdev │        NaN │     NaN │       NaN │        NaN │          NaN │               NaN │      NaN │        NaN │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

master:

bench = "pidigits.jl"
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ total time │ gc time │ mark time │ sweep time │ max GC pause │ time to safepoint │ max heap │ percent gc │
│         │         ms │      ms │        ms │         ms │           ms │                us │       MB │          % │
├─────────┼────────────┼─────────┼───────────┼────────────┼──────────────┼───────────────────┼──────────┼────────────┤
│ minimum │     119559 │      44 │        37 │          7 │           40 │                 0 │   401283 │          0 │
│  median │     119559 │      44 │        37 │          7 │           40 │                 0 │   401283 │          0 │
│ maximum │     119559 │      44 │        37 │          7 │           40 │                 0 │   401283 │          0 │
│   stdev │        NaN │     NaN │       NaN │        NaN │          NaN │               NaN │      NaN │        NaN │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

CC: @gbaraldi

The text was updated successfully, but these errors were encountered:

d-netto · 2023-10-05T15:59:15Z

I didn't check RSS, so could be an accounting bug somewhere.

gbaraldi · 2023-10-05T16:22:37Z

I think it might the accounting change, where we now need to keep a global counter in sync. Though I need to check

d-netto · 2023-10-05T18:50:25Z

Measured again on Linux machine.

On 1.9 peak RSS is around 400MB-500MB.

On master it goes beyond 70GB and eventually fails at Serialization:

EOFError: read end of file
Stacktrace:
 [1] read(this::Base.PipeEndpoint, ::Type{UInt8})
   @ Base ./stream.jl:980
 [2] deserialize
   @ ~/julia-stock/usr/share/julia/stdlib/v1.11/Serialization/src/Serialization.jl:814 [inlined]
 [3] deserialize(s::Base.PipeEndpoint)
   @ Serialization ~/julia-stock/usr/share/julia/stdlib/v1.11/Serialization/src/Serialization.jl:801
 [4] run_bench(runs::Int64, threads::Int64, gcthreads::Int64, file::String, show_json::Bool)
   @ Main ~/GCBenchmarks/run_benchmarks.jl:68
 [5] run_category_files(benches::Vector{String}, args::Dict{String, Any}, show_json::Bool)
   @ Main ~/GCBenchmarks/run_benchmarks.jl:143
 [6] main(args::Dict{String, Any})
   @ Main ~/GCBenchmarks/run_benchmarks.jl:196
 [7] top-level scope
   @ ~/GCBenchmarks/run_benchmarks.jl:200

vchuravy · 2023-10-06T01:40:28Z

A few observations.

Our internal heap_size tracking matches 1:1 with the OS size tracking. It is thus not an issue of metrics.
Running: ./usr/bin/julia --heap-size-hint=5G -e "GC.enable_logging(true)" -L pidigits.jl allows it to finish without using excessive memory.
Without --heap-size-hint we never run a full collection

./usr/bin/julia  -e "GC.enable_logging(true)" -L pidigits.jl 

GC: pause 27.69ms. collected 4.255280MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 40.83 MB, heap_target 43.75 MB, Fragmentation 0.019

GC: pause 2.63ms. collected 0.811043MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 42.94 MB, heap_target 43.75 MB, Fragmentation 0.909

GC: pause 0.30ms. collected 0.250763MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 43.54 MB, heap_target 87.29 MB, Fragmentation 1.799

GC: pause 0.51ms. collected 0.261078MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 87.08 MB, heap_target 174.58 MB, Fragmentation 1.363

GC: pause 0.66ms. collected 0.407867MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 174.22 MB, heap_target 305.47 MB, Fragmentation 1.162

GC: pause 0.84ms. collected 0.610123MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 304.92 MB, heap_target 523.67 MB, Fragmentation 1.224

GC: pause 1.23ms. collected 0.783508MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 522.95 MB, heap_target 785.45 MB, Fragmentation 1.290

GC: pause 1.17ms. collected 0.982773MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 784.54 MB, heap_target 1134.54 MB, Fragmentation 1.522

GC: pause 1.31ms. collected 1.117645MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 1133.51 MB, heap_target 1571.01 MB, Fragmentation 1.742

GC: pause 1.44ms. collected 1.260193MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 1569.84 MB, heap_target 2051.09 MB, Fragmentation 2.006

GC: pause 1.53ms. collected 1.396393MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 2049.79 MB, heap_target 2618.54 MB, Fragmentation 2.355

GC: pause 1.69ms. collected 1.493652MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 2617.20 MB, heap_target 4935.95 MB, Fragmentation 2.682

GC: pause 2.86ms. collected 1.593231MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 4934.47 MB, heap_target 8609.47 MB, Fragmentation 1.990

GC: pause 3.37ms. collected 2.464508MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 8607.16 MB, heap_target 14382.16 MB, Fragmentation 1.755

GC: pause 4.86ms. collected 3.399841MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 14378.99 MB, heap_target 21422.74 MB, Fragmentation 1.691

GC: pause 5.00ms. collected 4.419952MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 21418.56 MB, heap_target 29424.81 MB, Fragmentation 1.855

GC: pause 5.68ms. collected 5.157379MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 29419.79 MB, heap_target 37951.04 MB, Fragmentation 2.130

GC: pause 5.75ms. collected 5.669830MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 37945.53 MB, heap_target 47001.78 MB, Fragmentation 2.482

GC: pause 7.55ms. collected 5.999664MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 46996.11 MB, heap_target 57014.86 MB, Fragmentation 2.870

GC: pause 6.24ms. collected 6.241821MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 57008.88 MB, heap_target 67640.13 MB, Fragmentation 3.249

GC: pause 6.45ms. collected 6.479736MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 67633.97 MB, heap_target 78177.72 MB, Fragmentation 3.642

GC: pause 6.50ms. collected 6.677643MB. incr 
Heap stats: bytes_mapped 64.02 MB, bytes_resident 64.02 MB,
heap_size 78171.33 MB, heap_target 89152.58 MB, Fragmentation 4.078

Note the collected stat is wrong, since the GC aware free is happening from a finalizer.
Since GMP uses a finalizer and if enough objects per GC cycle get promoted to old.
without a full GC it does look like a memory leak.

gbaraldi · 2023-10-06T02:47:04Z

I found the issue, and it's quite fun. What happens here is that the GC thinks nothing is getting freed during the GC. Because the heap barely changes size, except that the heap goes down a lot when running finalizers, so for example, if the heap size before the GC was 4.5 and after sweep it's 4, the heuristics go and assume that to devise a new target. Except that running finalizers brings the heap down to 0.2, but the heuristics have no idea.

KristofferC · 2023-10-10T14:39:54Z

Two questions:

Is this also relevant for 1.10? All the measurements seem to be against master.
@gbaraldi, since you understand the cause, do you have a fix for this?

gbaraldi · 2023-10-10T14:55:24Z

This does affect 1.10, and I have a tentative solution.

The 1.10 GC heuristics introduced in #50144 have been a source of concerning issues such as #50705 and #51601. The PR also doesn't correctly implement the paper on which it's based, as discussed in #51498. Test whether the 1.8 GC heuristics are a viable option.

d-netto · 2023-10-20T23:41:59Z

Removing this issue from the 1.10 milestone since it's fixed by #51661.

The issue persists on master.

vtjnash · 2023-12-07T19:27:44Z

Fixed by #51611 (comment)

d-netto added this to the 1.10 milestone Oct 5, 2023

d-netto added regression Regression in behavior compared to a previous version GC Garbage collector labels Oct 5, 2023

d-netto mentioned this issue Oct 5, 2023

Take default GC choices always #51564

Closed

d-netto mentioned this issue Oct 6, 2023

Move heap_size batching code into pair of functions #51611

Merged

d-netto mentioned this issue Oct 10, 2023

Revert 1.10 GC back to 1.8 GC heuristics #51661

Merged

d-netto removed this from the 1.10 milestone Oct 20, 2023

thofma mentioned this issue Dec 7, 2023

gc: add some guard rails and refinements to MemBalancer #52197

Merged

vtjnash closed this as completed Dec 7, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Significant increase in maximum heap size in GCBenchmark #51601

Significant increase in maximum heap size in GCBenchmark #51601

d-netto commented Oct 5, 2023

d-netto commented Oct 5, 2023

gbaraldi commented Oct 5, 2023

d-netto commented Oct 5, 2023

vchuravy commented Oct 6, 2023

gbaraldi commented Oct 6, 2023

KristofferC commented Oct 10, 2023

gbaraldi commented Oct 10, 2023

d-netto commented Oct 20, 2023 •

edited

Loading

vtjnash commented Dec 7, 2023

Significant increase in maximum heap size in GCBenchmark #51601

Significant increase in maximum heap size in GCBenchmark #51601

Comments

d-netto commented Oct 5, 2023

d-netto commented Oct 5, 2023

gbaraldi commented Oct 5, 2023

d-netto commented Oct 5, 2023

vchuravy commented Oct 6, 2023

gbaraldi commented Oct 6, 2023

KristofferC commented Oct 10, 2023

gbaraldi commented Oct 10, 2023

d-netto commented Oct 20, 2023 • edited Loading

vtjnash commented Dec 7, 2023

d-netto commented Oct 20, 2023 •

edited

Loading