Linux Kernel events tracing

When working on a Linux system, it can be convenient to use the kernel events tracing mechanism, (described in details in Documentation/trace/events.txt in the Linux kernel sources).

We will only focus on a very simple use case here.

Listing possible event traces

All traceable events are listed under the  /sys/kernel/debug/tracing/events/ hierarchy of directories

Access to kernel event tracing is reserved to privileged users, so all instructions below need to be executed with root privileges

# ls -l /sys/kernel/debug/tracing/events/

Typical result:

alarmtimer  cfg80211  compaction  ext4  filelock  header_event  irq       mdio     napi  oom             power   raw_syscalls  rpm     skb    sunrpc   timer   workqueue block       cgroup    cpuhp       f2fs  filemap   header_page   jbd2      migrate  net   page_isolation  printk  rcu           sched   smbus  swiotlb  udp     writeback bpf         clk       dma_fence   fib   ftrace    i2c           kmem      mmc      nfs   pagemap         qdisc   regmap        scsi    sock   task     vmscan  xdp bridge      cma       enable      fib6  gpio      ipi           mac80211  module   nfs4  percpu          random  regulator     signal  spi    thermal

The first step is obviously to identify the events you want to trace within these. 

For example, let's look at the mmc events structure: 

# tree /sys/kernel/debug/tracing/events/mmc

The following hierarchy is present, with files and subfolders:

/sys/kernel/debug/tracing/events/mmc
├── enable
├── filter
├── mmc_request_done
│   ├── enable
│   ├── filter
│   ├── format
│   ├── id
│   └── trigger
└── mmc_request_start
    ├── enable
    ├── filter
    ├── format
    ├── id
    └── trigger

Each folder containing an enable file can be activated/de-activated by writing a 1 or a 0 to the corresponding enable file.

Each filter file corresponds to a list of filters applied to the corresponding event.

Each format file lists all possible parameter (which can be used in filters) and shows the print format for the corresponding trace.

Event traces format

format files list all possible parameters and show the print format:

# cat /sys/kernel/debug/tracing/events/mmc/mmc_request_done/format

name: mmc_request_done
ID: 643
format:
        field:unsigned short common_type;       offset:0;       size:2; signed:0;
        field:unsigned char common_flags;       offset:2;       size:1; signed:0;
        field:unsigned char common_preempt_count;       offset:3;       size:1; signed:0;
        field:int common_pid;   offset:4;       size:4; signed:1;

        field:u32 cmd_opcode;   offset:8;       size:4; signed:0;
        field:int cmd_err;      offset:12;      size:4; signed:1;
        field:u32 cmd_resp[4];  offset:16;      size:16;        signed:0;
        field:unsigned int cmd_retries; offset:32;      size:4; signed:0;
. . . 
        field:unsigned int retune_period;       offset:124;     size:4; signed:0;
        field:struct mmc_request * mrq; offset:128;     size:4; signed:0;
        field:__data_loc char[] name;   offset:132;     size:4; signed:0;

print fmt: "%s: end struct mmc_request[%p]: cmd_opcode=%u cmd_err=%d cmd_resp=0x%x 0x%x 0x%x 0x%x cmd_retries=%u stop_opcode=%u stop_err=%d stop_resp=0x%x 0x%x 0x%x 0x%x stop_retries=%u sbc_opcode=%u sbc_err=%d sbc_resp=0x%x 0x%x 0x%x 0x%x sbc_retries=%u bytes_xfered=%u data_err=%d tag=%d can_retune=%u doing_retune=%u retune_now=%u need_retune=%d hold_retune=%d retune_period=%u", __get_str(name), REC->mrq, REC->cmd_opcode, REC->cmd_err, REC->cmd_resp[0], REC->cmd_resp[1], REC->cmd_resp[2], REC->cmd_resp[3], REC->cmd_retries, REC->stop_opcode, REC->stop_err, REC->stop_resp[0], REC->stop_resp[1], REC->stop_resp[2], REC->stop_resp[3], REC->stop_retries, REC->sbc_opcode, REC->sbc_err, REC->sbc_resp[0], REC->sbc_resp[1], REC->sbc_resp[2], REC->sbc_resp[3], REC->sbc_retries, REC->bytes_xfered, REC->data_err, REC->tag, REC->can_retune, REC->doing_retune, REC->retune_now, REC->need_retune, REC->hold_retune, REC->retune_period

Enabling/disabling event traces

To enable mmc/mmc_request_done:

# echo 1 > /sys/kernel/debug/tracing/events/mmc/mmc_request_done/enable

To disable mmc/mmc_request_done:

# echo 0 > /sys/kernel/debug/tracing/events/mmc/mmc_request_done/enable

Filtering events

Filtering events is done by writing a filter to the filter file

Filters can be set on each parameter listed in the format file, whether it is a numeric

# echo "cmp_opcode != 53" > /sys/kernel/debug/tracing/events/mmc/mmc_request_done/filter

or a string

# echo "name == mmc1" > /sys/kernel/debug/tracing/events/mmc/mmc_request_done/filter

or a combination

# echo "(cmd_opcode != 53) && name == mmc1" > /sys/kernel/debug/tracing/events/mmc/mmc_request_done/filter

The relational-operators depend on the type of the field being tested:

The operators available for numeric fields are:

==, !=, <, <=, >, >=, &

And for string fields they are:

==, !=, ~

The glob (~) accepts a wild card character (*,?) and character classes
([). For example:

  prev_comm ~ "*sh"
  prev_comm ~ "sh*"
  prev_comm ~ "*sh*"
  prev_comm ~ "ba*sh"

Clearing filters

To clear the filter for an event, write a '0' to the event's filter
file.

To clear the filters for all events in a subsystem, write a '0' to the
subsystem's filter file.

Following event traces during execution

# cat /sys/kernel/debug/tracing/trace_pipe &

Following this, any enabled event will be traced into the console 

 Event tracing may not work with kernel versions < 4.9, due to a limitation in the event tracing mechanism. Functions with event tracing located too far way from the start of a module may not get their events traced. A workaround consists in moving source code files using event tracing at the beginning of the list of object files used to link the module. This is corrected in higher kernel releases.