Kubernetes Linux perf for OpenJ9 Java Recipe

  1. Restart the pod with additional JVM options to enable the perf mapping file either with -XX:+PerfTool for newer Java or -Xjit:perfTool for older Java as well as -Xdump:system:events=user2,request=exclusive+prepwalk for easier collection of OS core dumps:
    1. For IBM Java >= 8.0.7.20 or IBM Semeru Runtimes >= v8.0.352 / 11.0.17.0 / 17.0.5.0, restart the Java process with -XX:+PerfTool
    2. For older versions of IBM Java or IBM Semeru Runtimes, restart the Java process with -Xjit:perfTool while making sure to combine with commas with any pre-existing -Xjit options.
    3. For example, a common approach to add the options is using a JVM environment variable such as JAVA_TOOL_OPTIONS in a Deployment (making sure to combine envars of the same name if they're already present):
      spec:
        template:
          spec:
            containers:
            - name: ...
              env:
              - name: JAVA_TOOL_OPTIONS
                value: -XX:+PerfTool -Xdump:system:events=user2,request=exclusive+prepwalk
  2. For each pod of interest, open a terminal and ensure there are /tmp/perf-$PID.map files and note down the container process ID(s) from the file names. For example:
    $ kubectl exec -it liberty1-846f7c48c4-ltcvq -- sh -c "ls /tmp/perf*map"
    /tmp/perf-1021.map  /tmp/perf-1059.map  /tmp/perf-1.map  /tmp/perf-82.map
    • In some cases, there may be perf map files for Java processes that no longer exist as they were transient.
  3. For each pod, find the worker node the pod is on and the container ID; for example:
    $ kubectl get pod liberty1-846f7c48c4-ltcvq -o jsonpath='{.spec.nodeName}{"\n"}{.status.containerStatuses[*].containerID}{"\n"}'
    itz-bn7nf2-worker-3
    cri-o://fedce1715892cef7a360566f588fd006d343eb7e243d16402cf47c48167e1d54
  4. As a user with cluster-admin permissions, start a debug pod on the worker node (replace $NODE with the worker node name in the previous step and replace the fedora image with another general purpose image if needed). Note that older versions of kubectl don't require --profile=sysadmin.
    kubectl debug node/$NODE --profile=sysadmin -it --image=fedora -- bash
    1. Switch to the worker node filesystem:
      chroot /host
    2. Display the distribution and version of the worker node which may be needed later if you need to build a container with perf; for example:
      cat /etc/os-release
    3. Find the main PID of the container given the container ID from the steps above (excluding the URI prefix); for example:
      # crictl inspect fedce1715892cef7a360566f588fd006d343eb7e243d16402cf47c48167e1d54 | jq '.info.pid'
      41647
    4. Check if this main PID is the PID of Java by seeing if the container PID (3rd column) matches the initial steps above finding the Java PIDs in the container:
      # grep NSpid /proc/41647/status
      NSpid: 41647 1
    5. If the main PID is not Java, or if there are multiple Java PIDs of interest, then find all worker node PIDs of the Java processes:
      1. Find the PID namespace from the main container PID; for example:
        # readlink /proc/41647/ns/pid
        pid:[4026535300]
      2. List all worker node PIDs in that namespace; for example:
        sh-5.1# lsns 4026535300
          PID  PPID USER       COMMAND
        41647 41645 1000870000 /opt/java/openjdk/bin/java ...
        86373 86371 1000870000 sh
        88294 86373 1000870000 `-java ConsumeCPU 30
      3. For each worker node PID, find the matching container PID (third column); for example:
        # grep NSpid /proc/41647/status
        NSpid: 41647 1
        # grep NSpid /proc/88294/status
        NSpid: 88294 1059
    6. Check if perf is installed. Normally, perf is not installed and you'll get the following error.
      $ perf -v
      sh: perf: command not found
  5. If the worker node doesn't have perf and if you don't already have another available container image with perf installed, then create your own:
    1. Create a Containerfile that installs perf, matching or approximately matching the container distribution to that of the worker node found above; for example:
      FROM fedora
      RUN dnf install -y perf runc procps-ng binutils less lsof psmisc sysstat vim zip util-linux fatrace && dnf clean all
    2. Build the image locally; for example:
      podman build --platform linux/amd64 -t perfcontainer .
    3. Publish the image to your cluster image registry.
  6. Run a debug pod with an image that has perf; for example:
    kubectl debug node/$NODE --profile=sysadmin -it --image=image-registry.svc:5000/perfimage/perfcontainer -- bash
  7. Check if perf top works:
    perf top -z
    If it works, type q to exit. If there are errors, some permission errors may be resolved with dynamic (and temporary) kernel configuration changes:
    sysctl -w kernel.perf_event_paranoid=-1
    sysctl -w kernel.kptr_restrict=0
  8. Create symbolic links for all the Java perf maps using the container PIDs and the worker node PIDs found above; for example:
    ln -s /host/proc/41647/root/tmp/perf-1.map /tmp/perf-41647.map
    ln -s /host/proc/41647/root/tmp/perf-1059.map /tmp/perf-88294.map
    Create symbolic links in the worker node filesystem as well; for example:
    chroot /host/
    ln -s /proc/41647/root/tmp/perf-1.map /tmp/perf-41647.map
    ln -s /proc/41647/root/tmp/perf-1059.map /tmp/perf-88294.map
    exit
  9. Start the perf collection in the background:
    cd /tmp/
    nohup sh -c "date +'%Y-%m-%d %H:%M:%S.%N %Z' >> diag_perfdata_starttimes.txt; cat /proc/uptime >> diag_perfdata_starttimes.txt; perf record --call-graph dwarf,65528 -T -F 19 -o perf.data -a -g -- sleep infinity" &
  10. Ensure there were no errors starting perf:
    cat nohup.out
  11. Start a loop that continuously prints the size of the perf.data file to the screen to avoid some cases where lack of interaction causes termination of the debug pod and you can also monitor disk usage to ensure no exhaustion:
    while true; do date; ls -lh /tmp/perf.data; df -h /tmp; echo ""; sleep 8; done
  12. Leave the debug pod window open.
  13. Reproduce the problem.
  14. After the problem is reproduced, stop the data collection by going back to the debug pod window and Ctrl^C out of the while loop. Then, end the perf execution:
    kill -TERM %1
  15. Execute the jobs command until you see the "Terminated" output:
    # jobs
    [1]+  Running                    nohup sh -c "date +'%Y-%m-%d %H:%M:%S.%N %Z' >> diag_perfdata_starttimes.txt; cat /proc/uptime >> diag_perfdata_starttimes.txt; perf record --call-graph dwarf,65528 -T -F 19 -o perf.data -a -g -- sleep infinity" &
    # jobs
    [1]+  Running                    nohup sh -c "date +'%Y-%m-%d %H:%M:%S.%N %Z' >> diag_perfdata_starttimes.txt; cat /proc/uptime >> diag_perfdata_starttimes.txt; perf record --call-graph dwarf,65528 -T -F 19 -o perf.data -a -g -- sleep infinity" &
    # jobs
    [1]+  Terminated                 nohup sh -c "date +'%Y-%m-%d %H:%M:%S.%N %Z' >> diag_perfdata_starttimes.txt; cat /proc/uptime >> diag_perfdata_starttimes.txt; perf record --call-graph dwarf,65528 -T -F 19 -o perf.data -a -g -- sleep infinity"
  16. Run the following commands:
    perf script -i perf.data --symfs=/host --kallsyms=/host/proc/kallsyms --header -I -f -F comm,cpu,pid,tid,time,event,ip,sym,dso,symoff > diag_perfscript_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stdout.txt 2> diag_perfscript_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stderr.txt
    perf report -i perf.data --symfs=/host --kallsyms=/host/proc/kallsyms -n --show-cpu-utilization -v --stdio > diag_perfreport_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stdout.txt 2> diag_perfreport_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stderr.txt
  17. Delete the perf symlinks in the worker node filesystem; for example:
    rm -f /host/tmp/perf-41647.map
    rm -f /host/tmp/perf-88294.map
  18. Compress all the files:
    tar chzvf diag_perfoutput_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).tar.gz perf* diag* nohup.out
  19. List the full file name for later:
    $ ls diag_perfoutput*
    diag_perfoutput_itz-bn7nf2-worker-3_20260806_213742_673730815.tar.gz
  20. Start a loop to keep this debug pod active:
    while true; do date; sleep 8; done
  21. In another window, open a terminal to the pod.
    1. First check where OS core dumps will go:
      cat /proc/sys/kernel/core_pattern
    2. If the output starts with |, then they will go to the specified program on the worker node.
    3. If the output starts with /, they will attempt to be written to the specified directory. If this doesn't exist or the user doesn't have permissions to write to it, creating the core will fail. You may either try creating the directory dynamically, or temporarily change the core_pattern setting on the worker node through a debug pod:
      $ sysctl kernel.core_pattern # Print the current setting for later reversion
      kernel.core_pattern = /core.%e.%p.%t
      $ sysctl -w "kernel.core_pattern=/tmp/core" # Dynamically update the setting 
    4. Otherwise, they will go to the current working directory in the container (find with ls -l /proc/$PID/ | grep cwd).
  22. Request a non-destructive OS core dump of the relevant Java processes (replace $PID with the container process ID; in the above example, it was 1 and 1059):
    kill -USR2 $PID
  23. Exit the pod terminal and now find the running debug pod; for example:
    $ kubectl get pods -A | grep -e NAMESPACE -e -debug-
    NAMESPACE                  NAME                               READY   STATUS      RESTARTS       AGE
    debug-x54bw                itz-bn7nf2-worker-3-debug-bxgdm    1/1     Running     0              164m
  24. Download the perfoutput tar from the debug pod (replace the full tar file name from above twice):
    kubectl cp -n debug-x54bw itz-bn7nf2-worker-3-debug-bxgdm:/tmp/diag_perfoutput_FILE.tar.gz diag_perfoutput_FILE.tar.gz
  25. Download the OS core dumps from the pod or the worker node:
    1. For example, if core_pattern shows the following:
      # cat /proc/sys/kernel/core_pattern
      |/usr/lib/systemd/systemd-coredump %P %u %g %s %t %c %h
    2. Then download cores through the debug pod with:
      kubectl cp -n debug-x54bw itz-bn7nf2-worker-3-debug-bxgdm:/host/var/lib/systemd/coredump/ coredumps
  26. Upload diag_perfoutput*.tar.gz, coredumps, all relevant logs from the pods, and any OS core dumps.
  27. If you made any temporary kernel changes above using sysctl, then revert those.

Notes:

  1. Some other commands that may be useful to start after starting perf record (and then stop these after the problem is reproduced):
    1. strace:
      nohup strace -f -T -tt -s 256  -p $PID1 -p $PID2 -o diag_strace_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stdout.txt 2> diag_strace_${HOSTNAME}_$(date +%Y%m%d_%H%M%S_%N).stderr.txt &
    2. fatrace:
      nohup fatrace -t -f CROW > diag_fatrace_${HOSTNAME}_$(date +%Y%m%d_%H%M%S).txt 2> diag_fatrace_${HOSTNAME}_$(date +%Y%m%d_%H%M%S).stderr.txt &
  2. Only perf report output seems to be useful. It's unclear why, but perf script can't seem to evaluate JITted methods even with access to /tmp/perf-$PID.map either within the debug pod or the host with --symfs=/host; strace suggests some sort of issue calling libunwind with the perf map (unwind: failed with 'not a valid ELF file'):
    openat(AT_FDCWD, "/host///tmp/perf-211133.map", O_RDONLY) = 37
    fcntl(37, F_GETFD)                      = 0
    fstat(37, {st_mode=S_IFREG|0640, st_size=110045, ...}) = 0
    mmap(NULL, 110045, PROT_READ|PROT_WRITE, MAP_PRIVATE, 37, 0) = 0x7f035a3c0000
    munmap(0x7f035a3c0000, 110045)          = 0
    close(37)                               = 0
    write(2, "unwind: failed with 'not a valid ELF file'\n", 43) = 43
    write(1, "main  211133/211134  [001] 11013.555344: cpu/cycles/P: \n\n", 57) = 57
    For example, despite the raw perf script -D showing an instruction pointer 0x7f7d1ab53d18:
    1 11013660434443 0x70aa50 [0xfff8]: PERF_RECORD_SAMPLE(IP, 0x2): 211133/211134: 0x7f7d1ab53d18 period: 163762576 addr: 0
    Which maps to the perf-211133.map for the range 0x7F7D1AB53940 - 0x7F7D1AB56C75:
    00007F7D1AB53940 3335 com/sun/crypto/provider/AESCrypt.makeSessionKey([B)V_scorching
    Yet perf script doesn't show this top stack frame at all, let alone unwinding beyond it. perf report behaves differently.