While debugging, it’s invaluable to be able to trace functions in the Linux kernel. There are several tools for that task: perf, ftrace (with helper tool like trace-cmd), bpftrace, etc.

For my own debug of kernel internals and in the last few years to debug the i915 module for Intel graphics, I usually use tracepoints or dynamic tracepoints (with perf probe) as the trigger for something I want to trace.

One question I get some times is “how do I trace the initial probe of a kernel module?”. At that time you (usually) don’t yet have the module loaded and as a consequence, the symbols of that module are still not available for using tracepoints. For example:

# trace-cmd list -e '^i915.*'
#

One thing to realize is that a lot of time we don’t want to debug the module loading, but rather the module binding to a device. These are 2 separate things, that happen in a cascade of events. It probably also adds to the confusion that the userspace tools to load the modules are not named very consistently: modprobe and insmod, and they end up calling the [f]init_module syscall.

The various buses available in the kernel have mechanisms for stopping the autoprobe (and hence binding to a device), when a module is loaded. With i915, all we have to do is to set a few things in the /sys/bus/pci/:

# echo 0 > /sys/bus/pci/drivers_autoprobe
# modprobe i915

With the i915 module, but not attached to any device, we are ready to attach to any tracepoint or create new dynamic probes. Let’s suppose I want to debug the i915_driver_probe()() function, and any function called by it during the initialization. This is one of the functions to initialize the GPU in i915 called when we are binding to a device.

F=i915_driver_probe

echo 0 > /sys/bus/pci/drivers_autoprobe 
modprobe i915

cd /sys/kernel/debug/tracing
cat /dev/null >  trace
echo $F > set_graph_function
echo _printk > set_graph_notrace
echo 10 > max_graph_depth
echo function_graph > current_tracer
echo 1 > tracing_on

echo 0000:03:00.0 | tee /sys/bus/pci/drivers/i915/bind
cp trace /tmp/trace.txt

echo 0 > tracing_on
cat /dev/null >  trace

With the snippet above we will start tracing whenever function i915_driver_probe() is executed. We also set a few additional parameters: set the maximum call depth to graph, disable graphing on printk() since it’s usually not very interesting. Depending on the size of your trace you may also need to increase the buffer_size_kb to avoid the ring buffer to rotate, or have something to pump data out off the ringbuffer to a file.

Even after we enable tracing by echo’ing 1 to the tracing_on file, nothing happens as we are not automatically binding to the device. In the snippet above we bind it manually, by writting the pci slot to the /sys/bus/pci/drivers/i915/bind file. We then should start seeing the function to be traced:

# head /tmp/trace.txt
# tracer: function_graph
#
# CPU  DURATION                  FUNCTION CALLS
# |     |   |                     |   |   |   |
  3)               |  i915_driver_probe [i915]() {
  3)               |    __devm_drm_dev_alloc() {
  3)               |      __kmalloc() {
  3)               |        kmalloc_order_trace() {
  3)               |          kmalloc_order() {
  3)               |            __alloc_pages() {

Another thing very useful to do is to attach to a specific tracepoint. For example, to trace the MMIO read/write we can do the commands below. Now I’m using trace-cmd directly and omitting the device bind, that we should do after start recording:

# trace-cmd record -e i915:i915_reg_rw
Hit Ctrl^C to stop recording
^C
# trace-cmd report
...
tee-2239  [009]   778.693172: i915_reg_rw:          read reg=0x51000, len=4, val=(0xc1900, 0x0)
tee-2239  [009]   778.693174: i915_reg_rw:          write reg=0xc6204, len=4, val=(0x10251000, 0x0)
tee-2239  [009]   778.693796: i915_reg_rw:          read reg=0xa26c, len=4, val=(0x4, 0x0)
tee-2239  [009]   778.693805: i915_reg_rw:          read reg=0xd00, len=4, val=(0x14, 0x0)
tee-2239  [009]   778.693808: bprint:               intel_gt_init_clock_frequency: 0000:03:00.0 Using clock frequency: 19200kHz, period: 53ns, wrap: 113816ms
tee-2239  [009]   778.693817: i915_reg_rw:          read reg=0x913c, len=4, val=(0xff00, 0x0)
tee-2239  [009]   778.693825: i915_reg_rw:          read reg=0x9144, len=4, val=(0xff00, 0x0)
tee-2239  [009]   778.693908: i915_reg_rw:          read reg=0x9134, len=4, val=(0xff, 0x0)
tee-2239  [009]   778.693918: i915_reg_rw:          read reg=0x9118, len=4, val=(0xd02, 0x0)
tee-2239  [009]   778.693933: i915_reg_rw:          read reg=0x9140, len=4, val=(0x30005, 0x0)
tee-2239  [009]   778.693941: i915_reg_rw:          read reg=0x911c, len=4, val=(0x3000000, 0x0)

Politreco by Lucas De Marchi

Other articles

Using evemu to simulate input devices

git helper for “recursive rebase”

“Throw away” linux images in seconds

Hacking the Intel fan, for fun

Optimizing hash table with kmod as testbed

Other articles

blogroll

social