Lab 10: Trace a Wakeup

Background

A process blocks reading a pipe. Another process writes to it. Microseconds later the first process is running on a CPU. Between those two events the kernel made half a dozen decisions, and every one of them is instrumented.

This lab makes you follow one wakeup, end to end, naming every participant: who was woken, by whom, which CPU was chosen and why, how long until it actually ran, and what it displaced. Then you change the conditions and watch the decisions change.

There is almost no code to write. The deliverable is a trace you can explain line by line, which is a different and more useful thing than a program.

Why This Lab Matters

• Wakeup latency is what users experience as "slow", and this is how you measure it rather than guess.
• Placement decisions explain most real-world scheduler behavior, and they are invisible without tracing.
• The tools here — sched tracepoints, perf sched, bpftrace — are what you will actually reach for when a production system misbehaves.
• Being able to say "this task waited 14 ms runnable, on CPU 3, behind that task" is the difference between a bug report and a diagnosis.

Prerequisites

• Scheduling Classes and Placement, Balancing, and Power read.
• A lab guest with -smp 4 or more — placement is meaningless on one CPU.
• perf and bpftrace working in the guest (warm-up exercises 9–11).
• CONFIG_SCHEDSTATS=y helps; check grep CONFIG_SCHEDSTATS ~/kernel/build/.config.

Predict First

Write all six down.

1. From sched_wakeup to the matching sched_switch, on an idle machine: nanoseconds, microseconds, or milliseconds?
2. The same, with every CPU running a busy loop.
3. Two processes ping-ponging through a pipe: same CPU, same L3, or different sockets?
4. Does the woken task run on the CPU that woke it, the CPU it last ran on, or neither?
5. How many sched_switch events per second does an idle machine produce? (Not zero.)
6. When a task is woken on a different CPU than the waker, what makes that CPU notice?

The Target

   writer                          KERNEL                         reader
   ──────                          ──────                         ──────
   write(pipe)                                             (blocked in read())
      │                                                        state: S
      └──▶ pipe_write()
             └──▶ wake_up_interruptible()
                    └──▶ try_to_wake_up(reader)
                           ├── select_task_rq_fair()   ◀── WHICH CPU?
                           │     wake_affine / select_idle_sibling
                           ├── enqueue on that rq
                           └── if that CPU != this CPU:
                                 send an IPI ──────────────▶ that CPU
                                                              │
                                          [TRACEPOINT: sched_wakeup]
                                                              │
                                               ...time passes... ◀── HOW LONG?
                                                              │
                                          __schedule() on the target CPU
                                            pick_next_task() → reader
                                          [TRACEPOINT: sched_switch]
                                                              │
                                                        reader runs

Your job is to produce that timeline for one real wakeup, with real numbers.

Step-by-Step Tasks

Step 1: The workload

A minimal, deterministic ping-pong so there is exactly one wakeup to look at.

// SPDX-License-Identifier: GPL-2.0
/* pingpong.c -- two processes waking each other through pipes. */
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <unistd.h>
#include <sys/wait.h>

int main(int argc, char **argv)
{
	int n = argc > 1 ? atoi(argv[1]) : 10000;
	int a[2], b[2];
	char c = 'x';

	if (pipe(a) || pipe(b))
		return 1;

	if (fork() == 0) {			/* child: the READER first */
		for (int i = 0; i < n; i++) {
			if (read(a[0], &c, 1) != 1) _exit(1);
			if (write(b[1], &c, 1) != 1) _exit(1);
		}
		_exit(0);
	}

	for (int i = 0; i < n; i++) {		/* parent: the WRITER first */
		if (write(a[1], &c, 1) != 1) return 1;
		if (read(b[0], &c, 1) != 1) return 1;
	}
	wait(NULL);
	printf("done: %d round trips\n", n);
	return 0;
}

gcc -O2 -o pingpong pingpong.c
./pingpong 100000

Step 2: The raw tracepoints

Start with tracefs, because it works on a kernel too broken to run anything else.

