Tuesday, September 16, 2008

Kernel Logging, Log Ring Buffer, printk(), syslog-ng

Kernel Log (Ring) Buffer

Linux kernel generates log messages using printk(). These messages are stored in a "ring buffer". The size of this buffer is controlled by a kernel configuration parameter:
CONFIG_LOG_BUF_SHIFT
The default value of this parameter is 14, which means 2^14 bytes, thus 16KB. The size of the buffer can not be changed online so it should be modified (if you'd like to have a larger or smaller buffer) before compiling the kernel (more information on kernel compilation). (1)

printk() - print() function at the Kernel level

printk() is used to print messages at the kernel level. The size of the message can not be larger than 1KB. Below is a sample printk() statement:
printk( KERN_INFO "message\n");
One can classify kernel messages according to their importance/priorities. Priority of a print statement is given by a log level macro. There are 8 priority levels defined in the kernel:
  • KERN_EMERG - emergency the highest level
  • KERN_ALERT, KERN_CRIT, KERN_ERR, KERN_WARNING, KERN_NOTICE, KERN_INFO, and
  • KERN_DEBUG - debugging messages with the lowest priority
For more information on printk(): Linux Device Drivers, 3rd Edition.

How are Kernel Log Messages Exposed to User Space?

The log buffer is exposed to user through /proc/kmsg file. If the file is read one can catch the kernel log messages. In fact, there are available programs to display the ingredients of the file /proc/kmsg, and log the content of this file in a static file (e.g., klogd and syslogd deamons, and syslog-ng logging facility). /proc is a memory filesystem (it contains virtual files which reveals the current state of the running Linux kernel), and the content of /proc/kmsg are being overwritten. In addition, reading from /proc/kmsg is destructive; that's, once you read a line/message it's removed from the file.(2)

"syslog-ng" (system log new generation) is a widely used logging application in Linux systems. It can directly read from /proc/kmsg and log the messages into static file(s). "syslog-ng" can be regarded as the upgraded version of the old kernel deamon "syslogd".

syslog-ng

syslog-ng can be configured so that messages can be directed based on their priorities. That means you direct different level of messages to different files.

syslog-ng can be configured using the configuration file:
  • /etc/syslog-ng/syslog-ng.conf (in SuSE Linux, you need to change syslog-ng.conf.in file which is used to generate syslog-ng.conf automatically by SuSE config).
In this configuration file, you define:
  • the sources syslog-ng is using: for example, /proc/kmsg, /dev/log, etc.
  • filters to identify the priority of a message or the facility from which a message is originated (news, mail, etc.)
  • destination files to direct the messages belonging to certain group (based on filters)
  • Finally, with "log" statements, you combine {source, filter, destination} to specify where to log which messages.
You can find some sample configuration files here, and some more information on logging with syslog-ng here.

Tuning syslog-ng for Performance

In "Monitoring Block I/O at Linux FileSystem Level" project, I am logging information on each block I/O using printk() function and syslog-ng logging facility. In our experiments, we can produce a trace file (i.e., a log file) of size 1 GB within couple of hours. As a result, to be able to configure HOW we log kernel messages into a static trace file is critical, we don't want to hurt the performance by producing too many I/O operations at a high rate.

However, using syslog-ng, you can control how you log the messages into a file. While defining a destionation file, you can set
  • log_fifo_size: log buffer size (in terms of number of messages)
  • fsynch(no): by saying "no", syslog-ng will not issue fflush() for each of the message received from the source; otherwise, it'd be catastrophic for the performance.
  • flush_lines & flush_timeout: syslog-ng will flush either flush_lines many message are collected in the log buffer of the destination or flush_timeout is passed since the last flushing.
As a result, you can control the rate at which you write the syslog-ng destination files.

Example

Below is a simple example for a syslog-ng configuration file:

# defining a source: /proc/kmsg -> kernel messages
source my_source { file("/proc/kmsg" log_msg_size(1024)); };

# defining a filter: kernel messages with the level of KERN_DEBUG
filter f_myfilter { facility(kern) and priority(debug); };

# defining a destination file: it defines a log file (i.e., a.txt) which will have its
# own buffer with a size of 10000 messages. Messages are flushed from buffer
# to the log file if 8000 messages are collected in the buffer of 5 second is past
# since the last flushing.
destination my_destination { file("/home/user/a.txt" log_fifo_size(10000) fsync(no) flush_lines(8000) flush_timeout(5000) );};

# Finally, a logging point is defined using above source, filter, and destination:
log { source(my_source); filter(f_myfilter); destination(my_destination); };

Foot Notes:
(1) Some information may be kernel version dependant. I've considered Linux kernel 2.6.21 in this document.
(2) dmesg which also examines the kernel ring buffer is on the other hand non-destructive.