Author: Mugabi Siro

Category: General Linux

Summary:

This entry discusses the use of various API for printing messages in the kernel. References to kernel sources, headers and other files are with respect to the root of the kernel source tree. Linux 3.11.0 was used for reference.

Tags: linux debugging/tracing

Introduction

Humorous but serious Documentation/CodingStyle includes the following note1:

    Chapter 13: Printing kernel messages

Kernel developers like to be seen as literate. Do mind the spelling
of kernel messages to make a good impression. Do not use crippled
words like "dont"; use "do not" or "don't" instead.  Make the messages
concise, clear, and unambiguous.

Kernel messages do not have to be terminated with a period.

Printing numbers in parentheses (%d) adds no value and should be avoided.

There are a number of driver model diagnostic macros in <linux/device.h>
which you should use to make sure messages are matched to the right device
and driver, and are tagged with the right level:  dev_err(), dev_warn(),
dev_info(), and so forth.  For messages that aren't associated with a
particular device, <linux/printk.h> defines pr_debug() and pr_info().

Coming up with good debugging messages can be quite a challenge; and once
you have them, they can be a huge help for remote troubleshooting.  Such
messages should be compiled out when the DEBUG symbol is not defined (that
is, by default they are not included).  When you use dev_dbg() or pr_debug(),
that's automatic.  Many subsystems have Kconfig options to turn on -DDEBUG.
A related convention uses VERBOSE_DEBUG to add dev_vdbg() messages to the
ones already enabled by DEBUG.

The naming conventions for the pr_* and dev_* interfaces imply printk loglevels. printk is discussed here.

General Purpose Printing

The pr_* macros and functions are defined in <linux/printk.h>:

$ less include/linux/printk.h
(...)
#ifndef pr_fmt
#define pr_fmt(fmt) fmt
#endif

