2002-03-15 02:15:06

by Tony.P.Lee

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

> -----Original Message-----
> From: ext Alan Cox [mailto:[email protected]]
> 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.




2002-03-15 14:29:12

by Alan

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

> 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

2002-03-18 21:49:16

by Larry Kessler

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

[email protected] 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.