Measuring CPU usage

Hint

This page describes features that were added in DIS 5.28.0. They are available on Linux only.

Throughput and latency only tell half the story. dis_cpu_usage shows the other half: how many CPU cores your program and the eXpressWare driver stack use to deliver that performance. It works on any program, and programs can use the small cpubench library to get the numbers per phase, for example per message size.

Requirements

• Linux, with eXpressWare installed and running (dis_kosif loaded)

• Kernel 5.17 or later, or a distribution kernel with the same kernel thread data backported (for example RHEL 9), built with BTF (CONFIG_DEBUG_INFO_BTF=y)

• root, because the measurement uses kernel tracing

• bpftrace, from the distribution’s package repository

• python3

Check that everything is in place with:

$ sudo /opt/DIS/bin/dis_cpu_usage --check
dis_cpu_usage: ok

Measuring a program

Put dis_cpu_usage -- in front of the command:

$ sudo /opt/DIS/bin/dis_cpu_usage -- ./my_program --some-option
...output of my_program...

==== dis_cpu_usage: ./my_program --some-option
No marked rows, the command doesn't use cpubench or wasn't told to (e.g. -cpu).
Whole run (12.40 s): Process 0.98, IRQ 0.02, Deferred 0.05, Kthread 0.00
====

The program’s own output is passed through unchanged, and the CPU usage is printed once it exits. The exit status of dis_cpu_usage is the program’s. Every process and thread the command starts is included, so a shell script or a launcher can be measured too.

All numbers are in cores: CPU time divided by wall time. 1.00 means one CPU core was busy for the whole period, 0.25 means a quarter of one core.

Column	What it counts
Process	Every task in the command’s process tree, user and system time
Sync usr	User time of a marked phase
Sync sys	System time of a marked phase, including time spent in the driver on behalf of the program
IRQ	All Dolphin hard interrupt handlers (dis-* in /proc/interrupts) on this node
Deferred	All deferred driver work and driver timers on this node
Kthread	All Dolphin kernel threads on this node, for example the interrupt poller dis_poll

IRQ, Deferred and Kthread are for the whole node, not only your program. They include work done for other programs using the interconnect at the same time, and work the driver does for the node itself, such as heartbeats.

Use --json <file> to also get the results as JSON, see dis_cpu_usage.

Measuring phases with cpubench

To get one row per phase, mark the phases with the cpubench library. This example measures each message size of a send loop:

#include <stdio.h>
#include "cpubench.h"

int main(void)
{
    cpubench_row_t *row;
    size_t          size;

    row = cpubench_row_create(0);
    if (row == NULL) {
        fprintf(stderr, "cpubench_row_create failed\n");
        return 1;
    }

    for (size = 4; size <= 65536; size *= 2) {
        cpubench_row_start(row, size);
        send_messages(size);              /* the work to measure */
        cpubench_row_stop(row);
    }

    cpubench_row_destroy(row);
    return 0;
}

Build and run it:

$ gcc -I/opt/DIS/include my_program.c -o my_program -L/opt/DIS/lib64 -lcpubench
$ sudo /opt/DIS/bin/dis_cpu_usage --label Size -- ./my_program

==== dis_cpu_usage: ./my_program
Size         Sync usr   Sync sys   IRQ        Deferred   Kthread
4            0.00       0.72       0.12       0.04       1.00
8            0.25       0.44       0.07       0.05       1.00
...
Whole run (2.56 s): Process 0.14, IRQ 0.02, Deferred 0.01, Kthread 0.84
====

The key is any number you choose, for example a message size or an iteration number. Rows with the same key are added together. --label names the key column.

When the program isn’t running under dis_cpu_usage, the calls cost two getrusage() calls per phase and nothing is reported. Use cpubench_traced() to tell whether it is being measured, for example to print a warning. Keep the start and stop calls outside your inner loops.

Process or thread scope

By default Sync usr and Sync sys are for the whole process. That includes threads the SISCI library starts to run callbacks, for example DMA completion or interrupt callbacks, so work done in callbacks is counted against the phase.

Create the row with CPUBENCH_ROW_THREAD to count the calling thread only:

row = cpubench_row_create(CPUBENCH_ROW_THREAD);

A thread-scope row must be started and stopped on the same thread, otherwise it is reported as n/a. Work other threads do for the phase is not included. When any row is thread scope, the table gets a Scope column saying which scope each row used.

Several phases at once

Rows with different keys can be open at the same time, for example one per thread, each thread using its own row object:

row = cpubench_row_create(CPUBENCH_ROW_THREAD);
cpubench_row_start(row, thread_number);
do_work();
cpubench_row_stop(row);

