I got the idea for this rather silly post when I was trying to understand something regarding the Linux driver model and the DT (Device Tree). So, with Linux, a device driver (here am using a platform driver), need not hard-code the (platform) device stuff into the driver; in fact it mustn’t. That’s exactly what the DT is for. So, the driver can register itself as a platform driver and an entry is made in the DT for the platform device; then the DT source (.dts) is compiled (to .dtb) and passed along at boot (I tried all this on a Raspberry Pi 3 Model B+).

I was trying to empirically see for myself how exactly the kernel invokes our platform driver’s probe method? Lets use ftrace to find out (kudos Steven Rostedt & team)! To make it easier, we use the super trace-cmd(1) front-end to ftrace.

Get the trace-cmd source:

git
clone
https://git.kernel.org/pub/scm/linux/kernel/git/rostedt/trace-cmd.git

Build & install:

make
&& sudo make install

Use it: wanted to capture the work of platform_driver_register() within the insmod:

First, lets make it easier by ourselves emitting a message into the ftrace log buffer (via the trace_printk()), around the area of interest; this way, we can just search the (typically huge) report for this string!

[...]
trace_printk("@@@@@ %s: MARKER 1: platform_driver_register() begin\n", DRVNAME);
ret_val = platform_driver_register(&my_platform_driver);
trace_printk("@@@@@ %s: MARKER 2: platform_driver_register() done\n", DRVNAME);
[...]

TIP
To have ftrace trace the functions of a particular kernel module (very very useful!), use the syntax:

echo ":mod:<kernel-module-name>" >> /sys/kernel/debug/tracing/set_ftrace_filter

(Actually here I do not use this filter as otherwise we will lose the printk output).

trace-cmd record -p function_graph -F taskset 01 insmod ./dtdemo_platdrv.ko

trace-cmd
report -I -S -l > ftrc_rep.txt

Notice how we use taskset(1) to ensure that the process we’re interested in ftrace-ing (insmod(8)) runs on exactly one CPU (cpumask set to 01).

So back to the original question: Why is the printk slow? Because it executes a hell of a lot of code, in a loop. Why? Because it emits the content of the string passed character-by-character to the serial device. We actually see this by gleaning the voluminous trace-cmd report output below; I’ve just put three screenshots of the trace-cmd report output below, else the wrapping is far too much and ugly; also, all the output shown below in the screenshots may not be perfectly contiguous (though that’s the intention):

[…] the above repeats many times!

This, below, is the close brace of the above printk() (yes, it’s wrapped around, ignore that):

insmod-12410   0....  6164.594698: funcgraph_exit:       # 11726.146 us |                              }

So, in this particular case, it took around 117.26 ms to execute! Quite a bit…
A few additional (useless) stats:

The trace-cmd(1) (ftrace wrapper front-end) snippet of only the single printk is over 6000 lines (I extracted only the printk stuff into another text file):

$ wc -l the_ftraced_printk.txt 
 6546 the_ftraced_printk.txt
$ 

The function that actually writes a single character to the serial device here is serial8250_console_putchar(); lets see how many times it was called within this one printk:

$ grep "serial8250_console_putchar" the_ftraced_printk.txt |wc -l
 44
$ 

Whew. So, when one must output a lot of printk’s and it’s a time-constrained code path (think interrupts), what must one do? Ah: ftrace provides the versatile trace_printk() function. It’s functionally equivalent (better!) to the printk, but does not write to the kernel log buffer nor to the – critical point – console device; it writes to the ftrace buffer only (which, btw, is tunable – you can make it very large unlike the printk buffer). (An aside: check out my post A HEADER OF CONVENIENCE; it shows several macros. The MSG() macro emits a debug message: one can internally set the preference – to use the regular printk or the trace_printk().