T=/sys/kernel/tracing; [ -d "$T" ] || T=/sys/kernel/debug/tracing

sudo sh -c "echo 0 > $T/tracing_on; echo > $T/trace"
sudo sh -c "echo 1 > $T/events/sched/sched_wakeup/enable"
sudo sh -c "echo 1 > $T/events/sched/sched_switch/enable"
sudo sh -c "echo 1 > $T/events/sched/sched_migrate_task/enable"

# Filter to just our processes, or the trace is unreadable:
sudo sh -c "echo 'comm ~ \"pingpong\"' > $T/events/sched/sched_wakeup/filter"

sudo sh -c "echo 1 > $T/tracing_on"
./pingpong 20
sudo sh -c "echo 0 > $T/tracing_on"

sudo head -40 "$T/trace"

You are looking at lines like:

 pingpong-812  [002] d..5.  4231.882417: sched_wakeup: comm=pingpong pid=813 prio=120 target_cpu=003
   <idle>-0    [003] d..3.  4231.882431: sched_switch: prev_comm=swapper/3 prev_pid=0 prev_prio=120
                                          prev_state=R ==> next_comm=pingpong next_pid=813 next_prio=120

Read every field. For that pair:

That 14 µs is the wakeup latency, and reproducing that measurement is the core of this lab.

Step 3: Measure the latency properly

One number is an anecdote. Get a distribution.

sudo bpftrace -e '
tracepoint:sched:sched_wakeup /str(args.comm) == "pingpong"/ {
	@wake[args.pid] = nsecs;
}
tracepoint:sched:sched_switch /@wake[args.next_pid]/ {
	@latency_us = hist((nsecs - @wake[args.next_pid]) / 1000);
	delete(@wake[args.next_pid]);
}' &
sleep 1; ./pingpong 200000; sleep 1; kill %1

PREDICT FIRST: where will the histogram peak — the 1–2 µs bucket, 4–8 µs, or 64–128 µs?

Then load the machine and do it again:

for i in $(seq "$(nproc)"); do sh -c 'while :; do :; done' & done
sudo bpftrace -e '...same script...' &
./pingpong 200000
jobs -p | xargs kill

PREDICT FIRST: how far does the distribution move? Does the peak move, or does a long tail appear? Those are different diagnoses.

Step 4: Answer "which CPU, and why"

# Where do wakeups land, relative to the waker?
sudo bpftrace -e '
tracepoint:sched:sched_wakeup /str(args.comm) == "pingpong"/ {
	@same_cpu[cpu == args.target_cpu] = count();
	@target[args.target_cpu] = count();
}' &
./pingpong 100000; kill %1

# And the topology to interpret it against:
lscpu | grep -E 'Thread|Core|Socket|NUMA'
cat /sys/devices/system/cpu/cpu0/cache/index3/shared_cpu_list
cat /sys/devices/system/cpu/cpu0/topology/thread_siblings_list

PREDICT FIRST: what fraction of wakeups place the target on the waker's own CPU? Explain your answer using wake_affine and the fact that the waker immediately blocks in read().

Now change the answer deliberately:

taskset -c 0 ./pingpong 100000        # both pinned to one CPU
taskset -c 0,1 ./pingpong 100000      # two CPUs
taskset -c 0,7 ./pingpong 100000      # pick two that do NOT share an L3

Time each and explain the ordering.

Step 5: perf sched

sudo perf sched record -- ./pingpong 100000
sudo perf sched latency --sort max | head -20
sudo perf sched timehist | head -40

perf sched latency gives you, per task: average and maximum time spent runnable but not running. That is the number to quote in a bug report — not CPU usage, not load average.

  Task                  |  Runtime ms  | Switches | Avg delay ms | Max delay ms
  pingpong:813          |     43.221   |   100000 |     0.014    |     2.481
                                                    ^^^^^^^^^^     ^^^^^^^^^^
                                          typical wakeup latency   the tail

Step 6: Watch it in GDB

Tracing shows you what. GDB shows you where.

