From: Vegard Nossum <vegard.nossum@...>
Subject: [RFC] New kernel-message logging API
Date: Sep 22, 3:27 pm 2007

After recent discussions on LKML and a general dissatisfaction at the
current printk() kernel-message logging interface, I've decided to
write down some of the ideas for a better system.


Requirements
============

 * Backwards compatibility with printk(), syslog(), etc. There is no
way the whole kernel can be converted to a new interface in one go.
printk() is used all over the kernel, in many different ways,
including calls from assembly, multi-line prints spread over several
calls, etc.

 * Extensibility. Features like timestamping or file/line recording
[1] should be both selectable at compile-time and (if compiled in) at
run-time.


API
===

#define kprint(fmt, ...)

The main part of the kprint interface should be the kprint() function.
The string must be a single line of information (ie. it must not
contain any newlines). Calling kprint("Hello world") is equivalent to
calling printk("Hello world\n"). kprint() may be implemented as a
macro, and must not be called from assembly.


To support the different log-levels, there exists one kprint_*()
function for each log-level, for example kprint_info(). The string
must be a single line of information. Calling kprint_emerg("Oops.") is
equivalent to calling printk(KERN_EMERG "Oops.\n"). These functions
may also be implemented as macros, and must also not be called from
assembly. The different log-levels (and their functions) are:

enum kprint_loglevel {
	KPRINT_EMERG,	/* kprint_emerg() */
	KPRINT_ALERT,	/* kprint_alert() */
	KPRINT_CRIT,	/* kprint_crit() */
	KPRINT_ERROR,	/* kprint_error() and/or kprint_err() */
	KPRINT_WARNING,	/* kprint_warning() and/or kprint_warn() */
	KPRINT_NOTICE,	/* kprint_notice() */
	KPRINT_INFO,	/* kprint_info() */
	KPRINT_DEBUG,	/* kprint_debug() */
};

In order to print several related lines as one chunk, the emitter
should first allocate an object of the type struct kprint_buffer. This
buffer is initialized with the function kprint_buffer_init() which
takes as arguments a pointer to an object of the type struct
kprint_buffer followed by the log-level number. The emitter may then
make as many or as few calls to kprint_buffer() that is desired.
kprint_buffer() is a function that takes a literal string followed by
a variable number of arguments, similarly to the kprint() function. A
final call to kprint_buffer_flush() appends the messages to the kernel
message log in a single, atomic call. After it has been flushed, the
buffer is not usable again (unless it is re-initialized). If for any
reason the buffer should be de-initialized without writing it to the
log, a call to kprint_buffer_abort() must be made.

Example: {
	struct kprint_buffer buf;

	kprint_buffer_init(&buf, KPRINT_DEBUG);
	kprint_buffer(&buf, "Stack trace:");

	while(unwind_stack()) {
		kprint_buffer(&buf, "%p %s", address, symbol);
	}

	kprint_buffer_flush(&buf);
}


It may happen that certain parts of the kernel might wish to emit
messages to the log (and console, if any) in an early part of the boot
procedure, for example before the main memory allocation routines have
been set up properly. For this purpose, a function kprint_early()
exists. This "early" is a minimal way for the kernel to log its
functions, and may as such not include all the features of the full
kprint system. When the kernel is beyond the critical "early" point,
the messages (if any) in the "early" log may be moved into the main
logging store and kprint_early() must not be used again.
kprint_early() is a function and may be called from assembly.

To allow non-early calls from assembly, a function kprint_asm()
exists. This function takes a log-level number followed by a string
literal followed by a variable number of arguments.


The then legacy printk() function must be replaced by a
backwards-compatible but different interface. In short, printk should
parse messages, remove (and convert) initial log-level tokens, remove
any newlines (splitting the string into several lines), and call the
apropriate kprint()-system functions.


Internals
=========

The kprint() and its log-level variants are implemented as macros in
order to be able to transparently pass extra information into the main
kprint() machinery. As an example, it might happen that an extra
feature is added that prepends the current file and line (the __FILE__
and __LINE__ macros) to the message, but in such a way that it can be
discarded at run-time, or recorded along with the messages.
Additionally, this would allow the compiler to completely optimize out
calls that are below a certain log-level severity level [2][3].

With such a modular interface, message attributes (for example the
current time) and arguments can be recorded separately from the actual
format string, instead of written formatted to a ring buffer as a
sequence of characters. Parameters would be formatted to their own
strings (regardless of the original type) and saved in an array.

Example: {
	struct kprint_message {
		const char *format;

		unsigned int argc;
		char **argv;

	#ifdef KPRINT_TIMESTAMP
		unsigned long long timestamp;
	#endif

	#ifndef KPRINT_LOCATION
		const char *file;
		unsigned int line;

		const char *function;
	#endif
	};
}

This can be a great help, for example in (user-space) localisation of
kernel messages [4], since the "static" message (ie. format string)
can be translated seperately and the arguments re-attached at
run-time, possibly in a different order. A new kernel-/user-space
interface would be needed to retrieve the messages in this format.

The syslog() and /proc/kmsg interfaces can retain backwards
compatibility by formatting messages as they are requested from
user-space.


Considerations
==============

This scheme is obviously much more complex than the printk() is today.
But at the same time, it is also much more powerful, extensible, and
clearly/cleanly defined.

