Kernel Tracing for Context Switches and Scheduling

1. What is Tracing?

Before diving in, let's understand what we mean by "tracing." The Linux kernel is a complex system with thousands of things happening every second. Tracing is the act of recording specific events as they occur inside the kernel, allowing us to reconstruct a sequence of operations. These events can be function calls, returns from interrupts, or, most importantly for us today, scheduler decisions.

The primary tool for this is ftrace, the official tracer of the Linux kernel.

2. Exploring ftrace and tracefs

ftrace is not a single program but a framework built directly into the kernel. It exposes its controls through a special pseudo-filesystem, usually mounted at /sys/kernel/tracing or /sys/kernel/debug/tracing. Interacting with it means reading from and writing to files in this directory.

Let's watch a video from Steven Rostedt, the author of ftrace, to get a foundational overview.

The key idea is that we can enable specific kernel events and then read the trace file to see a log of when those events occurred.

3. Observing Context Switches with ftrace

Let's use the raw tracefs interface to see a context switch in action. This low-level approach helps build a solid understanding of the underlying mechanics.

The most important event for our purpose is sched_switch. This event fires every time the scheduler switches the CPU from one task to another.

Step-by-Step Guide:

1. Navigate to the tracing directory (you will need root privileges for this):

   cd /sys/kernel/tracing
   

2. Ensure tracing is off and clear the old trace buffer:

   echo 0 > tracing_on
   echo > trace
   

   Writing an empty string to the trace file clears its contents.

3. Find and enable the sched_switch event:
   Events are organized by subsystem. We can find scheduler events under events/sched.

   
   
   
   # See available scheduler events
   ls events/sched
   
   
   
   
   # Enable the sched_switch event
   echo 1 > events/sched/sched_switch/enable
   

4. Start tracing:

   echo 1 > tracing_on
   

5. Let it run for a couple of seconds while the system does some work (you can move your mouse or type in another terminal).

6. Stop tracing:

   echo 0 > tracing_on
   

7. Read the trace log:

   cat trace
   

You will see output similar to this:

# tracer: nop
#
# entries-in-buffer/entries-written: 4/4   #P:16
#
#                                _-----=> irqs-off
#                               / _----=> need-resched
#                              | / _---=> hardirq/softirq
#                              || / _--=> preempt-depth
#                              ||| /     delay
#           TASK-PID     CPU#  ||||    TIMESTAMP  FUNCTION
#              | |         |   ||||       |         |
           bash-1836    [004] ....  4633.243916: sched_switch: prev_comm=bash prev_pid=1836 prev_prio=120 prev_state=R ==> next_comm=kworker/4:1 next_pid=123 next_prio=120
      kworker/4:1-123    [004] ....  4633.244243: sched_switch: prev_comm=kworker/4:1 prev_pid=123 prev_prio=120 prev_state=S ==> next_comm=bash next_pid=1836 next_prio=120

Interpreting the Output:

• bash-1836: The task being switched out (prev_comm=bash, prev_pid=1836).
• [004]: The CPU core where this happened.
• 4633.243916: The timestamp in seconds since boot.
• sched_switch: The name of the event.
• prev_state=R: The previous task was in a runnable state (R). S means it was sleeping (waiting for something).
• ==>: The switch itself.
• next_comm=kworker/4:1: The task being switched in.

This single line tells you exactly when the scheduler made a decision, on which CPU, what task was stopped, and what task was started. By analyzing these events, you can reconstruct the exact execution history of your CPUs.

The following video provides a detailed walkthrough of this exact process.

4. trace-cmd: A Friendlier Frontend

While the tracefs interface is powerful, it can be cumbersome. The community created trace-cmd, a command-line tool that acts as a user-friendly frontend to ftrace. It simplifies recording and reporting traces.

Using trace-cmd, the entire process from the previous section becomes two simple commands:

1. Record the trace: This command enables the sched_switch and sched_wakeup events, starts tracing, waits for you to press Ctrl+C, and then saves the collected data to a file named trace.dat.

   
   
   
   # You may need to install it first: sudo apt-get install trace-cmd
   sudo trace-cmd record -e sched:sched_switch -e sched:sched_wakeup
   

   Why sched_wakeup? This event tells you when a sleeping task is marked as runnable. The time between a sched_wakeup and the corresponding sched_switch is the scheduling latency—a critical metric in real-time systems.

