CPU Scheduling events

On Android and Linux Perfetto can gather scheduler traces via the Linux Kernel ftrace infrastructure.

This allows to get fine grained scheduling events such as:

  • Which threads were scheduling on which CPU cores at any point in time, with nanosecond accuracy.
  • The reason why a running thread got descheduled (e.g. pre-emption, blocked on a mutex, blocking syscall or any other wait queue).
  • The point in time when a thread became eligible to be executed, even if it was not put immediately on any CPU run queue, together with the source thread that made it executable.

UI

When zoomed out, the UI shows a quantized view of CPU usage, which collapses the scheduling information:

However, by zooming in, the individual scheduling events become visible:

Clicking on a CPU slice shows the relevant information in the details panel:

Scrolling down, when expanding individual processes, the scheduling events also create one track for each thread, which allows to follow the evolution of the state of individual threads:

data_sources {
  config {
    name: "linux.ftrace"
    ftrace_config {
      ftrace_events: "sched/sched_switch"
      ftrace_events: "sched/sched_waking"
    }
  }
}

SQL

At the SQL level, the scheduling data is exposed in the sched_slice table.

select ts, dur, cpu, end_state, priority, process.name, thread.name
from sched_slice left join thread using(utid) left join process using(upid)
tsdurcpuend_statepriorityprocess.name,thread.name
2611870121709952471882S130/system/bin/logdlogd.klogd
261187012418183128122D120/system/bin/traced_probestraced_probes0
2611870124210992200004D120kthreaddkworker/u16:2
261187012430995723962D120/system/bin/traced_probestraced_probes1
261187012454537139580D120/system/bin/traced_probestraced_probes0
261187012460318463543S120/system/bin/traced_probestraced_probes2
261187012468495106250R120[NULL]swapper/0
26118701247912064590D120/system/bin/traced_probestraced_probes0
26118701248557977600R120[NULL]swapper/0
261187012493339348960D120/system/bin/traced_probestraced_probes0

TraceConfig

data_sources: {
    config {
        name: "linux.ftrace"
        ftrace_config {
            ftrace_events: "sched/sched_switch"
            ftrace_events: "sched/sched_process_exit"
            ftrace_events: "sched/sched_process_free"
            ftrace_events: "task/task_newtask"
            ftrace_events: "task/task_rename"
        }
    }
}

# This is to get full process name and thread<>process relationships.
data_sources: {
    config {
        name: "linux.process_stats"
    }
}

Scheduling wakeups and latency analysis

By further enabling the following in the TraceConfig, the ftrace data source will record also scheduling wake up events:

  ftrace_events: "sched/sched_wakeup_new"
  ftrace_events: "sched/sched_waking"

While sched_switch events are emitted only when a thread is in the R(unnable) state AND is running on a CPU run queue, sched_waking events are emitted when any event causes a thread state to change.

Consider the following example:

Thread A
condition_variable.wait()
                                     Thread B
                                     condition_variable.notify()

When Thread A suspends on the wait() it will enter the state S(sleeping) and get removed from the CPU run queue. When Thread B notifies the variable, the kernel will transition Thread A into the R(unnable) state. Thread A at that point is eligible to be put back on a run queue. However this might not happen for some time because, for instance:

  • All CPUs might be busy running some other thread, and Thread A needs to wait to get a run queue slot assigned (or the other threads have higher priority).
  • Some other CPUs other than the current one, but the scheduler load balancer might take some time to move the thread on another CPU.

Unless using real-time thread priorities, most Linux Kernel scheduler configurations are not strictly work-conserving. For instance the scheduler might prefer to wait some time in the hope that the thread running on the current CPU goes to idle, avoiding a cross-cpu migration which might be more costly both in terms of overhead and power.

NOTE: sched_waking and sched_wakeup provide nearly the same information. The difference lies in wakeup events across CPUs, which involve inter-processor interrupts. The former is emitted on the source (wakee) CPU, the latter on the destination (waked) CPU. sched_waking is usually sufficient for latency analysis, unless you are looking into breaking down latency due to inter-processor signaling.

When enabling sched_waking events, the following will appear in the UI when selecting a CPU slice:

Decoding end_state

The sched_slice table contains information on scheduling activity of the system:

> select * from sched_slice limit 1
id  type        ts          dur    cpu utid end_state priority
0   sched_slice 70730062200 125364 0   1    S         130     

Each row of the table shows when a given thread (utid) began running (ts), on which core it ran (cpu), for how long it ran (dur), and why it stopped running: end_state.

end_state is encoded as one or more ascii characters. The UI uses the following translations to convert end_state into human readable text:

end_stateTranslation
RRunnable
SSleeping
DUninterruptible Sleep
TStopped
tTraced
XExit (Dead)
ZExit (Zombie)
xTask Dead
ITask Dead
KWake Kill
WWaking
PParked
NNo Load
+(Preempted)

Not all combinations of characters are meaningful.

If we do not know when the scheduling ended (for example because the trace ended while the thread was still running) end_state will be NULL and dur will be -1.