#define pr_emerg(fmt, ...) \
    printk(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
#define pr_alert(fmt, ...) \
    printk(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)

                ...     ...     ...

#define pr_cont(fmt, ...) \
    printk(KERN_CONT fmt, ##__VA_ARGS__)

Should the need to customize and override the default pr_fmt setting arise, place the new macro definition at the top of your source file before #include <linux/printk.h> (or any headers that include <linux/printk.h>), for example:

#define pr_fmt(fmt) "%s:%s:%d:: ", fmt, KBUILD_MODNAME, __func__, __LINE__
#include <linux/kernel.h>  /* this includes <linux/printk.h> */

In this case, whenever pr_emerg, pr_alert, etc are used, then their print-out will have the kernel module name, function name and line number prepended to whatever that was included in the macro parenthesis. The following userspace code is presented in the hopes of clarifying this pr_fmt usage:

$ cat vipi.c

#include <stdio.h>
#include <libgen.h> /* basename */

#define MODNAME basename(__FILE__)

#define pr_fmt(fmt) "%s:%s:%d:: " fmt, MODNAME, __func__, __LINE__
#define pr_info(fmt, ...) \
    printf(pr_fmt(fmt), ##__VA_ARGS__)

int main(void)
{
    pr_info("Dunia, vipi? Moja ni %d tu.\n", 1);    
    return 0;
}

Using the -E (preprocessor) switch of gcc(1) helps to view the macro expansion:

$ gcc -E vipi.c | tail -5
int main(void)
{
    printf("%s:%s:%d:: " "Dunia, vipi? Moja ni %d tu.\n", __xpg_basename("vipi.c"), __func__, 10, 1);
    return 0;
}

Compiling and running:

$ gcc -Wall -O2 vipi.c
$ ./a.out
vipi.c:main:10:: Dunia, vipi? Moja ni 1 tu.

Driver model diagnostic macros

The function prototypes of dev_emerg, dev_alert, etc, are declared in <linux/device.h>.

$ less include/linux/device.h
(...)
#ifdef CONFIG_PRINTK
(...)
extern __printf(2, 3)
int dev_emerg(const struct device *dev, const char *fmt, ...);
(...)
extern __printf(2, 3)
int _dev_info(const struct device *dev, const char *fmt, ...);

#else

(...) /* if !CONFIG_PRINTK, then these function do nothing */

#endif

/*
 *  hackaround for existing uses of non-printk uses dev_info
 *
 * Note that the definition of dev_info below is actually _dev_info
 * and a macro is used to avoid redefining dev_info
 */

#define dev_info(dev, fmt, arg...) _dev_info(dev, fmt, ##arg)

See Section Appendix for an explanation of __printf(N, M).

The functions dev_emerge, dev_alert, etc, are defined (via macro expansion) in drivers/base/core.c (and exported if CONFIG_PRINTK is enabled).

$ less drivers/base/core.c
(...)
/*
 * Device logging functions
*/
#ifdef CONFIG_PRINTK
(...)
#define define_dev_printk_level(func, kern_level)       \
int func(const struct device *dev, const char *fmt, ...)    \
{                               \
    struct va_format vaf;                   \
    va_list args;                       \
    int r;                          \
                                \
    va_start(args, fmt);                    \
                                \
    vaf.fmt = fmt;                      \
    vaf.va = &args;                     \
                                \
    r = __dev_printk(kern_level, dev, &vaf);        \
                                \
    va_end(args);                       \
                                \
    return r;                       \
}                               \
EXPORT_SYMBOL(func);

define_dev_printk_level(dev_emerg, KERN_EMERG);
define_dev_printk_level(dev_alert, KERN_ALERT);
define_dev_printk_level(dev_crit, KERN_CRIT);
define_dev_printk_level(dev_err, KERN_ERR);
define_dev_printk_level(dev_warn, KERN_WARNING);
define_dev_printk_level(dev_notice, KERN_NOTICE);
define_dev_printk_level(_dev_info, KERN_INFO);
#endif /* CONFIG_PRINTK */

struct device

The dev_* functions accept a pointer to an object of type struct device as their first argument. In the Linux device model, devices are represented by a struct device and are connected to the system via a bus. A bus may be associated with a physical channel (PCI, USB, etc) or an internal, virtual "platform" bus. Generally, once a device driver successfully completes the necessary initialization in it's init function, the corresponding underlying bus layer will prepare a struct device, for the device driver. This structure will then be passed to the device driver's callback methods in someway. For example:

$ less drivers/usb/serial/cyberjack.c
(...)
static void cyberjack_read_int_callback(struct urb *urb)
{
    struct usb_serial_port *port = urb->context;
    (...)
    struct device *dev = &port->dev;
    (...)
        result = usb_submit_urb(port->read_urb, GFP_ATOMIC);
        if (result)
            dev_err(dev, "%s - failed resubmitting read urb, error %d\n",
                __func__, result);
    (...)
}

$ less drivers/video/xilinxfb.c
(...)
static int xilinxfb_of_probe(struct platform_device *op)
{
    (...)
    drvdata = kzalloc(sizeof(*drvdata), GFP_KERNEL);
    if (!drvdata) {
        dev_err(&op->dev, "Couldn't allocate device private record\n");
        return -ENOMEM;
    }
    (...)
}

$ less drivers/net/ethernet/intel/igbvf/netdev.c
(...)
static int igbvf_probe(struct pci_dev *pdev, const struct pci_device_id *ent)
{
    (...)
    err = hw->mac.ops.reset_hw(hw);
    if (err) {
        dev_info(&pdev->dev,
             "PF still in reset state. Is the PF interface up?\n");
    (...)
}

Rate Limiting

The pr_* variants are defined in include/linux/printk.h:

#ifdef CONFIG_PRINTK
#define printk_ratelimited(fmt, ...)     \
({                                       \
    static DEFINE_RATELIMIT_STATE(_rs,     \
              DEFAULT_RATELIMIT_INTERVAL,  \
              DEFAULT_RATELIMIT_BURST);    \
                                           \
    if (__ratelimit(&_rs))                 \
        printk(fmt, ##__VA_ARGS__);          \
})
(...)
#define pr_emerg_ratelimited(fmt, ...)                  \
    printk_ratelimited(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
(...)
#define pr_info_ratelimited(fmt, ...)                   \
    printk_ratelimited(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
/* no pr_cont_ratelimited, don't do that... */

while the dev_* interfaces are defined in include/linux/device.h:

#define dev_level_ratelimited(dev_level, dev, fmt, ...)         \
do {                                    \
    static DEFINE_RATELIMIT_STATE(_rs,       \
                DEFAULT_RATELIMIT_INTERVAL,  \
                DEFAULT_RATELIMIT_BURST);    \
    if (__ratelimit(&_rs))              \
        dev_level(dev, fmt, ##__VA_ARGS__);    \
} while (0)

#define dev_emerg_ratelimited(dev, fmt, ...)                \
    dev_level_ratelimited(dev_emerg, dev, fmt, ##__VA_ARGS__)
(...)
#define dev_info_ratelimited(dev, fmt, ...)             \
    dev_level_ratelimited(dev_info, dev, fmt, ##__VA_ARGS__)

where:

/* include/linux/ratelimit.h */
#define DEFAULT_RATELIMIT_INTERVAL  (5 * HZ)
#define DEFAULT_RATELIMIT_BURST   10

Printing Once Only

Print a one-time message. The code is self-explanatory:

#ifdef CONFIG_PRINTK
#define printk_once(fmt, ...)      \
({                                 \
    static bool __print_once;        \
                                     \
    if (!__print_once) {             \
        __print_once = true;           \
        printk(fmt, ##__VA_ARGS__);    \
    }                                \
})
(...)
#define pr_emerg_once(fmt, ...)    \
    printk_once(KERN_EMERG pr_fmt(fmt), ##__VA_ARGS__)
#define pr_alert_once(fmt, ...)    \
    printk_once(KERN_ALERT pr_fmt(fmt), ##__VA_ARGS__)
(...)
#define pr_info_once(fmt, ...)     \
    printk_once(KERN_INFO pr_fmt(fmt), ##__VA_ARGS__)
#define pr_cont_once(fmt, ...)     \
    printk_once(KERN_CONT pr_fmt(fmt), ##__VA_ARGS__)

Printing Debug Messages

The pr_devel macro is expanded if the code is compiled with a DEBUG directive for the preprocessor.

/* include/linux/printk.h */
#ifdef CONFIG_PRINTK
    #ifdef DEBUG
        #define pr_devel(fmt, ...) \
            printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

On the other hand, pr_debug behaviour also depends on whether CONFIG_DYNAMIC_DEBUG was defined:

/* include/linux/printk.h */
#ifdef CONFIG_PRINTK
    #if defined(CONFIG_DYNAMIC_DEBUG)
        /* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
        #define pr_debug(fmt, ...) \
            dynamic_pr_debug(fmt, ##__VA_ARGS__)
    #elif defined(DEBUG)
        #define pr_debug(fmt, ...) \
            printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)

CONFIG_DYNAMIC_DEBUG is discussed below under "Dynamic Debug". Now, for some action, consider:

$ cat external_module.c

#define pr_fmt(fmt) "%s:%d" fmt, __func__, __LINE__
#include <linux/module.h>

static int xmod_init(void)
{
    pr_info("\n");
    pr_debug("\n");
    return 0;
}

static void xmod_fini(void)
{
    pr_info("\n");
    pr_debug("\n");
}

module_init(xmod_init);
module_exit(xmod_fini);

MODULE_LICENSE("GPL");

$ cat Makefile
ifneq ($(KERNELRELEASE),)
obj-m := external_module.o
else

KDIR ?= /lib/modules/$$(uname -r)/build

default:
    $(MAKE) -C $(KDIR) M=$$PWD modules

clean:
    $(MAKE) -C $(KDIR) M=$$PWD clean

.PHONY : clean
endif

$ make

$ sudo sh -c "echo 8 > /proc/sys/kernel/printk"

$ sudo insmod external_module.ko
[16211.429980] xmod_init:6

$ sudo rmmod external_module 
[16249.616083] xmod_fini:13

$ make clean

$ make KCPPFLAGS=-DDEBUG

$ sudo insmod external_module.ko
[16322.325751] xmod_init:6
[16322.326461] xmod_init:7

$ sudo rmmod external_module 
[16324.883789] xmod_fini:13
[16324.885189] xmod_fini:14

Note:

  • If writing a device driver, use the dev_dbg interface instead. Like pr_dbg, its behaviour also depends on whether CONFIG_DYNAMIC_DEBUG was enabled:

    /* include/linux/device.h */
    #if defined(CONFIG_DYNAMIC_DEBUG)
    #define dev_dbg(dev, format, ...)              \
    do {                                           \
        dynamic_dev_dbg(dev, format, ##__VA_ARGS__); \
    } while (0)
    #elif defined(DEBUG)
    #define dev_dbg(dev, format, arg...)           \
        dev_printk(KERN_DEBUG, dev, format, ##arg)
    
  • The pr_devel_once, pr_debug_once, pr_devel_ratelimited, pr_debug_ratelimited and dev_dbg_ratelimited interfaces are also available.

Dynamic Debug

  • Kernel Config

    Select Kernel hacking >> printk and dmesg options >> Enable dynamic printk() support [CONFIG_DYNAMIC_DEBUG=y]

  • See Documentation/dynamic-debug-howto.txt

Resources

  • Linux v3.11 sources

Footnotes

1. Make an earnest effort to browse through the entire Documentation/CodingStyle - I haven't done so yet. [go back]

Appendix

  • __printf(N, M)

    This is a macro defined in include/linux/compiler-gcc.h:

    #define __printf(a, b)      __attribute__((format(printf, a, b)))
    

    format is a gcc feature for "printf-style" functions where:

    • a - Position of format string (fmt)

    • b - Position of arguments supplied to format string (...)

    Essentially, __attribute__((format(printf, a, b))) instructs cc1 to perform compile time checks to ensure that the arguments supplied have types appropriate to the format string specified, and that the conversions specified in the format string make sense. See -Wformat in gcc(1).