~/kernel-labs/scripts/gdb-attach.sh try_to_wake_up

(gdb) continue
        ... in the guest: ./pingpong 1
(gdb) bt
(gdb) p p->comm
(gdb) p p->__state
(gdb) p p->wake_cpu
(gdb) finish                      ← where did select_task_rq_fair send it?
(gdb) lx-ps

PREDICT FIRST: what will bt show above try_to_wake_up? Name the three or four frames between it and the write() syscall before you look.

Warning: A breakpoint here stops the whole machine, including its clock. Timers and watchdogs all expire at once when you continue, so anything you measure while stepping is meaningless. Use GDB to answer "which code runs", and tracing to answer "how long". Never the reverse.

Step 7: Change the conditions, predict each time

For each row, predict before measuring, then explain any surprise:

The last row is the one worth dwelling on: the latency distribution grows a tail of roughly the cgroup period, which is the throttling failure mode from EEVDF and Fairness appearing in a measurement.

Implementation Requirements / Deliverables

• pingpong.c built and running.
• A raw tracefs trace of at least one wakeup/switch pair, annotated field by field in your own words.
• A latency histogram from bpftrace, idle and loaded, with both predictions recorded.
• The placement distribution: what fraction land on the waker's CPU, and an explanation.
• perf sched latency output, with the avg and max delay identified and explained.
• A GDB backtrace from try_to_wake_up up to the write() syscall, with every frame named.
• The eight-row conditions table, filled in, with predictions recorded before measurements.
• A written explanation of the cgroup-throttling row that names cpu.stat's nr_throttled.
• One paragraph: how would you use these tools on a production machine where "some requests are occasionally slow"?

Expected Output

$ sudo perf sched latency --sort max | head -8
 -------------------------------------------------------------------------------
  Task                  |   Runtime ms  | Switches | Avg delay ms | Max delay ms
 -------------------------------------------------------------------------------
  pingpong:(2)          |     86.443 ms |   200000 | avg: 0.014 ms | max: 2.481 ms
  kworker/3:1:87        |      1.204 ms |       42 | avg: 0.008 ms | max: 0.061 ms

$ sudo bpftrace -e '...'     # idle machine
@latency_us:
[1, 2)             12043 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[2, 4)             71822 |...
[4, 8)              9310 |...
[8, 16)              412 |
[16, 32)              38 |

Loaded, the shape changes in a specific way:

@latency_us:
[2, 4)              8102 |@@@@@@
[4, 8)             31022 |@@@@@@@@@@@@@@@@@@@@@@@
[8, 16)            66431 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|
[16, 32)           21044 |@@@@@@@@@@@@@@@@
[32, 64)            2210 |@
[64, 128)            188 |
[128, 256)            11 |            ← the tail is the interesting part

Debugging Steps

The trace file is empty

tracing_on was not set, or your filter matches nothing. Filters are on the event's fields, so comm in a sched_wakeup filter is the woken task's name, not the waker's. Clear the filter and look at raw output first.

The trace is gigabytes

You enabled sched_switch with no filter on a busy machine. Use trace_pipe with head, or filter, or use bpftrace, which aggregates in-kernel and never writes the raw events.

bpftrace cannot find args.comm

Field names differ between tracepoints and kernel versions. Check:

sudo cat /sys/kernel/tracing/events/sched/sched_wakeup/format
sudo bpftrace -lv 'tracepoint:sched:sched_wakeup'

perf sched says "no schedstat"

CONFIG_SCHEDSTATS is off, or /proc/sys/kernel/sched_schedstats is 0:

sudo sysctl kernel.sched_schedstats=1

The latencies are absurd (milliseconds on an idle machine)

You are in a VM without KVM, so every guest instruction is emulated. Check ls -l /dev/kvm on the host. The shape of the distribution is still informative; the absolute numbers are not.

Everything runs on one CPU

-smp 1. Rebuild the QEMU line. This lab is meaningless on one CPU.

GDB timings are nonsense

Expected — see the warning in step 6. The whole machine was stopped.

