Pathological GC time on M1 mac

[Keno]

M1 mac:

category = "linked"
bench = "list.jl"
  No Changes to `~/GCBenchmarks/benches/serial/linked/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/linked/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │      50297 │   48807 │     41368 │       7439 │         2172 │                 6 │     4034 │         97 │
│  median │      54143 │   52600 │     44078 │       8607 │         3089 │                 9 │     4048 │         97 │
│ maximum │      89575 │   88079 │     74315 │      13758 │         4959 │                27 │     4072 │         98 │
│   stdev │      11430 │   11436 │      9714 │       1845 │          928 │                 8 │       14 │          0 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

x86 server:

category = "linked"
bench = "list.jl"
  No Changes to `~/GCBenchmarks/benches/serial/linked/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/linked/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │       7205 │    4740 │      3419 │       1320 │         1625 │                 6 │     2557 │         63 │
│  median │       7455 │    5015 │      3637 │       1369 │         1807 │                 7 │     2600 │         66 │
│ maximum │       8035 │    5657 │      4266 │       1416 │         2395 │                10 │     2622 │         69 │
│   stdev │        300 │     305 │       275 │         39 │          248 │                 2 │       20 │          2 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

For comparison, on other benchmarks, the M1 is faster:

category = "append"
bench = "append.jl"
  No Changes to `~/GCBenchmarks/benches/serial/append/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/append/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │        888 │     127 │        52 │         73 │           30 │                 5 │     1483 │          8 │
│  median │        907 │     132 │        56 │         76 │           33 │                 7 │     1484 │          9 │
│ maximum │       1163 │     145 │        65 │         84 │           42 │                12 │     1485 │         10 │
│   stdev │        109 │       6 │         4 │          3 │            4 │                 2 │        0 │          1 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

vs

category = "append"
bench = "append.jl"
  No Changes to `~/GCBenchmarks/benches/serial/append/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/append/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │       2305 │     108 │        84 │         24 │           48 │                 3 │     1483 │          1 │
│  median │       2664 │     112 │        87 │         25 │           49 │                 4 │     1484 │          2 │
│ maximum │       3442 │     139 │       102 │         40 │           59 │                 4 │     1524 │          2 │
│   stdev │        345 │      11 │         7 │          5 │            5 │                 1 │       16 │          0 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

Benchmarks are from https://github.com/JuliaCI/GCBenchmarks.

[vchuravy]

I assume this is on master? cc: @d-netto

[gbaraldi]

I'm not sure, but we're seeing bad behaviour on 1.9 as well.

[Keno]

Yes, this was master.

[gbaraldi]

bench = "list.jl"
  No Changes to `~/GCBenchmarks/benches/serial/linked/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/linked/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │       9253 │    6099 │      5380 │        704 │         1981 │                12 │     3055 │         63 │
│  median │       9342 │    6118 │      5396 │        722 │         1995 │                13 │     3136 │         64 │
│ maximum │       9424 │    6226 │      5503 │        725 │         2031 │                18 │     3140 │         65 │
│   stdev │         62 │      53 │        51 │          6 │           19 │                 2 │       26 │          0 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘
Julia Version 1.9.0-beta3
Commit 24204a73447 (2023-01-18 07:20 UTC)
Platform Info:
  OS: Linux (aarch64-linux-gnu)
  CPU: 4 × Neoverse-N1
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, neoverse-n1)
  Threads: 1 on 4 virtual cores

Doesn't seem to be aarch64 related. It would be nice to test on x86 mac as well.

bench = "append.jl"
  No Changes to `~/GCBenchmarks/benches/serial/append/Project.toml`
  No Changes to `~/GCBenchmarks/benches/serial/append/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ 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 │       1963 │     199 │       158 │         40 │           98 │                15 │     1470 │          3 │
│  median │       1975 │     204 │       163 │         41 │           99 │                17 │     1470 │          3 │
│ maximum │       2016 │     211 │       170 │         42 │          101 │                21 │     1470 │          4 │
│   stdev │         16 │       3 │         3 │          1 │            1 │                 2 │        0 │          0 │
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

For reference. It's slower than expected but not pathological.

[d-netto]

linked/list.jl got worse after #47292 on M1 (master refers to before the merge and PR after):

┌─────────────────┬────────┬────────┐
│                 │ master │     PR │
├─────────────────┼────────┼────────┤
│ total time [ms] │  76984 │ 102113 │
│    gc time [ms] │  75482 │ 101252 │
│  mark time [ms] │  53561 │  73611 │
│ sweep time [ms] │  21905 │  27691 │
│  max pause [ms] │   4038 │   4330 │
│ max memory [MB] │   4051 │   4047 │
│          pct gc │     98 │     99 │
└─────────────────┴────────┴────────┘

The same benchmark had an opposite trend on a AMD/x86-64 machine:

┌─────────────────┬────────┬──────┐
│                 │ master │   PR │
├─────────────────┼────────┼──────┤
│ total time [ms] │   7152 │ 5736 │
│    gc time [ms] │   5357 │ 3918 │
│  mark time [ms] │   4826 │ 3376 │
│ sweep time [ms] │    532 │  542 │
│  max pause [ms] │   1787 │ 1302 │
│ max memory [MB] │   2410 │ 2410 │
│          pct gc │     74 │   67 │
└─────────────────┴────────┴──────┘

[Keno]

Would be interesting to test M1 linux as well. I guess a VM might be fine to just get a rough idea.

[gbaraldi]

bench = "list.jl"
  No Changes to `~/gctest/Resources/julia/bin/GCBenchmarks/benches/serial/linked/Project.toml`
  No Changes to `~/gctest/Resources/julia/bin/GCBenchmarks/benches/serial/linked/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬──────
│         │ total time │ gc time │ mark time │ sweep time │ max GC pause │ tim ⋯
│         │         ms │      ms │        ms │         ms │           ms │     ⋯
├─────────┼────────────┼─────────┼───────────┼────────────┼──────────────┼──────
│ minimum │       7592 │    5487 │      4825 │        662 │         1792 │     ⋯
│  median │       7912 │    5772 │      5075 │        695 │         1888 │     ⋯
│ maximum │       8352 │    6050 │      5339 │        720 │         1982 │     ⋯
│   stdev │        266 │     184 │       173 │         19 │           69 │     ⋯
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴──────
                                                               3 columns omitted

bench = "append.jl"
  No Changes to `~/gctest/Resources/julia/bin/GCBenchmarks/benches/serial/append/Project.toml`
  No Changes to `~/gctest/Resources/julia/bin/GCBenchmarks/benches/serial/append/Manifest.toml`
┌─────────┬────────────┬─────────┬───────────┬────────────┬──────────────┬──────
│         │ total time │ gc time │ mark time │ sweep time │ max GC pause │ tim ⋯
│         │         ms │      ms │        ms │         ms │           ms │     ⋯
├─────────┼────────────┼─────────┼───────────┼────────────┼──────────────┼──────
│ minimum │       2167 │     240 │        86 │        153 │           58 │     ⋯
│  median │       2222 │     251 │        90 │        162 │           63 │     ⋯
│ maximum │       2356 │     263 │        95 │        172 │           65 │     ⋯
│   stdev │         55 │       7 │         3 │          7 │            2 │     ⋯
└─────────┴────────────┴─────────┴───────────┴────────────┴──────────────┴──────


julia> versioninfo()
Julia Version 1.9.0-beta3
Commit 24204a73447 (2023-01-18 07:20 UTC)
Platform Info:
  OS: macOS (x86_64-apple-darwin21.4.0)
  CPU: 12 × Intel(R) Core(TM) i7-8700B CPU @ 3.20GHz
  WORD_SIZE: 64
  LIBM: libopenlibm
  LLVM: libLLVM-14.0.6 (ORCJIT, skylake)
  Threads: 1 on 12 virtual cores
Environment:
  DYLD_FALLBACK_LIBRARY_PATH = /Users/julia/lib:/usr/local/lib:/lib:/usr/lib:/Users/julia/Library/Python/3.7/lib
  JULIA_PKG_PRECOMPILE_AUTO = 1
  JULIA_PKG_SERVER = https://pkg.julialang.org

It seems to be m1 related 🤔

[gbaraldi]

macOS is doing something really bad here because this is on a Linux VM on my m1 laptop

I couldn't get the clipboard working so bear witb the prints

[Keno]

It seems surprising that there would be such a big OS difference here .... We're not really doing any system calls. I guess we might be stressing the memory subsystem, but jeez....

[Keno]

I did a bare metal linux run and the results match @gbaraldi's VM results.

[Keno]

GC log on M1/macOS:

GC: pause 6.97ms. collected 38.484309MB. incr
GC: pause 29.97ms. collected 0.093800MB. incr
GC: pause 49.96ms. collected 0.000000MB. incr
GC: pause 77.46ms. collected 0.000000MB. incr
GC: pause 109.58ms. collected 0.000000MB. incr
GC: pause 161.82ms. collected 0.000000MB. incr
GC: pause 241.54ms. collected 0.000000MB. incr
GC: pause 369.79ms. collected 0.000000MB. incr
GC: pause 563.72ms. collected 0.000000MB. incr
GC: pause 790.89ms. collected 0.000000MB. incr
GC: pause 729.75ms. collected 0.000000MB. full
GC: pause 1206.77ms. collected 14.342874MB. full
GC: pause 1235.39ms. collected 2.383547MB. full
GC: pause 1272.20ms. collected 0.000000MB. full
GC: pause 1284.24ms. collected 0.000000MB. full
GC: pause 1305.48ms. collected 0.000000MB. full
GC: pause 1328.40ms. collected 0.000000MB. full
GC: pause 1349.18ms. collected 0.000000MB. full
GC: pause 1369.07ms. collected 0.000000MB. full
GC: pause 1395.83ms. collected 0.000000MB. full
GC: pause 1420.44ms. collected 0.000000MB. full
GC: pause 1438.30ms. collected 0.000000MB. full
GC: pause 1462.76ms. collected 0.000000MB. full
GC: pause 1487.71ms. collected 0.000000MB. full
GC: pause 1512.28ms. collected 0.000000MB. full
GC: pause 1531.34ms. collected 0.000000MB. full
GC: pause 1553.63ms. collected 0.000000MB. full
GC: pause 1571.83ms. collected 0.000000MB. full
GC: pause 1597.79ms. collected 0.000000MB. full
GC: pause 1617.82ms. collected 0.000000MB. full
GC: pause 1634.78ms. collected 0.000000MB. full
GC: pause 1657.50ms. collected 0.000000MB. full
GC: pause 1683.11ms. collected 0.000000MB. full
GC: pause 1704.77ms. collected 0.000000MB. full
GC: pause 1729.11ms. collected 0.000000MB. full
GC: pause 1934.86ms. collected 0.000000MB. full
GC: pause 1768.93ms. collected 0.000000MB. full
GC: pause 1794.73ms. collected 0.000000MB. full
GC: pause 1830.96ms. collected 0.000000MB. full
GC: pause 1844.74ms. collected 0.000000MB. full
GC: pause 1870.58ms. collected 0.000000MB. full
GC: pause 1893.89ms. collected 0.000000MB. full
GC: pause 1900.76ms. collected 0.000000MB. full
GC: pause 1913.94ms. collected 0.000000MB. full
GC: pause 1937.05ms. collected 0.000000MB. full
GC: pause 1961.40ms. collected 0.000000MB. full
GC: pause 1979.99ms. collected 0.000000MB. full
GC: pause 2001.17ms. collected 0.000000MB. full
GC: pause 2036.07ms. collected 0.000000MB. full
GC: pause 2048.52ms. collected 0.000000MB. full
GC: pause 2104.55ms. collected 0.000000MB. full
GC: pause 2120.38ms. collected 0.000000MB. full
GC: pause 2135.64ms. collected 13.838608MB. full
(value = 134217728, times = 0x00000010f92eb423, gc_diff = Base.GC_Diff(4294967296, 0, 0, 134217728, 0, 175, 71423721960, 52, 42), gc_end = Base.GC_Num(30364928, 0, 0, 1483, 1, 142908647, 50668, 1480, 71518025462, 5312867266, 0, 0x0000000002bc0000, 74, 42, 2120381292, 4244861763, 7542, 15209, 322084250, 1798285791, 10952903502, 60563773457))

vs x86_64 linux:

GC: pause 18.85ms. collected 26.226526MB. incr
GC: pause 41.31ms. collected 0.146512MB. incr
GC: pause 65.38ms. collected 0.000000MB. incr
GC: pause 83.65ms. collected 0.000000MB. incr
GC: pause 155.24ms. collected 0.000000MB. incr
GC: pause 174.23ms. collected 0.000000MB. incr
GC: pause 260.61ms. collected 0.000000MB. incr
GC: pause 394.58ms. collected 0.000000MB. incr
GC: pause 617.96ms. collected 0.000000MB. incr
GC: pause 1018.14ms. collected 0.000000MB. incr
GC: pause 1329.41ms. collected 0.000000MB. incr
(value = 134217728, times = 0x0000000158a0571d, gc_diff = Base.GC_Diff(4294967296, 0, 0, 134217728, 0, 13, 4159353906, 11, 0), gc_end = Base.GC_Num(822962816, 0, 0, 35, 0, 136652179, 1193, 27, 4230891708, 3642918580, 0, 0x0000000068707a6b, 14, 0, 1329409486, 2725647287, 15250, 20040, 280061775, 1049347211, 872873882, 3357979326))

For some reason on macOS, we're just doing way more collections and in particular an excessive amount of full collections.

[KristofferC]

What's the status on 1.8? Just thinking if there is something to bisect.

[Keno]

Looks like 1.8 is fine (M1/aarch64):

GC: pause 11.79ms. collected 24.086122MB. incr
GC: pause 26.25ms. collected 0.008432MB. incr
GC: pause 47.50ms. collected 0.003504MB. full
GC: pause 124.23ms. collected 0.875768MB. full
GC: pause 219.33ms. collected 0.000000MB. full
GC: pause 488.75ms. collected 0.000000MB. full
GC: pause 1290.01ms. collected 0.000000MB. full
(value = 134217728, times = 0x00000000b6d8db62, gc_diff = Base.GC_Diff(4294967296, 0, 0, 134217728, 0, 20, 2207871376, 7, 5), gc_end = Base.GC_Num(1270836832, 0, 0, 210, 0, 136860540, 1828, 208, 2230395626, 3231358286, 0, 0x000000010b076000, 11, 5))