Linux Device Drivers

Chapter 4. Debugging Techniques

One of the most compelling problems for anyone writing kernel code is how to approach debugging. Kernel code cannot be easily executed under a debugger, nor can it be traced, because it is a set of functionalities not related to a specific process.

This chapter introduces techniques you can use to monitor kernel code and trace errors.

Debugging by Printing

The most common debugging technique is monitoring, which in applications programming is done by calling printf at suitable points. When you are debugging kernel code, you can accomplish the same goal with printk.

Printk

We used the printk function in earlier chapters with the simplifying assumption that it works like printf. Now it’s time to introduce some of the differences.

One of the differences is that printk lets you classify messages according to their severity by associating different ``loglevels,'' or priorities with the messages. You indicate the loglevel with a macro. For example, KERN_INFO, which we saw prepended to some of the earlier print statements, is one of the possible loglevels of the message. The loglevel macro expands to a string, which is concatenated to the message text at compile time; that’s why there is no comma between the priority and the format string in the examples below. Here are two examples of printk commands, a debug message and a critical message:

printk(KERN_DEBUG "Here I am: line %i\n", __LINE__);
printk(KERN_CRIT "I'm trashed; giving up on %p\n", ptr);

There are eight possible loglevel strings, which are defined in the header <linux/kernel.h>. A printk statement with no specified priority defaults to DEFAULT_MESSAGE_LOGLEVEL, an integer value specified in kernel/printk.c. The default loglevel value has changed several times during Linux development, so I suggest that you always specify a suitable loglevel.

Based on the loglevel, the kernel prints the message to the current text console: if the priority is less than the integer variable console_loglevel, the message is displayed. If both klogd and syslogd are running on the system, kernel messages are appended to /var/log/messages, independent of console_loglevel.

The variable console_loglevel is initialized to DEFAULT_CONSOLE_ LOGLEVEL and can be modified through the sys_syslog system call. One way to change it is by specifying the -c switch when invoking klogd, as specified in the klogd man page. Note that to change the current value, you must first kill the logger and then restart it with the -c option. Alternatively, you can write a program to change the console loglevel. You’ll find my version of such a program in misc-progs/setlevel.c in the source files provided on the O’Reilly FTP site. The new level is specified as an integer value between 1 and 8, inclusive.

You’ll probably want to lower the loglevel after a kernel fault (see Section 4.4), because the fault-handling code raises the console_loglevel to 15, causing every subsequent message to appear on the console. You’ll want to raise the loglevel if you are running a 2.0.x kernel and want to see your debugging messages. The 2.0 kernel release lowered the MINIMUM_CONSOLE_LOGLEVEL, while old versions of klogd tried by default to shut up console messages. If you happen to run an old daemon, the 2.0 kernel will be much quieter than you expect unless you raise the loglevel. That’s why hello.c had the <1> markers; they are there to make sure that messages appear on the console.

Versions of Linux from 1.3.43 on allow for some flexibility in logging policies by letting you send messages to a specific virtual console. By default, the ``console'' is the current virtual terminal. To select a different virtual terminal to receive messages, you can issue ioctl(TIOCLINUX) on any console device. The following program, setconsole, can be used to choose which console receives kernel messages; it must be run by the superuser. If you don’t feel confident using ioctl, you might prefer to skip to the next section and come back to this code after reading the section Section 5.1 in Chapter 5.

int main(int argc, char **argv)
{
    char bytes[2] = {11,0}; /* 11 is the TIOCLINUX cmd number */

    if (argc==2) bytes[1] = atoi(argv[1]); /* the chosen console */
    else {
        fprintf(stderr, "%s: need a single arg\n",argv[0]); exit(1);
    }

    if (ioctl(STDIN_FILENO, TIOCLINUX, bytes)<0) {    /* use stdin */
        fprintf(stderr,"%s: ioctl(stdin, TIOCLINUX): %s\n",
                argv[0], strerror(errno));
        exit(1);
    }
    exit(0);
}

setconsole uses the special ioctl command TIOCLINUX, which implements Linux-specific functions. To use TIOCLINUX, you pass it an argument that is a pointer to a byte array. The first byte of the array is a number that specifies the requested subcommand, and the following bytes are subcommand-specific. In setconsole, subcommand 11 is used, and the next byte (stored in bytes[1]) identifies the virtual console. The complete description of TIOCLINUX can be found in drivers/char/tty_io.c, in the kernel sources.

How Messages Get Logged

The printk function writes messages into a circular buffer that is LOG_BUF_LEN bytes long. It then wakes any process that is waiting for messages, i.e., any process that is sleeping in the syslog system call or that is reading /proc/kmesg. These two interfaces to the logging engine are equivalent. Nonetheless, reading the /proc file is easier because the file looks like a fifo, from which kernel messages can be read. A simple cat can read the messages.

