`perf` profiling in 4.14 and 5.0: calls to GC misattributed?

[panglesd]

I wanted to profile some programs using perf, and I observed some strange behaviour on OCaml 5. Switching to OCaml 4, the number seemed more reasonable.

I would tend to say that the reason is that time spent in the GC is not put as a child of the correct function perf since 5.0, seeing the output below.

Here is a somewhat minimal example:

(* test.ml *)

let l = ref []

let rec lots_of_allocs i =
  if i = 0 then ()
  else (
    for _ = 0 to 99999 do
      let i = ref 0 in
      i := !i + 1;
      i := !i - 1;
      l := !i :: !l
    done;
    l := [];
    lots_of_allocs (i - 1))

let rec lots_of_nothing i =
  if i = 0 then ()
  else (
    for _ = 0 to 100000000 do
      ()
    done;
    lots_of_nothing (i - 1))

let measure f =
  let t =
    let start = Unix.gettimeofday () in
    let _ = f () in
    let end_ = Unix.gettimeofday () in
    end_ -. start
  in
  Format.printf "Took %f seconds.\n%!" t

let () =
  print_endline "Starting lots_of_nothing";
  (measure @@ fun () -> lots_of_nothing 100);
  print_endline "Starting a lots_of_allocs";
  (measure @@ fun () -> lots_of_allocs 1000);
  print_endline "finished"

When I run this file, I have some information about the time spent in each function, lots_of_allocs and lots_of_nothing:

$ ocamlopt --version
5.0.0
$ ocamlopt -I +unix -g unix.cmxa test.ml
$ perf record --call-graph dwarf ./a.out 
Starting lots_of_nothing
Took 2.361002 seconds.
Starting a lots_of_allocs
Took 1.551887 seconds.
finished
[ perf record: Woken up 538 times to write data ]
[ perf record: Captured and wrote 134.438 MB perf.data (16701 samples) ]

However, if I ask perf about the time spent in each function, I get a result which does not match the measured time:

$ perf report
[...]
-   64.97%     0.00%  a.out    a.out                 [.] Test.entry                       
     Test.entry                                                                           
   - Test.measure_276                                                                     
        61.30% Test.lots_of_nothing_273                                                   
        3.67% Test.lots_of_allocs_269  
[...]

So, only 3.67% on lots_of_allocs, while it takes 1.55 seconds (compared to 61.30% for the 2.3 seconds of lots_of_nothing).

---

After that, I tried the same thing using ocaml 4.14:

$ ocamlopt --version
4.14.1
$ ocamlopt -I +unix -g unix.cmxa test.ml
$ perf record --call-graph dwarf ./a.out
Starting lots_of_nothing
Took 2.540385 seconds.
Starting a lots_of_allocs
Took 2.139729 seconds.
finished
[ perf record: Woken up 596 times to write data ]
[ perf record: Captured and wrote 149.053 MB perf.data (18499 samples) ]

Then, perf reports:

$ perf report
[...]
-   94.31%     0.00%  a.out    a.out                 [.] Test.entry                       
     Test.entry                                                                           
   - Test.measure_275                                                                     
        59.78% Test.lots_of_nothing_272                                                   
      - 34.53% Test.lots_of_allocs_268                                                    
         + 29.47% caml_call_gc                                                            
           2.30% caml_modify 
[...]

The time is now correctly counted, and there are children to the lots_of_allocs function. One of them is the gc, and seems to account for the missing time in OCaml 5...

[tmcgilchrist]

@panglesd Which Linux distro and architecture (x86_64 or ARM64) are you running on?

[OlivierNicole]

Every six months I need to understand a perf report and every six months it gives me headaches because of how un-intuitive it is. (And the man page is particularly obscure, too.)

I believe that without the --children option, the children of a function are its callers and not its callees, which makes me wince every time because my brain thinks in flame graphs. I think the output is somewhat more understandable by my brain, but barely, with the --children option.

I’ve been advised in the past to use pprof instead which is reportedly much more intuitive, but I haven’t put that advice into practice yet.

[lthls]

Also, if using perf with OCaml 5 you should not use --call-graph dwarf. It is very slow, and the split stack between C and OCaml tends to confuse it so it will not attribute children correctly when switching from OCaml to C and vice-versa.
Instead, if possible you should use --call-graph lbr (available on any moderately recent Intel CPU, not sure about other manufacturers) which is fast and reliable.

[OlivierNicole]

When lbr isn’t available, one can also set up an opam switch with frame pointer support and use --call-graph fp.

[edwintorok]

According to https://github.com/ocaml-multicore/docs/blob/main/ocaml_5_design.md#dwarf-debugging-support the DWARF info should correctly link the OCaml and C stacks, and although that design doc is not in the main OCaml codebase, the referenced c_stack_link is.
This is probably easier to debug by using gdb to verify whether stacktraces are correct, before involving perf.

Breakpoint 1, caml_alloc_small_dispatch (dom_st=0x55cb30, wosize=2, flags=3, nallocs=1, 
    encoded_alloc_lens=0x4eecf7 <camlTest.frametable+199> "\001\371\312C") at runtime/minor_gc.c:834
