Chapter 3: Debug via Instrumentation – printk and Friends

Quick, think: how often have you interspersed printf() instances (or the equivalent) in your program in order to follow its progress as it executes code, and indeed, to see at approximately which point it (perhaps) crashes? Often, I'm guessing! Don't feel bad at all, this is a really good debugging technique! It has a fancy name to boot: instrumentation.

What you've been doing is instrumenting your code, allowing you to see the flow (depending on the granularity of your print statements); this allows you to understand where it's been. Often enough, this is all that's required to debug many situations. Do recollect, though, what we discussed in the previous chapter – a technique like instrumentation is typically useful in certain circumstances, not all. For example, a resource leak (such as a memory leak) defect is difficult, if not impossible, to debug with instrumentation. For most...

Technical requirements

The technical requirements and workspace remain identical to what's described in Chapter 1, A General Introduction to Debugging Software. The code examples can be found within the book's GitHub repository here: https://github.com/PacktPublishing/Linux-Kernel-Debugging.

The ubiquitous kernel printk

There's a good reason the famous and familiar Kernighan and Ritchie (K&R) Hello, world C program employs the printf() API: it's the preferred API via which any output is written to the screen (well, technically, to the standard output channel stdout of the calling process). After all, it's how we can actually see that our program is really doing something, right?

You will surely recall using this API when writing your very first C program. Did you write the code that incorporates the printf() function? No, of course not; then where is it? You know: it's part of the (typically rather large) standard C library – GNU libc (glibc) on Linux. Pretty much every binary executable program on a Linux box automatically and dynamically links into this library; thus printf() is pretty much always available! (On x86, doing ldd $(which ps) will have the useful ldd script show you the libraries that the ps app links into; one of them will...

Leveraging the printk for debug purposes

You might imagine that all you have to do to emit a debug message to the kernel log is simply to issue a printk at the log level KERN_DEBUG. Though there's (a lot) more to it, the pr_debug() (and dev_dbg()) macros are actually designed to be more than mere printers when the kernel's dynamic debug option is enabled. We will learn about this powerful aspect in the coming Using the kernel's powerful dynamic debug feature section.

In this section, let's first learn more about issuing a debug print, followed by slightly more advanced ways that help in the issuing of debug messages to the kernel log.

Writing debug messages to the kernel log

In the simple kernel module we covered in the previous section (printk_loglevel), let's relook at the couple of lines of code that emitted a kernel printk at the debug log levels:

pr_debug("Hello, debug world @ log-level KERN_DEBUG   [%d]\n", LOGLEVEL_DEBUG...

Using the kernel's powerful dynamic debug feature

The instrumentation approach to debugging – interspersing your kernel (and module) code with many printk is indeed a good technique. It helps you narrow things down and debug them! But as you've no doubt realized, there can be a (pretty high) cost to this:

• It eats into your disk (or flash) space as logs get filled in. This can be especially problematic on constrained embedded systems. Also, writing to disk is much slower than writing to RAM.
• It's fast in RAM, but the ring buffer is not that large and would thus quickly get overwhelmed; older prints will soon be lost.
• Even more important, on many production systems, a high volume of printks would have an adverse performance impact, creating bottlenecks and even possible livelocks! Rate limiting helps with this, to some extent...

A solution would be to use the pr_debug() and/or the dev_dbg() APIs! They're especially useful during development...

Remaining printk miscellany

By now, you're familiar with most of the typical and pragmatic means to leverage the kernel's powerful and ubiquitous printk and its related APIs, macros, and frameworks. Of course, innovation never stops (especially in the open source universe). The community has come up with more and more ways (and tooling) to use this simple and powerful tool. Without claiming to cover absolutely everything, here's what I think is the remaining and relevant tooling to do with the printk that we haven't had a chance to cover until now. Do check it out – it will probably turn out to be useful one day!

Printing before console init – the early printk

You understand that the printk output can be sent to the console device of course (we covered this in the Understanding where the printk output goes section(see Table 3.1). By default, on most systems, it's configured such that all printk messages of log level 3 and below (<4)...

Summary

Good going! You've just completed the first of many techniques for debugging the kernel. Instrumentation, though deceptively simple, almost always proves to be a useful and powerful debugging technique.

In this chapter, you began by learning the basics regarding the ubiquitous kernel printk(), pr_*(), and dev_*() routines and macros. We then went into more detail about the specific use of these routines to help in debug situations and tips and tricks that will prove useful in debugging your (driver) modules... This included leveraging the kernel's ability to rate-limit printks, often a necessity on high-volume code paths.

The kernel's elegant and powerful dynamic debug framework was the highlight of this chapter. Here, you learned about it, and how to leverage it to be able to toggle your (and indeed the kernel's) debug prints even on production systems, with virtually no performance degradation when turned off.

We finished this chapter with a...

Further reading

• Code browser tutorials:
  • Ctags Tutorial: https://courses.cs.washington.edu/courses/cse451/10au/tutorials/tutorial_ctags.html
  • The Vim/Cscope tutorial: http://cscope.sourceforge.net/cscope_vim_tutorial.html
• The printk and /dev/kmsg: https://www.kernel.org/doc/Documentation/ABI/testing/dev-kmsg
• Debugging by printing: https://elinux.org/Debugging_by_printing; covers useful info on debugging with the early printk facility, even debugging by dumping the kernel log from the bootloader as well!
• Signing kernel modules; official kernel documentation: Kernel module signing facility: https://www.kernel.org/doc/html/v5.0/admin-guide/module-signing.html#kernel-module-signing-facility
• Red Hat Developer series on GDB:
  • The GDB developer's GNU Debugger tutorial, Part 1: Getting started with the debugger, Seitz, RedHat Developer, Apr 2021: https://developers.redhat.com/blog/2021/04/30/the-gdb-developers-gnu-debugger-tutorial-part-1-getting-started-with-the-debugger...