If the circular buffer fills up, printk wraps around and starts adding new data to the beginning of the buffer, overwriting the oldest data. The logging process thus loses the oldest data. This problem is negligible compared to the advantages of using such a circular buffer. For example, a circular buffer allows the system to run even without a logging process, while minimizing memory waste. Another feature of the Linux approach to messaging is that printk can be invoked from anywhere, even from an interrupt handler, with no limit on how much data can be printed. The only disadvantage is the possibility of losing some data.

If the klogd process is running, it retrieves kernel messages and dispatches them to syslogd, which in turn checks /etc/syslog.conf to find out how to deal with them. syslogd differentiates between messages according to a ``facility'' and a ``priority''; allowable values for both the facility and the priority are defined in <sys/syslog.h>. Kernel messages are logged by the LOG_KERN facility, at a priority corresponding to the one used in printk. If klogd isn’t running, data remains in the circular buffer until someone reads it or the buffer overflows.

If you want to avoid clobbering your system log with the monitoring messages from your driver, you can either specify the -f (file) option to klogd to write the messages to a different file, or modify /etc/syslog.conf. Another possibility is to take the brute-force approach: kill klogd and verbosely print messages on an unused virtual terminal,^[14] or issue the command cat /proc/kmesg from an unused xterm.

Using the Preprocessor to Ease Monitoring

During the early stages of driver development, printk can help considerably in debugging and testing new code. When you officially release the driver, on the other hand, you should remove, or at least disable, such print statements. Unfortunately, you’re likely to find that as soon as you think you no longer need the messages and remove them, you’ll implement a new feature in the driver and want to turn at least one of the messages back on. There are several ways to solve both issues--how to globally enable and disable the messages and how to turn individual messages off and on.

The code I use for most of my messaging is shown below and has the following features:

• Each print statement can be enabled or disabled by removing or adding a single letter to the macro’s name.

• All the messages can be disabled at once, by changing the value of the CFLAGS variable before compiling.

• The same print statement can be used in kernel code (the driver) and user-level code (demonstration and test programs).

The code fragment below implements these features and comes directly from the header scull.h.

#undef PDEBUG             /* undef it, just in case */
#ifdef SCULL_DEBUG
# ifdef __KERNEL__
   /* This one if debugging is on, and kernel space */
#  define PDEBUG(fmt, args...) printk(KERN_DEBUG "scull: " fmt, ## args)
# else
   /* This one for user space */
#  define PDEBUG(fmt, args...) fprintf(stderr, fmt, ## args)
# endif
#else
# define PDEBUG(fmt, args...) /* not debugging: nothing */
#endif

#undef PDEBUGG
#define PDEBUGG(fmt, args...) /* nothing: it's a placeholder */

The symbols PDEBUG and PDEBUGG depend on whether or not SCULL_DEBUG is defined, and they behave like a printf call.

To simplify the process further, add the following lines to your Makefile:

# Comment/uncomment the following line to disable/enable debugging
DEBUG = y

ifeq ($(DEBUG),y)
  DEBFLAGS = -O -g -DSCULL_DEBUG # "-O" is needed to expand inlines
else
  DEBFLAGS = -O2
endif

CFLAGS = -D__KERNEL__ -DMODULE -Wall $(DEBFLAGS)

The macros shown in this section depend on a gcc extension to the ANSI C preprocessor that supports macros with a variable number of arguments. This gcc dependency shouldn’t be a problem because the kernel proper depends heavily on gcc features anyway. In addition, the Makefile depends on GNU’s gmake; the same considerations apply to make it not a problem.

If you’re familiar with the C preprocessor, you can expand on the definitions above to implement the concept of a ``debug level,'' defining different levels and assigning an integer (or bitmask) value to each level to determine how verbose it should be.

But every driver has its own features and monitoring needs. The art of good programming is in choosing the best tradeoff between flexibility and efficiency, and I can’t tell what is the best for you. Remember that preprocessor conditionals (as well as constant expressions in the code) are executed at compile time, so you must recompile to turn messages on or off. A possible alternative is to use C conditionals, which are executed at run time and therefore permit you to turn messaging on and off during program execution. This ability is a nice feature, but it requires additional processing every time the code is executed, which can affect performance even when the messages are disabled. Sometimes this performance hit is unacceptable.

Personally, I’ve been satisfied with the macros shown above, although they force me to recompile and reload the module every time I want to add or remove a message.

---

^[14] For example, use setlevel 8; setconsole 10 to set up tty 10 to display messages.