2. Report the trace: This command reads trace.dat and prints a human-readable report.

   sudo trace-cmd report
   

The trace-cmd tool handles all the echo commands, buffer management, and formatting for you.

5. A Glimpse of Modern Tracing with eBPF

While ftrace is the foundational tracing framework, the ecosystem has evolved. The most significant advancement is the extended Berkeley Packet Filter (eBPF). eBPF allows you to run small, sandboxed programs inside the kernel itself. This enables much more powerful and efficient tracing, as you can filter, aggregate, and summarize data at the source instead of dumping millions of raw events to user-space.

For a senior developer interview, being aware of eBPF and its advantages is crucial.

A popular frontend for eBPF is bpftrace, which provides a high-level scripting language. The equivalent of our sched_switch trace can be done with this simple one-liner:

# You may need to install it: sudo apt-get install bpftrace
sudo bpftrace -e 'tracepoint:sched:sched_switch { printf("%s -> %s\n", args->prev_comm, args->next_comm); }'

This command attaches a small program to the sched_switch tracepoint. Each time the event fires, the program executes the printf statement inside the kernel, printing the names of the old and new tasks. This demonstrates the programmability and efficiency that eBPF brings to kernel tracing.

6. Interview Scenario: Diagnosing Scheduling Latency

Let's apply what we've learned to a typical interview question.

Scenario: You are working on an automotive system where a high-priority SCHED_FIFO task is responsible for a critical control loop. You suspect it's experiencing sporadic delays and not getting the CPU as quickly as it should after being woken up. How would you investigate this using kernel tracing?

Your Thought Process and Answer:

1. Identify the Key Events: The problem is about the delay between a task becoming runnable and it actually running. This translates to two kernel events:

   • sched_wakeup: Occurs when the task is marked runnable (e.g., its timer expires or I/O completes).
   • sched_switch: Occurs when the task is actually placed on the CPU.
     The time difference between these two events is the scheduling latency.

2. Choose the Right Tool: trace-cmd is an excellent choice. It's standard, powerful, and easy to use.

3. Formulate the Command:

   sudo trace-cmd record -e sched_wakeup -e sched_switch
   

   I would run this command while the system is exhibiting the problem.

4. Analyze the Trace Data:
   After stopping the trace, I would run trace-cmd report | grep 'my_task_name'.

   • First, I'd find a sched_wakeup event for my task's PID. I'd record the timestamp.
   • Next, I'd find the first sched_switch event after that wakeup where my task appears as the next_comm. I'd record its timestamp.
   • The difference between these two timestamps is the latency for that specific instance.

5. Pinpoint the Cause:
   The crucial step is to look at the sched_switch events that occurred on the same CPU during that latency window. The prev_comm field in those events will tell me exactly what other task(s) were running on the CPU, preventing my high-priority task from executing. This could reveal:

   • A higher-priority real-time task was running (correct behavior).
   • The kernel was stuck in an interrupt handler for a long time (a driver bug).
   • Another task of the same priority was running, and I should reconsider my priority assignments.

6. Mention Advanced Techniques: For bonus points, I would mention that for long-term monitoring, a simple trace can generate too much data. A better approach would be to use an eBPF script (with bpftrace or BCC) to calculate the latency in-kernel and only export statistics or outliers, which is far more efficient.

Conclusion

You have now learned how to peer inside the kernel and see the scheduler at work. This is no longer a theoretical black box. You have the tools to verify its behavior and diagnose real-world problems.

Key Takeaways:

• ftrace is the Linux kernel's built-in tracing framework, controlled via the tracefs pseudo-filesystem.
• The sched:sched_switch event is the fundamental tracepoint for observing context switches and scheduling decisions.
• trace-cmd is a user-friendly command-line tool that simplifies recording and reporting ftrace data.
• eBPF and bpftrace represent the modern, programmable approach to kernel tracing, offering superior efficiency and flexibility for complex analysis.
• By tracing sched_wakeup and sched_switch, you can precisely measure scheduling latency, a critical performance metric.

In our next lesson, we will put this new skill to the test. We will be presented with a scenario-based scheduling problem, such as priority inversion or CPU starvation, and use these tracing techniques to diagnose the root cause and propose a solution.