Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18

[Larry Kessler]

Brian,

I am responding to your comments in reverse order:

> One thing to remember, is that the really hard and important part of
> logging is not the part that can be legislated, or automated, it is
> making sure that the correct events are reported in a accurate manner

I could not agree more, and there has not really been any guidance for
developers about what correct and accurate events are (nor is it clear
that developers would follow the guidance, anyway).  Our focus,
obviously, has been on whether or not the existing logging capabilities 
facilitate the accurate recording of "correct" events.  I will comment
more on that below.

> I understand about POSIX standards, but POSIX standards are not the
> infallible word of of the diety of computing and sometimes are
> completely bogos.

True, but in this case the POSIX standard is not a standard, but 
currently only a draft, and we (the Linux event logging team) have 
been (and are continuing to be) directly involved it its writing,
editing, and (eventual, we hope) adoption as a standard.  Even so,
balloting could lead it into a direction that is contrary to what
is best for Linux, in which case we would drop the "POSIX compliant"
claims and do what's really needed.  I do not expect that to happen,
but you can never tell.

> Instead of adding
> extra kernel functionality, would it not be possible to define a text
> format to messages and some SIMPLE macros, to allow printk's to generate
> the desired information...
> ...it maye be possible to provide some formating guidelines
> and support to printk and some log analysis tools to provide 99%
> solution.

Ok, I am not conceding that your suggestion is "better" than event
logging, but I do like the concept and we have, in fact, been discussing
how to somehow get more information out of printk without asking kernel
maintainers to use a different API.  Specifically, we thought about 
renaming the printk() function and creating a printk macro.  In the
printk macro you would collect source file name, line number and
function name (and maybe some other useful info), and then call the
renamed printk function with the original message plus the additional
stuff (actually we were thinking call posix_log_write() with the orig.
message+addl. info and call the renamed printk with just the original
message).

Is this the sort of thing you had in mind ?

The problem we found is some code like this...

printk("<1>" "And the answer is... %d\n",
#ifdef ONE
1
#else
2
#endif
);

which the compiler/preprocessor rejects.  

Just casually looking I found at least 3 device drivers that log this
way.
Do you think device driver maintainers would be willing to change  
their code to avoid this problem (and the Linux community be willing to 
abandon this style of coding with printks)?

I don't know if you've had a chance to look at the event filtering,
event
notification, and log management utilities that we have in the user lib,
but these work with text-based events, whether printks forwarded to
event 
logging, or messages logged with our new logging functions.  So the user
lib does have some log analysis/processing features like you've
mentioned. 

Another limitation that printk has is that everything has facility of
LOG_KERN.  Don't you think its useful to be able to define a facility of
"XYZ Ethernet 10/100 Device Driver" (which in event logging generates a 
32-bit CRC that gets stored in the event records, and gets converted
back 
to the facility name by the aforementioned utilities)?

I am absolutely open to suggestions for making printk messages better
and more useful--we just haven't figured-out how yet.

Thanks,
Larry Kessler
http://evlog.sourceforge.net/

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18y

[Alan Cox]

> I am absolutely open to suggestions for making printk messages better
> and more useful--we just haven't figured-out how yet.

What you don't want to do is break printk. In AberMUD I used macros for
something similar

#define Module  static char *Mod_Name=
#define Version static char *Ver_Name=
#define Author  static char *Aut_Name=

#define Error(x)        ErrFunc((x),Mod_Name,Ver_Name,__LINE__,__FILE__)

And drivers started

Module  "System";
Version "1.28";
Author  "----*(A)";


However that doesn't work for varargs. Nevertheless something of a similar
approach might let you avoid breaking printk in most old code. If you can
avoid a grand replacement of printk you win lots of friends. If you can
do it in a way that people can do automated parsing of kernel messages
for translation tables in klogd/initlog/dmesg you also win lots of friends.

RE: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18y

[Tony.P.Lee]

> -----Original Message-----
> From: ext Alan Cox [mailto:alan@lxorguk.ukuu.org.uk]
> Sent: Thursday, March 14, 2002 5:49 PM
> To: Larry Kessler

> > I am absolutely open to suggestions for making printk 
> messages better
> 
> However that doesn't work for varargs. Nevertheless something 
> of a similar
> approach might let you avoid breaking printk in most old 
> code. If you can
> avoid a grand replacement of printk you win lots of friends. 
> If you can
> do it in a way that people can do automated parsing of kernel messages
> for translation tables in klogd/initlog/dmesg you also win 
> lots of friends.
> 