One of the difficult things with kernel messages is that the interface
should be fail-proof. We must be able to tell the user that our memory
allocator just blew. In the current printk() interface, a ring buffer
of fixed size is used. With a fixed, static buffer, we are certain to
never run into memory-related problems, even if the rest of the system
is unstable or unusable.

I think an easy solution would be to check for EMERG messages and
treat these with special care, like using a static reservoir.

The message entry and a message's arguments are kept separately. Most
likely, there will be a huge number of tiny allocations. I am not sure
how well this is handled in the kernel. Or we could try to merge the
allocation of the struct kprint_message and its arguments into a
single allocation by looking at the arguments before they're
formatted. After all, the arguments cannot exist without the message
or vice versa. Alternatively, a statically-sized ring buffer of struct
kprint_message objects could be used, and then only arguments would
need to be allocated dynamically. Either way, I think it should be
possible to come up with a fairly memory-efficient system even for
this method of storing the kernel log.

Also undealt with are dev_printk(), sdev_printk(), and
ata_dev_printk(), but our backwards compatible printk() should handle
this. Alternatively, the macros could be changed, though as I know
close to nothing about them, I'll leave this entire field to somebody
else.


References:
[1] http://lkml.org/lkml/2007/9/21/267 (Joe Perches <joe@perches.com>)
[2] http://lkml.org/lkml/2007/9/20/352 (Rob Landley <rob@landley.net>)
[3] http://lkml.org/lkml/2007/9/21/151 (Dick Streefland
<dick.streefland@altium.nl>)
[4] http://lkml.org/lkml/2007/6/13/146 (holzheu <holzheu@linux.vnet.ibm.com)



Vegard
-


From: Jesse Barnes <jesse.barnes@...>
Subject: Re: [RFC] New kernel-message logging API
Date: Sep 24, 2:26 pm 2007

On Saturday, September 22, 2007 12:27 pm Vegard Nossum wrote:
> enum kprint_loglevel {
> 	KPRINT_EMERG,	/* kprint_emerg() */
> 	KPRINT_ALERT,	/* kprint_alert() */
> 	KPRINT_CRIT,	/* kprint_crit() */
> 	KPRINT_ERROR,	/* kprint_error() and/or kprint_err() */
> 	KPRINT_WARNING,	/* kprint_warning() and/or kprint_warn() */
> 	KPRINT_NOTICE,	/* kprint_notice() */
> 	KPRINT_INFO,	/* kprint_info() */
> 	KPRINT_DEBUG,	/* kprint_debug() */
> };

I wonder if all these levels are still needed (though I really like the 
error/err & warning/warn aliases, those always get me :).

It seems like fewer levels would make things easier on both kernel 
developers and administrators; looking at current counts may help 
figure out which ones could be combined (warning, very naive grep -r 
data):

KERN_EMERG: 371
KERN_ALERT: 236
KERN_CRIT: 602
KERN_ERR: 11961
KERN_WARNING: 6463
KERN_NOTICE: 1142
KERN_INFO: 8491
KERN_DEBUG: 6125

So KERN_ERR is the most common by a pretty large margin, though it seems 
to me that KERN_NOTICE, KERN_INFO and KERN_DEBUG are mostly redundant 
and probably make up a majority of the "SIMD FPU exception support was 
enabled" (as if I care) type messages.  Likewise, ERR, ALERT, CRIT and 
EMERG serve very similar purposes (i.e. something unrecoverable 
occurred), maybe they could be condensed into one or two levels rather 
than four?  So that would drop us to three levels:

KERN_ERR /* something really bad happened, machine is dead or near so */
KERN_WARNING /* you really ought to know about this */
KERN_INFO /* no one but the kernel developer likely cares about this */

But maybe I'm just living in a dream world where then number of printks 
the kernel spits out suddenly drops by 99% and only actually important 
messages make it to my log...

Jesse
-


From: Rob Landley <rob@...>
Subject: Re: [RFC] New kernel-message logging API
Date: Sep 23, 4:05 pm 2007

On Saturday 22 September 2007 2:27:29 pm Vegard Nossum wrote:
> After recent discussions on LKML and a general dissatisfaction at the
> current printk() kernel-message logging interface, I've decided to
> write down some of the ideas for a better system.
>
>
> Requirements
> ============
>
>  * Backwards compatibility with printk(), syslog(), etc.

I.E. what we have now works just fine for what it does.

>  * Extensibility. Features like timestamping or file/line recording
> [1] should be both selectable at compile-time and (if compiled in) at
> run-time.

That doesn't require changing the API.  Allowing the compiler to eliminate 
messages below a threshold requires changing the API.

>
> API
> ===
>
> #define kprint(fmt, ...)
>
> The main part of the kprint interface should be the kprint() function.

And then you propose not having a single kprint() function...

> To support the different log-levels, there exists one kprint_*()
> function for each log-level, for example kprint_info().

Why is this better than feeding the level in as an argument to the macro?

> In order to print several related lines as one chunk, the emitter
> should first allocate an object of the type struct kprint_buffer.

You know, I'm pretty happy with a first pass that doesn't address this issue 
at all.  Why bundle three unrelated problems into a single all-or-nothing 
pass?

Rob
-- 
"One of my most productive days was throwing away 1000 lines of code."
  - Ken Thompson.
-