Part VII: Profiling

This chapter covers the kernel’s timing characteristics. Unlike the Part VI: Memory Footprint figures, which are fixed at build time, these have to be measured on the target — they depend on the exact hardware and build.

Note

Every timing figure depends on the CPU core, clock frequency, compiler and optimisation level, and the cache / flash wait-state configuration. Record those conditions next to any measurement; a cycle count without them is not comparable.

Enabling instrumentation

Build with QRT_CFG_PERF_ENABLE to have the kernel measure its own worst-case execution time (WCET). It records the longest time taken by each system call, by a context switch and by the SysTimer handler, and the longest it holds interrupts off. Each measured operation adds a small, fixed cost, so leave the option disabled in production builds.

Measurement needs a CPU cycle counter. Every supported core has one, except Cortex-M0+ and Cortex-M23 have none.

Reading the results

Read the figures with qrt_perf_read(), which writes a plain-text report into a buffer you supply:

#include "qrt.h"

char buf[1024];

qrt_perf_read(buf, sizeof(buf));
fputs(buf, stdout);

Each line is a name and its worst-case cycle count. The exercised system calls come first, then context_switch, irq_mask and systimer. For example:

sem_wait         1234
mutex_lock        456
kernel_boot      8901
context_switch    312
irq_mask           48
systimer          176

The report is truncated to fit the buffer and is always NULL-terminated; qrt_perf_read() returns the number of bytes written.

Note

Halting the core in a debugger while instrumentation is enabled does not corrupt the reported worst-case figures.

Worst-case figures

Measured on an ARM Cortex-M3 at 64 MHz. The system-call and context-switch figures are not skewed by an interrupt landing mid-call.

Three kernel-wide figures accompany the per-call system-call times:

context_switch — saving the outgoing thread’s context and restoring the next.
irq_mask — the longest the kernel keeps interrupts disabled; nothing can be serviced in that window, so it bounds the kernel’s contribution to interrupt latency.
systimer — the longest run of the SysTimer handler, which runs at the highest priority and so holds off every lower-priority interrupt while it executes, adding to their latency.

Figure	Cycles	Time
`context_switch`	—	—
`irq_mask`	—	—
`systimer`	—	—