B6. Profiling

advancedbuilds on module 13, module 18

Goal

The last lab of the course applies the earlier modules to one practical question: why is this slow? The main skill here is the order of steps. A function profiler shows where a program computes, but first you have to find out whether it is computing at all, or waiting on the disk or on memory. The path of read() through the kernel and the page cache is described in module 13, cache lines and misses in module 2, and tracing with eBPF in module 18.

After this lab you will be able to:

• from top and the process state, say whether a program lacks CPU or is waiting on I/O;
• read the output of strace -c and name the system call where the time goes, and how many times it is called;
• find a hot function with perf record and perf report;
• use IPC and cache-misses from perf stat to tell computation from waiting on memory;
• show the distribution of disk latencies with biolatency or iostat -xz.

This is what the first hour of any “the service got slow” investigation looks like: before touching the code, prove with numbers where the time is lost, and after the fix, measure again.

Task

The result is a report with three analyzed cases of a slow program: for each, the cause is named, proven by measurement, and the numbers before and after the fix are shown.

What to do: the three tasks below. In each one you need to find the cause, prove it by measurement and fix it, and then show the numbers before and after. Follow the “Order of steps”: first find out whether the program is waiting or computing, and only then reach for the profiler.

1. A program that waits.

   Take or write a program that reads a file in tiny chunks of 1 byte. Find this with strace -c, fix it with buffering, and show the difference in the number of system calls and in time (module 3).

2. A program that misses the cache.

   Traversing a two-dimensional array by columns instead of rows. Prove with perf stat that the problem is memory access, not the number of operations: the instruction count should stay almost the same (module 2).

   Look first at cache-references, not only at cache-misses: it is the number of accesses beyond L1 that explodes. For reference, a 3000×3000 array (34 MiB), the same 127 M instructions in both cases:

   Traversal	cache-references	cache-misses
   by rows	2.0 M	1.35 M
   by columns	35.8 M	1.59 M

   The array must be filled

   If you declare static int a[N][N] and write nothing into it, all that memory will be mapped to a single shared zero page (module 12). There will be no difference between the traversals at all, and by columns you will even get fewer misses than by rows.

   Fill the array in a loop before measuring. This is the same trap as -O2 in the race condition demo from module 9: the system optimizes away what you are trying to show.

3. A system slowed down by the disk.

   Create a load (fio or dd in a loop), find the culprit with iostat -xz and biolatency from bpftrace, and show the latency distribution (module 13, module 14).

What not to do. Do not optimize blindly: a change without a measurement before and after does not count. Flame graphs and your own bpftrace programs are left for the “Going further” section.

Constraints. Task 2 requires a C program built with -g: otherwise perf report will show addresses instead of function names. For tasks 1 and 3 any language will do.

What goes in the report:

• for task 1: the number of system calls and the time from strace -c before and after buffering;
• for task 2: instructions, cache-references and cache-misses from perf stat for traversal by rows and by columns;
• for task 3: the latency distribution from biolatency or r_await/w_await from iostat -xz, and the name of the process generating the load;
• for each task: the process state and %wa from top at the first step of the order of steps, and the conclusion you drew from them.

Done when:

• you can confirm with a command each of the seven claims in the “What you must be able to prove” table;
• the report names the cause for each of the three tasks and has the numbers before and after the fix;
• the report contains the four items above.

Before you start

• Read the sections “The path of one read()” and “Buffering and caching” in module 13, the section “Memory hierarchy” in module 2, and the section “eBPF: the kernel became programmable” in module 18. For task 1 the section “What it costs” in module 3 will help.
• The Vagrant machine from the archive has linux-perf, bpftrace, fio and sysstat (iostat). On your own system install the same with setup/provision.sh: it also lowers perf_event_paranoid and kptr_restrict, without which perf and bpftrace cannot see kernel symbols.
• The biolatency script is one of the bpftrace examples. There is no starter code or check.sh for this lab in the archive: the result is confirmed by the claims table and the report.

You need a VM, not a container

perf needs access to the CPU’s performance counters, and bpftrace to the kernel’s tracepoints. An unprivileged container has neither (module 17).

Order of steps

This is the core material of the lab. Remember the sequence: it saves hours.

1. Is it the CPU at all?

   top: if the process is in state S or D and %wa is high, the CPU is sufficient and the program is waiting. A function profiler will not help here.

2. What exactly is it waiting on?

   strace -T -c shows which system calls the time went into. For state D, cat /proc/<pid>/wchan or stack: that gives the name of the kernel function in which the process went to sleep.

3. If it is the CPU, then where?

   perf top for a live picture, perf record + perf report for analysis. Look at the share first, function names later.

4. Is it computation at all?

   perf stat: the ratio of instructions to cycles (IPC). A value below one means the CPU is waiting on memory instead of computing (module 2). Then look at cache-misses and dTLB-load-misses (module 11).

5. If you need something the ready-made tools do not provide, use bpftrace.

What you must be able to prove

Claim	How to prove it
You can tell waiting from computing	top %wa + process state
You found which call the time goes into	strace -c -T
You found the hot function	perf report
You know whether the CPU is computing or waiting	perf stat, IPC
Cache misses are measured, not assumed	perf stat -e cache-misses
Disk latencies are shown as a distribution	biolatency or iostat -xz
The fix had an effect	numbers before and after for each task

Common mistakes

Profiling without symbols. perf report will show addresses instead of names. You need -g at build time and packages with debug symbols.

Measuring without warm-up. The first run reads from disk, and the following ones from the page cache (module 13). The difference is a hundredfold, and it has nothing to do with your optimization.

Optimizing the wrong thing. A function takes eighty percent of the time, but it is called where the program is waiting on the disk anyway. That is why you start with the first step of the order of steps.

strace as a profiler. It slows the program down several times over, because it intercepts every call. It is fine for the distribution of time between calls, not for absolute numbers.

A conclusion without a second measurement. “It got faster” without numbers before and after does not count as a result.

Going further

Build a flame graph from perf record and see what the same profile looks like as a call tree. Or write your own bpftrace one-liner that counts the latency distribution of a specific system call.