It has been a long time, but updated the answer here for reference.
Here is what I finally finished:
Timestamps are enabled on my client terminal on a PC (TeraTerm).
Actually allowed to write the log to a file on disk &
Selected option to add a timestamp to each line.
Added printk() statements in the kernel.
- 1st at the beginning of the block that I was trying to configure.
- 2nd at the end of the block I was trying to configure.
Despite the slight delay between events on the device and when receiving logs on the host PC via the serial port, this is a fairly constant value for this hardware setting. Consequently, the difference between the two timestamps is accurate with the actual time-diff between the events on the device that generated these logs. Also the overhead / side effects of the 2 printk statements are minimal.
UPDATE: 2 years after the end of the line and hundreds of hours of kernel debugging, I would recommend using the tracers functions . It takes a little effort to learn. As it is well said here , you need:
- Include
CONFIG_FUNCTION_TRACER in .config - Use
trace_printk() instead of printk() - Check output logs
cat /sys/kernel/debug/tracing/trace
source share