How about this?

int printk_improve(const char* filename, int line_no, 
	const char* function_name, int module_buf_idx, ...);

#define printk(PRINTF_ARGS...) \
	printk_improve(__FILE__, __LINE__, __FUNCTION__, \
		CUR_MODULE_BUF_IDX, ##PRINTF_ARGS);


1) If anyone is going to add this to the kernel, please make sure
printk_improve also log the TSC, current_process_id (if avail), etc.  
Very useful for performance profiling and failure analysis.

2) The next imporvement is to able to log to different buffers as 
suggested, such as ethernet driver logging goes to its own buffer, 
filesystem goes to its own buffer.  

2a) If you implement logging to multiple buffers, you need to 
make sure there is a global counter that atomically increment 
for all the events regardles which buffer it goes to.   

I used it in our project (RTOS, non-linux, yet...).  
It is very powerful to debug any SMP bugs caused by timing and 
race condition.

3) After that you need to get special BIOS so that we can log the 
buffer to a section of memory that is preserved after reset.   
With this, you can easily postmortem diagnostic any problem that 
crash the kernel/ISR/Driver.   This is much easily to do in 
embedded projects as compare to PC, since we control the BIOS.


Did all these in few of my projects already, it is wonderful 
way to debug any "completely lockup" problem with RTOS/ISR/Kernel.
The nice thing is that I don't have to ask anyone to reproduce
the problems.  The logging is always on.

----------------------------------------------------------------
Tony Lee           Nokia Networks, Inc. 
p.s.  Looking for linux kernel module engineers to work on 
system with 40 pentium CPUs. 24 of which are P4 SMP running linux.
Email me if interested.

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18y

[Alan Cox]

> 1) If anyone is going to add this to the kernel, please make sure
> printk_improve also log the TSC, current_process_id (if avail), etc. =20
> Very useful for performance profiling and failure analysis.

We always have a guess at the current pid (current->pid is always safe
to talk about but in an IRQ its of questionable value. Since it tells you
what was running when it blew up it does sometimes help with stack
scribbes/overruns)

> 3) After that you need to get special BIOS so that we can log the=20
> buffer to a section of memory that is preserved after reset.  =20
> With this, you can easily postmortem diagnostic any problem that=20
> crash the kernel/ISR/Driver.   This is much easily to do in=20
> embedded projects as compare to PC, since we control the BIOS.

I've found that a lot of the 3dfx voodoo 4/5 boards are not cleared by
the firmware on boot up. This allows you to hide about 24Mb of logs in
the top of the card ram and recover it after a soft boot.

Alan

Re: [PATCH-RFC] POSIX Event Logging, kernel 2.5.6 & 2.4.18y

[Larry Kessler]

Tony.P.Lee@nokia.com wrote:
> How about this?
> 
> int printk_improve(const char* filename, int line_no,
>         const char* function_name, int module_buf_idx, ...);
> 
> #define printk(PRINTF_ARGS...) \
>         printk_improve(__FILE__, __LINE__, __FUNCTION__, \
>                 CUR_MODULE_BUF_IDX, ##PRINTF_ARGS);

When printk is defined as a macro...
"directives may not be used inside a macro argument"
...is the error caused by this style of coding:

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

In the 2.5.6 kernel, the complete list of source files 
with directives inside the printk arg list:
drivers/net/tulip/de4x5.c
drivers/net/de620.c
drivers/net/de600.c
drivers/net/slip.c
drivers/scsi/oktagon_esp.c
drivers/scsi/sun3_NCR5380.c
drivers/scsi/sym53c8xx.c
drivers/scsi/NCR5380.c
drivers/scsi/mac_NCR5380.c
drivers/scsi/ncr53c8xx.c
drivers/scsi/seagate.c
drivers/scsi/atari_scsi.c
drivers/scsi/atari_NCR5380.c
drivers/s390/s390io.c
arch/ppc/8xx_io/fec.c
arch/alpha/kernel/setup.c
arch/s390x/kernel/setup.c
arch/s390/kernel/setup.c
sound/oss/msnd_pinnacle.c
fs/ntfs/fs.c

It is possible to submit patches to all of the maintainers
explaining that we wish to collect a standard set of info
with each call to printk, so please accept this patch, but
is it reasonable to prohibit this coding style ?  

On a related note, there are 554 #defines in the kernel that
contain "printk" in the first line, so there is some
customization going on already.