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

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.

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.