Experiment

CLAIM. Wakeup latency is not a property of the scheduler alone. It is a property of the scheduler plus the load, and the two produce different distribution shapes that mean different things.

METHOD. Collect the latency histogram under four conditions:

PREDICTION. Before measuring, sketch the four histograms. Specifically predict: which conditions move the peak, and which add a tail?

RESULT. The distinction is the point of the experiment:

• A shifted peak means everything is uniformly slower — contention.
• A long tail means most wakeups are fine and some are catastrophic — usually a priority/class/throttling interaction.

Those two symptoms have completely different causes and completely different fixes, and averages hide both. Write one sentence you would put in a bug report for each shape.

Test

Turn the measurement into something repeatable:

cat > ~/kernel-labs/scripts/wakeup-latency.sh <<'EOF'
#!/usr/bin/env bash
# Wakeup latency distribution for a named command, as a repeatable measurement.
#   ./wakeup-latency.sh ./pingpong 200000
set -euo pipefail
COMM=$(basename "$1")
sudo bpftrace -e "
tracepoint:sched:sched_wakeup /str(args.comm) == \"$COMM\"/ { @w[args.pid] = nsecs; }
tracepoint:sched:sched_switch /@w[args.next_pid]/ {
	@us = hist((nsecs - @w[args.next_pid]) / 1000);
	delete(@w[args.next_pid]);
}
END { clear(@w); }" -c "$*"
EOF
chmod +x ~/kernel-labs/scripts/wakeup-latency.sh
~/kernel-labs/scripts/wakeup-latency.sh ./pingpong 200000

Verify it can show a difference: run it idle, then run it with nproc busy loops. If the two histograms look the same, something is wrong with your setup — most likely -smp 1, or no KVM.

Challenge Extensions

1. Find the IPI. When a task is woken on a different CPU, that CPU is told via an inter-processor interrupt. Watch it: grep -E 'Rescheduling|Function call' /proc/interrupts before and after, and trace ipi:* events if your kernel has them. Then answer: when is the IPI avoided, and why?

2. Measure wake_affine directly. Put a kprobe on wake_affine and record its return value against the eventual target_cpu. How often does the decision it makes survive select_idle_sibling?

3. Break it deliberately. Pin the reader and writer to CPUs on different NUMA nodes (if you have them) and measure the round-trip cost. Then measure it with the memory allocated on the wrong node too, and separate the two effects.

4. Compare against SCHED_DEADLINE. Give the reader sched_setattr deadline parameters and measure the latency distribution. Explain the shape difference in terms of admission control.

5. Write a sched_ext scheduler. If your kernel has CONFIG_SCHED_CLASS_EXT, start from tools/sched_ext/scx_simple and modify the placement policy. Re-run this lab's measurements under it. This is the fastest path from "I read fair.c" to "I have changed scheduling policy and measured it".

6. Reproduce the throttling tail. Put the reader in a cgroup with a small cpu.max, produce the ~period-length latency tail, and then produce the cpu.stat output that identifies it. Write it up as if it were a bug report you received — that write-up is a genuinely useful artifact.

Validation / Self-check

1. Walk the path from write() to the reader running, naming every function and the two tracepoints.
2. In a sched_wakeup line, what do target_cpu and the bracketed CPU number mean, and why do they differ?
3. How do you compute wakeup latency from two tracepoints? What exactly is being measured?
4. What does perf sched latency's "delay" column measure, and why is it the right number for a bug report?
5. What fraction of your ping-pong wakeups landed on the waker's CPU, and what explains it?
6. Why does pinning both processes to one CPU sometimes make the round trip faster?
7. What makes a remote CPU notice that something was enqueued on it? When is that avoided?
8. Distinguish a shifted peak from a long tail in a latency histogram. What does each imply?
9. Why are GDB-derived timings meaningless, and what is GDB good for here instead?
10. You have a production machine where "some requests are occasionally slow". Give the exact first three commands you would run, and what each would rule in or out.

Next: Memory Management — the other subsystem every driver touches.