Event logging vs enhancing printk

[Martin J. Bligh]

Sorry to drag up an old thread again, but Larry Kessler and I have been 
having some conversations about this subject over the last week, and I 
said I'd post the conclusions we came to. There's a reference to the more
general plans for Event Logging at: http://evlog.sourceforge.net/

1. Making any significant changes to the way we call existing printk subsystem 
is going to be extremely unpopular - the sheer bulk of changes needed to
make this kind of update, the mindshift for future developers, and the number
of patches that aren't yet in the mainline kernel that we'd break makes this
unfeasible.

2. Making any significant changes to the way we log existing messages into
/var/log/messages et al via syslog is going to be extremely unpopular - it
will break sysadmin's setups and log parsing scripts.

3. People want to be able to get better debug information, with more detail
than is currently possible with printk, hence the Event logging project. 
It's unrealistic to expect wholesale conversion to the new event logging
calls, though some drivers and kernel areas could be converted. 

Given these constraints, it seems like it may be best to leave the printk
subsystem more or less "as is", add the evlog subsystem as a seperate
entity, whilst adding hooks to printk to capture messages into the evlog
subsystem as well. This could be reasonably easily implemented by
renaming the existing printk call to printk_raw, and creating a new printk
macro along the lines of:

# ifdef CONFIG_EVLOG
	#define printk printk_evlog
# else
	#define printk printk_raw
# endif.

where printk_evlog calls printk_raw, then logs an "enhanced" version of
the printk message to the *event logging* subsystem (not /var/log/messages),
including process PID (0 or -1 if in_interrupt() ), file, line number, function,
cpu number, accurate time stamp, etc, etc.

Some people were worried about buffer usage, I'd suggest these enhanced
messages go into the evlog buffer, rather than the existing printk buffer,
which should avoid overflow problems.

Some printk's are not "line atomic" (5845 cases) - ie they do something like this:
"for (i=0; i<10; i++) { printk ("%d ", i); } printk("\n");" - this causes two problems:

1. There seems to me to be a race within the current SMP code (with or without
the event logging stuff). It seems that segments of the line could get interspersed 
with segments of another line (or a whole other line) generated by another cpu ... 
is this correct?

2. If we have event logging enabled we don't want to log a heavyweight message 
for each little piece of the printk - we really want to have one per "event". 

Unfortunately, I can't see how to designate an "event" under the existing infrastructure
of printk, but we can get close by breaking things up per line of output.
The solution would be similar for both problems mentioned above: we need to 
buffer  per line until we have a complete line, then flush the buffer out with the 
normal calls. The question is then where to store the buffer, or rather how many 
buffers to create. As we potentially have a pre-emptible kernel, I think we need 
to make a per task buffer (potentially just on the task's kernel stack?). The only 
case I can think of where this might go wrong is during an interrupt handler ... 
as long as we cannot get preempted during an interrupt handler, I think we're OK 
here too.

There are apparently about 20 cases where we do something like this:

   printk("generic options"
# ifdef AUTOPROBE_IRQ
	"AUTOPROBE_IRQ"
# else
	"AUTOSENSE"
# endif
	);

I'd propose we just unwrap these to:

# ifdef AUTOPROBE_IRQ
   printk("generic options"	 "AUTOPROBE_IRQ");
# else
   printk("generic options"	"AUTOSENSE");
# endif

which seems simple enough.

Hopefully this all makes sense, I know much of this has been stated before,
but it seems useful to pull together the current set of thoughts in one summary.

M.