warning: 834    runtime/minor_gc.c: No such file or directory                                                                                    
(gdb) bt
#0  caml_alloc_small_dispatch (dom_st=0x55cb30, wosize=2, flags=3, nallocs=1, 
    encoded_alloc_lens=0x4eecf7 <camlTest.frametable+199> "\001\371\312C") at runtime/minor_gc.c:834
#1  <signal handler called>
#2  0x000000000043caf2 in camlTest.lots_of_allocs_270 ()
#3  0x000000000043cba0 in camlTest.measure_277 ()
#4  0x000000000043cd07 in camlTest.entry ()
#5  0x000000000043a2cb in caml_program ()
#6  <signal handler called>
#7  0x00000000004bbdc4 in caml_startup_common (pooling=<optimized out>, argv=0x7fffffffd4b8) at runtime/startup_nat.c:132
#8  caml_startup_common (argv=0x7fffffffd4b8, pooling=<optimized out>) at runtime/startup_nat.c:88
#9  0x00000000004bbe3b in caml_startup_exn (argv=<optimized out>) at runtime/startup_nat.c:139
#10 caml_startup (argv=<optimized out>) at runtime/startup_nat.c:144
#11 caml_main (argv=<optimized out>) at runtime/startup_nat.c:151
#12 0x0000000000439f6c in main (argc=<optimized out>, argv=<optimized out>) at runtime/main.c:37

The 'signal handler called' is likely from '.cfi_signal_frame', but then we are missing the name of a function here (it was actually caml_call_gc, because if I put a breakpoint there instead then it stops at <signal handler called> as the function on the stack).

FWIW the stacktrace looks fine in lldb:

(lldb) bt
* thread #1, name = 'a.out', stop reason = breakpoint 2.1
  * frame #0: 0x00000000004b2750 a.out`caml_alloc_small_dispatch(dom_st=0x000000000055cb30, wosize=2, flags=3, nallocs=1, encoded_alloc_lens="\U00000001\xf9\xcaC") at minor_gc.c:830:1
    frame #1: 0x00000000004bc21f a.out`caml_call_gc + 231
    frame #2: 0x000000000043caf2 a.out`camlTest.lots_of_allocs_270 + 178
    frame #3: 0x000000000043cba0 a.out`camlTest.measure_277 + 64
    frame #4: 0x000000000043cd07 a.out`camlTest.entry + 215
    frame #5: 0x000000000043a2cb a.out`caml_program + 603
    frame #6: 0x00000000004bc404 a.out`caml_start_program + 112
    frame #7: 0x00000000004bbdc4 a.out`caml_startup_common at startup_nat.c:132:9
    frame #8: 0x00000000004bbce8 a.out`caml_startup_common(argv=0x00007fffffffd4e8, pooling=<unavailable>) at startup_nat.c:88:7
    frame #9: 0x00000000004bbe3b a.out`caml_main [inlined] caml_startup_exn(argv=<unavailable>) at startup_nat.c:139:10
    frame #10: 0x00000000004bbe34 a.out`caml_main at startup_nat.c:144:15
    frame #11: 0x00000000004bbe34 a.out`caml_main(argv=<unavailable>) at startup_nat.c:151:3
    frame #12: 0x0000000000439f6c a.out`main(argc=<unavailable>, argv=<unavailable>) at main.c:37:3
    frame #13: 0x00007ffff7d0b14a libc.so.6`__libc_start_call_main + 122
    frame #14: 0x00007ffff7d0b20b libc.so.6`__libc_start_main@@GLIBC_2.34 + 139
    frame #15: 0x0000000000439fa5 a.out`_start + 37

Maybe OCaml 5 needs some more dwarf directives to make GDB and Perf happy.

Aside: LBR and SFrame:

Note that LBR is limited in depth, if you have lots of recursive calls it'll stop too early, and although compiling OCaml with framepointers is useful you'll miss out on sampling C code correctly (which likely won't be compiled with frame pointers).

There is a new method being worked on called SFrame stack format that should enable DWARF-like callgraph sampling but with much lower overhead, but this is still very new and may not be ready to be tried out just yet: https://tracingsummit.org/ts/2023/files/SFrame_TracingSummit2023.pdf. Once they get this working reliably for C then it'd be interesting to see what (if anything) needs to be done in OCaml to support it. For OCaml 4.x I think it might just work if you have the new binutils and use the appropriate binutils flags, but for OCaml 5 it might need to be taught how to link up the split stack.

[edwintorok]

Ah I think I know why perf --call-graph=dwarf cannot work with OCaml 5: when you trigger the profiling event (e.g. periodic sampling) it will sample (copy) a predefined amount of stack space, but it won't process the dwarf information at that point. DWARF information is then used to decode that into a stacktrace, but if you're switching stacks then the stack sample will only contain one of your stacks! (so although GDB perhaps could be fixed up to link them up in a nicer way and not miss caml_call_gc, that fix won't directly help perf).
If I look at the output of perf script it seems to confirm this hypothesis:

a.out   55604  2330.836263:    1332802 cycles:P: 
                  4b1b24 oldify_mopup+0x94 (/var/home/edwin/lbr/a.out)
                  4b179f alloc_shared+0x10f (inlined)
                  4b179f oldify_one+0x10f (/var/home/edwin/lbr/a.out)
                  4b1c4a oldify_mopup+0x1ba (/var/home/edwin/lbr/a.out)
                  4b2162 caml_empty_minor_heap_promote+0x212 (/var/home/edwin/lbr/a.out)
                  4b24ca caml_stw_empty_minor_heap_no_major_slice+0x3a (inlined)
                  49f37d caml_try_run_on_all_domains_with_spin_work+0x1bd (/var/home/edwin/lbr/a.out)
                  4b273a caml_try_stw_empty_minor_heap_on_all_domains+0x3a (inlined)
                  4b273a caml_empty_minor_heaps_once+0x3a (/var/home/edwin/lbr/a.out)
                  49ee78 caml_poll_gc_work+0x1c8 (/var/home/edwin/lbr/a.out)
                  4b6187 caml_do_pending_actions_exn+0x17 (/var/home/edwin/lbr/a.out)
                  4b2774 caml_alloc_small_dispatch+0x24 (/var/home/edwin/lbr/a.out)
                  4bc21e caml_call_gc+0xe6 (/var/home/edwin/lbr/a.out)
[...]
a.out   55604  2330.832262:    1328410 cycles:P: 
                  43ca94 Test.lots_of_allocs_270+0x54 (/var/home/edwin/lbr/a.out)
                  43cb9f Test.measure_277+0x3f (/var/home/edwin/lbr/a.out)
                  43cd06 Test.entry+0xd6 (/var/home/edwin/lbr/a.out)
                  43a2ca caml_program+0x25a (inlined)
                  4bc403 caml_start_program+0x6f (/var/home/edwin/lbr/a.out)

So we'd somehow need to get perf to always sample 2 stacks: the current one pointed to by the stack pointer, and the "other" stack if any, which is stored elsewhere. This will probably require patching perf and/or the kernel.

[tmcgilchrist]

cannot work with OCaml 5: when you trigger the profiling event (e.g. periodic sampling) it will sample (copy) a predefined amount of stack space, but it won't process the dwarf information at that point.

Is this copying behaviour documented anywhere or did you need to read the perf code itself? @edwintorok

[kayceesrk]

The copying behaviour is reasonably well-known. Some references:

• https://rwmj.wordpress.com/2023/02/14/frame-pointers-vs-dwarf-my-verdict/
• https://dl.acm.org/doi/pdf/10.1145/3360572

From the latter

For instance the perf profiler is forced to copy the whole stack on taking each sample and to build the backtraces offline: this solution has a memory and time overhead but also serious confidentiality and security flaws

[tmcgilchrist]

Thanks @kayceesrk

After looking into this, I agree with @edwintorok that DWARF support in perf is unlikely to ever work for OCaml 5, as we would need to teach perf to copy stacks from various places. Using FP or LBR are the best options with the restriction that both are currently only x86. Support could be added for frame pointers (FP) to other platforms like ARM64?

This older discussion on Restore frame-pointers support for amd64 has more information.

[edwintorok]

LBR are the best options with the restriction that both are currently only x86

Note that LBR doesn't work everywhere even on x86. Did a quick test with the machines I got at hand:

• Intel machine at work, PV Dom0 running on Xen 4.17: perf complains that PMU lacks overflow interrupt support so can't use LBR callgraphs (even with vpmu=1 and watchdog turned off). Looks like we've got some work to do in Xen to support this
• AMD Zen 4 running bare-metal Fedora 39 at home: perf records something, but always fails with Can't parse sample, err = -14 (this appears to be a bug in perf/Linux, Zen4 is meant to have LBR and even record speculation information)

(no doubt I can probably find a machine where LBR works if I keep searching, e.g. I'd expect a Xen HVM DomU to work)

This is probably a good opportunity to test and fix LBR support

[edwintorok]

I found some eBPF userspace DWARF stacktrace code, they may not work out of the box, but might be possible to tweak them to work with OCaml 5 (gdb can walk the dwarf info to find both stacks):
https://www.polarsignals.com/blog/posts/2022/11/29/profiling-without-frame-pointers
parca-dev/parca-agent#948
https://github.com/dvc94ch/cargo-trace/blob/master/bpf-backtrace/src/lib.rs

[OlivierNicole]

So, from what I understand, frame pointers (fp) are the only method that should still work well with perf in OCaml 5.

[kayceesrk]

I'd say that frame pointers are the recommended method for perf in OCaml 4 as well due to the cost of stack snapshots when using DWARF affecting the performance of the program being profiled.

[kayceesrk]

Support could be added for frame pointers (FP) to other platforms like ARM64?

I don't develop on other platforms. If there are users on other platforms, who are using perf with call graph, then they will need frame-pointer support on OCaml 5 for sensible profiles.

[tmcgilchrist]

Adding frame pointers for ARM64 Linux is on my list of tasks.