Rows with the same key can also be open at the same time, from different row objects. They are added together like rows of the same key that follow each other.

Because IRQ, Deferred and Kthread are for the whole node, rows that are open at the same time each see all of it. Don’t add those columns up across rows that overlap.

Reading the results

Rows marked * are shorter than 10 ms or 10 scheduler ticks. The split between user and system time is sampled at the scheduler tick, so it is unreliable for short rows. The sum of the two is still accurate.

The whole run line covers the command from start to exit, including start-up and any time spent waiting.

The Kthread over the whole run line splits the whole run’s Kthread time by kernel thread name, for example dis_poll 0.97 dma_inst_wd 0.00, so you can see which Dolphin kernel thread used it.

Interrupt and DMA polling. By default the driver switches from interrupts to polling as soon as interrupts arrive, and back when they slow down. While polling is on, the kernel thread dis_poll busy-polls on one core and shows up as about 1.00 in the Kthread column, with IRQ close to 0. dis_poll gives the CPU up to any other work that is ready to run, so a busy poller does not prevent the core from being used. Polling is controlled with intr_poll_mode and dma_poll_mode in /opt/DIS/lib/modules/dis_irm.conf:

Mode	Behaviour
0	Off, interrupts only
1	Delayed: polling starts above *_poll_thresh_on events per second
2	Immediate (default): the first event starts polling
3	Always on

Polling stops when the rate falls below *_poll_thresh_off events per second. DMA polling is on by default with PX adapters and off with MX adapters.

IRQ check lines compare the interrupts dis_cpu_usage saw with /proc/interrupts over the same period. A FAIL means the IRQ and Deferred numbers can’t be trusted.

Benchmarks

The SISCI benchmarks scibench2, scipp, dma_bench and intr_bench mark their rows when given -cpu. Run them under dis_cpu_usage on both nodes:

$ sudo /opt/DIS/bin/dis_cpu_usage --label Size -- /opt/DIS/bin/scibench2 -rn 4 -client -cpu

On the server side, scipp reports one row per size and intr_bench one row per loop, starting at the first interrupt. The scibench2 and dma_bench servers only wait for the client, so they report one row for the whole run, including the time spent waiting.

sisci_benchmarks.sh runs the whole suite this way with -cpu. Use the same options on both nodes:

$ sudo /opt/DIS/bin/sisci_benchmarks.sh -rn 8 -server -cpu
$ sudo /opt/DIS/bin/sisci_benchmarks.sh -rn 4 -client -cpu

-full runs the suite once without and once with -cpu, so the throughput and latency numbers of the first run are not affected by the measurement.

Overhead

While dis_cpu_usage runs, it traces every context switch, Dolphin interrupt and driver work item on the whole node, which costs on the order of 100 ns each. Everything running on the node is slightly slower while it measures. Compare performance numbers against a run without dis_cpu_usage, or use sisci_benchmarks.sh -full. There is no overhead when it isn’t running.

The tracing time spent inside a driver work item is counted as Deferred, so Deferred is highest relative to the real cost when there are many short work items. On a PXH830 node, dma_bench DMA completion work items took about 0.3 µs each without dis_cpu_usage and about 0.7 µs with it, so Deferred showed about twice the cost without measurement. Read Deferred for many short work items as an upper bound.

Don’t run other tracing tools, such as another bpftrace script or perf, while measuring. Their time inside driver work items is counted too.

Limitations

• Only the node dis_cpu_usage runs on is measured. Run it on every node.

• Not counted: driver tasklets and kernel threads not started by the Dolphin driver. On Linux only SuperSockets uses driver tasklets; SISCI interrupt and DMA handling runs in work items and kernel threads, which are counted.

• Dolphin interrupt and timer time can also show up in Sync usr and Sync sys when it interrupts the measured program. To avoid that, the kernel must be built with CONFIG_IRQ_TIME_ACCOUNTING=y (see /boot/config-$(uname -r) or /lib/modules/$(uname -r)/config), not be booted with tsc=noirqtime, and not have marked its clock unstable (sched_clock: Marking unstable in dmesg).

• Interrupts handled in kernel threads are not counted. With the threadirqs boot option or a real-time (PREEMPT_RT) kernel, the Dolphin interrupt handlers run in kernel threads named irq/<n>-dis-..., and IRQ only shows the short part that wakes the thread. dis_cpu_usage --check warns when this is the case.

• 64-bit programs only.

• Nodes with more than 1024 possible CPUs (/sys/devices/system/cpu/possible) fail the start-up check.

• Programs that build the cpubench source into themselves instead of linking libcpubench need --probe <program>.