counting cycles in GC

[d-netto]

Instrumentation to count cycles in GC: basically wraps a perf_event_open syscall in the GC callbacks.

TODO:

• Add script to compile measure_gc_cyles.c into a shared library.
• Further testing.

[d-netto]

Example of output table:

┌─────────┬────────────┬─────────┬──────────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ total time │ gc time │ cycles in gc │ mark time │ sweep time │ max GC pause │ time to safepoint │ max heap │ percent gc │
│         │         ms │      ms │          1e6 │        ms │         ms │           ms │                us │       MB │          % │
├─────────┼────────────┼─────────┼──────────────┼───────────┼────────────┼──────────────┼───────────────────┼──────────┼────────────┤
│ minimum │       7514 │     903 │         2324 │       834 │         67 │          565 │                 6 │       99 │         10 │
│  median │       9029 │     982 │         2493 │       915 │         69 │          574 │                 9 │       99 │         10 │
│ maximum │      11443 │    1242 │         2768 │      1169 │         74 │          857 │                23 │       99 │         11 │
└─────────┴────────────┴─────────┴──────────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

I believe this would need further assessment to judge whether the callback instrumentation introduces too much noise into the clock-time metrics.

[d-netto]

Latest commit should run benchmark 2*N times: N of them have the callbacks set and are used exclusively to measure cycles in GC.

This should avoid putting the cost of a read syscall into the path of GC when measuring wall-clock time.

[vchuravy]

This is really nice! We should think about what other metrics we might want. Probably page-faults?

[d-netto]

The cycle count seems to be a bit discrepant with wall-clock-time in some of the benchmarks:

bench = "TimeZones.jl"
┌─────────┬────────────┬─────────┬──────────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ total time │ gc time │ cycles in gc │ mark time │ sweep time │ max GC pause │ time to safepoint │ max heap │ percent gc │
│         │         ms │      ms │          1e6 │        ms │         ms │           ms │                us │       MB │          % │
├─────────┼────────────┼─────────┼──────────────┼───────────┼────────────┼──────────────┼───────────────────┼──────────┼────────────┤
│ minimum │       1825 │    1156 │           71 │      1124 │         32 │          350 │                13 │     5086 │         57 │
│  median │       1858 │    1217 │           75 │      1176 │         41 │          394 │                16 │     5086 │         59 │
│ maximum │       2125 │    1532 │          103 │      1466 │         66 │          535 │                19 │     5086 │         63 │
└─────────┴────────────┴─────────┴──────────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

[vchuravy]

I think you want to actually measure CPU-Time (x-ref JuliaCI/BenchmarkTools.jl#94) instead of wall-clock-time.

I think perf has an event for this https://github.com/JuliaPerf/LinuxPerf.jl/blob/a7fee0ff261a5b5ce7a903af7b38d1b5c27dd931/src/LinuxPerf.jl#L80-L81

[d-netto]

Seems like we were missing a few full GC collections. Latest commit seems to be a bit more consistent.

bench = "TimeZones.jl"
┌─────────┬────────────┬─────────┬──────────────┬───────────┬────────────┬──────────────┬───────────────────┬──────────┬────────────┐
│         │ total time │ gc time │ cycles in gc │ mark time │ sweep time │ max GC pause │ time to safepoint │ max heap │ percent gc │
│         │         ms │      ms │          1e6 │        ms │         ms │           ms │                us │       MB │          % │
├─────────┼────────────┼─────────┼──────────────┼───────────┼────────────┼──────────────┼───────────────────┼──────────┼────────────┤
│ minimum │       1926 │    1263 │         3435 │      1203 │         59 │          379 │                17 │     5086 │         57 │
│  median │       2308 │    1544 │         4013 │      1480 │         64 │          466 │                18 │     5086 │         58 │
│ maximum │       2691 │    1826 │         4591 │      1756 │         70 │          553 │                18 │     5086 │         59 │
└─────────┴────────────┴─────────┴──────────────┴───────────┴────────────┴──────────────┴───────────────────┴──────────┴────────────┘

Wondering how we can sanity check these results.