printk subsystems
PATCH 1/1 printk subsystems
Hello,
In an effort to get greater control over which printk()'s are logged during boot and after, I've put together this patch that introduces the concept of printk subsystems. The problem that some are beginning to face with larger machines is that certain subsystems are overly verbose (SCSI, USB, cpu related messages on large NUMA or SMP machines) and they overflow the buffer. Making the logbuffer bigger is a stop gap solution but I think this is a more elegant solution.
Basically, each printk is assigned to a subsystem and that subsystem has the same set of values that the console_printk array has. The difference is that the console_printk loglevel decides if the message goes to the console whereas the subsystem loglevel decides if that message goes to the log at all.
This patch implements the core, but I haven't yet put in the facilities to change the default values that are used at compile-time. I'm looking for opinions on the architecture, not the completeness. I plan to add configuration through sysctl.
To use the feature you simply add the subsystem identifier to the printk call, much the same way that you add the priority tag:
printk(PRINTK_NET KERN_INFO "This is a printk from the net subsys\n");
Each subsystem has a default KERN_* priority, and if no subsystem is given then the printk is put into the PRINTK_UNASS queue (which is setup by default to log all messages).
The patch is against 2.5.66.
Opinions and comments welcome
mh
Signature · 192 lines
Martin Hicks || [email protected] || PGP/GnuPG: 0x4C7F2BEE plato up 6 days, 6:33, 14 users, load average: 0.09, 0.11, 0.09 Beer: So much more than just a breakfast drink. diff -X /home/mort/diff-exclude -uEr linux-2.5.66.pristine/include/linux/kernel.h linux-2.5.66/include/linux/kernel.h --- linux-2.5.66.pristine/include/linux/kernel.h 2003-03-17 16:43:37.000000000 -0500 +++ linux-2.5.66/include/linux/kernel.h 2003-04-07 14:33:05.000000000 -0400 @@ -47,6 +47,18 @@ #define minimum_console_loglevel (console_printk[2]) #define default_console_loglevel (console_printk[3]) +/* Printk subsystem identifiers */ +#define PRINTK_UNASS "<A>" /* unassigned printk subsystem */ +#define PRINTK_CORE "<B>" /* from the core kernel */ +#define PRINTK_SCSI "<C>" /* from the SCSI subsystem */ +#define PRINTK_NET "<D>" /* from the Net subsystem */ +#define PRINTK_USB "<E>" /* from the USB subsystem */ + +#define FIRST_PRINTK_SUBSYS PRINTK_UNASS[1] +#define LAST_PRINTK_SUBSYS PRINTK_USB[1] + +extern int printk_subsystem[5][4]; + struct completion; #ifdef CONFIG_DEBUG_SPINLOCK_SLEEP @@ -102,6 +114,62 @@ console_loglevel = 15; } +static inline int decode_subsys(char *subsys) +{ + if (subsys[1] >= FIRST_PRINTK_SUBSYS && + subsys[1] <= LAST_PRINTK_SUBSYS) + return subsys[1] - FIRST_PRINTK_SUBSYS; + return -1; +} + +/* returns the log threshold for a given subsystem. -1 on error. */ +static inline int get_subsys_loglevel(char *subsys) +{ + int index; + if ((index = decode_subsys(subsys)) != -1) + return printk_subsystem[index][0]; + return -1; +} + +/* sets the log threshold for a given subsystem. + * returns 0 if everything is okay, -1 if an error is encoutered. */ +static inline int set_subsys_loglevel(char *subsys, int level) +{ + int index; + if (level < 0 || level > 8) + return -1; + if ((index = decode_subsys(subsys)) != -1) { + if (level < printk_subsystem[index][2]) + level = printk_subsystem[index][3]; + printk_subsystem[index][0] = level; + return 0; + } + return -1; +} + +/* returns the default message level for a given subsystem. -1 on error */ +static inline int get_subsys_msglevel(char *subsys) +{ + int index; + if ((index = decode_subsys(subsys)) != -1) + return printk_subsystem[index][1]; + return -1; +} + +/* sets the default message level for a given subsystem. + * return 0 if everything is okay, - 1 if an error is encountered */ +static inline int set_subsys_msglevel(char *subsys, int level) +{ + int index; + if (level < 0 || level > 7) + return -1; + if ((index = decode_subsys(subsys)) != -1) { + printk_subsystem[index][1] = level; + return 0; + } + return -1; +} + extern void bust_spinlocks(int yes); extern int oops_in_progress; /* If set, an oops, panic(), BUG() or die() is in progress */ Only in linux-2.5.66.pristine/include/sound: pcm_sgbuf.h diff -X /home/mort/diff-exclude -uEr linux-2.5.66.pristine/kernel/printk.c linux-2.5.66/kernel/printk.c --- linux-2.5.66.pristine/kernel/printk.c 2003-03-17 16:44:50.000000000 -0500 +++ linux-2.5.66/kernel/printk.c 2003-04-07 14:54:33.356776808 -0400 @@ -42,6 +42,9 @@ #define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */ #define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */ +#define MINIMUM_SUBSYS_LOGLEVEL 1 +#define DEFAULT_SUBSYS_LOGLEVEL 8 + DECLARE_WAIT_QUEUE_HEAD(log_wait); int console_printk[4] = { @@ -51,6 +54,18 @@ DEFAULT_CONSOLE_LOGLEVEL, /* default_console_loglevel */ }; +int printk_subsystem[5][4] = { /* [][0] == subsystem log level + * [][1] == default message loglevel + * [][2] == minimum subsystem loglevel + * [][3] == default subsystem loglevel */ + [0 ... 4] = { + DEFAULT_SUBSYS_LOGLEVEL, + DEFAULT_MESSAGE_LOGLEVEL, + MINIMUM_SUBSYS_LOGLEVEL, + DEFAULT_SUBSYS_LOGLEVEL + } +}; + int oops_in_progress; /* @@ -390,10 +405,11 @@ { va_list args; unsigned long flags; - int printed_len; + int printed_len, msg_log_level, msg_subsystem, i; char *p; static char printk_buf[1024]; - static int log_level_unknown = 1; + static int begin_message = 1; + if (oops_in_progress) { /* If a crash is occurring, make sure we can't deadlock */ @@ -409,23 +425,44 @@ va_start(args, fmt); printed_len = vsnprintf(printk_buf, sizeof(printk_buf), fmt, args); va_end(args); - + /* - * Copy the output into log_buf. If the caller didn't provide - * appropriate log level tags, we insert them here + * Copy the output into log_buf. */ - for (p = printk_buf; *p; p++) { - if (log_level_unknown) { - if (p[0] != '<' || p[1] < '0' || p[1] > '7' || p[2] != '>') { + p = printk_buf; + while (*p) { + if (begin_message) { + /* Figure out if there is zero, one or two flags */ + msg_log_level = -1; + msg_subsystem = 0; /* A - Unassigned */ + for (i = 0; i < 2; i++) { + if (p[0] == '<' && p[2] == '>') { + if (p[1] >= '0' && p[1] <= '7') + msg_log_level = p[1] - '0'; + if (p[1] >= 'A' && p[1] <= 'G') + msg_subsystem = p[1] - 'A'; + } else + break; + p+=3; + } + + /* Decide if we print this message at all */ + if (msg_log_level == -1) + msg_log_level = printk_subsystem[msg_subsystem][1]; + + if (msg_log_level < printk_subsystem[msg_subsystem][0]) { + begin_message = 0; emit_log_char('<'); - emit_log_char(default_message_loglevel + '0'); + emit_log_char(msg_log_level + '0'); emit_log_char('>'); + } else { // Get out of this loop. Don't log anything. + break; } - log_level_unknown = 0; } emit_log_char(*p); if (*p == '\n') - log_level_unknown = 1; + begin_message = 1; + p++; } if (!cpu_online(smp_processor_id())) {
Hi!
Quoted 8 lines
In an effort to get greater control over which printk()'s are logged during boot and after, I've put together this patch that introduces the concept of printk subsystems. The problem that some are beginning to face with larger machines is that certain subsystems are overly verbose (SCSI, USB, cpu related messages on large NUMA or SMP machines) and they overflow the buffer. Making the logbuffer bigger is a stop gap solution but I think this is a more elegant solution.
Quoted 5 lines
Basically, each printk is assigned to a subsystem and that subsystem has the same set of values that the
console_printkarray has. The difference is that theconsole_printkloglevel decides if the message goes to the console whereas the subsystem loglevel decides if that message goes to the log at all.
Well, I consider this stop gap too... Right solution is to kill printk()s from too verbose part so that it does not overflow....
Pavel
Signature · 2 lines
When do you have a heart between your knees? [Johanka's followup: and *two* hearts?]
Quoted 7 lines
Quoted 7 lines
Quoted 1 line
Quoted 1 line
Quoted 1 line
"Pavel" == Pavel Machek <[email protected]> writes:
Basically, each printk is assigned to a subsystem and that subsystem has the same set of values that the
console_printkarray has. The difference is that theconsole_printkloglevel decides if the message goes to the console whereas the subsystem loglevel decides if that message goes to the log at all.
Pavel> Well, I consider this stop gap too... Right solution is to kill Pavel> printk()s from too verbose part so that it does not Pavel> overflow....
Hi Pavel,
Killing the printk's means they are not around if you have an end user who is running into problems at boot time. Having a feature like this means they can default to 'off' then if a problem arises, whoever is doing the support can ask the user to try and enable printk's for say SCSI and get the input, without haven to rebuild the kernel from scratch.
For people supporting large numbers of users (like all the distributions) this seems like a good win to me.
Cheers,
Jes
Hi!
Quoted 10 lines
Quoted 5 lines
Quoted 5 lines
Basically, each printk is assigned to a subsystem and that subsystem has the same set of values that the
console_printkarray has. The difference is that theconsole_printkloglevel decides if the message goes to the console whereas the subsystem loglevel decides if that message goes to the log at all.Pavel> Well, I consider this stop gap too... Right solution is to kill Pavel> printk()s from too verbose part so that it does not Pavel> overflow....
Quoted 8 lines
Hi Pavel,
Killing the printk's means they are not around if you have an end user who is running into problems at boot time. Having a feature like this means they can default to 'off' then if a problem arises, whoever is doing the support can ask the user to try and enable printk's for say SCSI and get the input, without haven to rebuild the kernel from scratch.
Well, I think we should first kill all crappy messages -- that benefits everyone. I believe that if we kill all unneccessary (carrying no information except perhaps copyright or advertising) will help current problem a lot.
See:Redundant:
Mar 31 21:38:54 amd kernel: Local APIC disabled by BIOS -- reenabling. Mar 31 21:38:54 amd kernel: Found and enabled local APIC! Strange: Mar 31 21:38:54 amd kernel: -> /dev Mar 31 21:38:54 amd kernel: -> /dev/console Mar 31 21:38:54 amd kernel: -> /root Could not those be made to a signle line? Or dropped completely? Mar 31 21:38:54 amd kernel: enabled ExtINT on CPU#0 Mar 31 21:38:54 amd kernel: ESR value before enabling vector: 00000000 Mar 31 21:38:54 amd kernel: ESR value after enabling vector: 00000000 Useless: Mar 31 21:38:54 amd kernel: Initializing RT netlink socket Mar 31 21:38:54 amd kernel: mtrr: v2.0 (20020519) I do not believe bio's are *that* important: Mar 31 21:38:54 amd kernel: BIO: pool of 256 setup, 15Kb (60 bytes/bio) Mar 31 21:38:54 amd kernel: biovec pool[0]: 1 bvecs: 256 entries (12 bytes) Mar 31 21:38:54 amd kernel: biovec pool[1]: 4 bvecs: 256 entries (48 bytes) Mar 31 21:38:54 amd kernel: biovec pool[2]: 16 bvecs: 256 entries (192 bytes) Mar 31 21:38:54 amd kernel: biovec pool[3]: 64 bvecs: 256 entries (768 bytes) Mar 31 21:38:54 amd kernel: biovec pool[4]: 128 bvecs: 256 entries (1536 bytes) Mar 31 21:38:55 amd kernel: biovec pool[5]: 256 bvecs: 256 entries (3072 bytes) Mar 31 21:38:55 amd kernel: block request queues: Mar 31 21:38:55 amd kernel: 128 requests per read queue Mar 31 21:38:55 amd kernel: 128 requests per write queue Mar 31 21:38:55 amd kernel: 8 requests per batch Mar 31 21:38:55 amd kernel: enter congestion at 15 Mar 31 21:38:55 amd kernel: exit congestion at 17 More useless stuff (could be usefull whhhhen CONFIG_MODULE, but when in kernel?) Mar 31 21:38:55 amd kernel: Linux Kernel Card Services 3.1.22 Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver usbfs Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver hub Mar 31 21:38:55 amd kernel: Coda Kernel/Venus communications, v5.3.15, [email protected] Mar 31 21:38:55 amd kernel: Installing knfsd (copyright (C) 1996 [email protected]). Mar 31 21:38:55 amd kernel: NTFS driver 2.1.0 [Flags: R/O DEBUG]. Mar 31 21:38:55 amd kernel: udf: registering filesystem Mar 31 21:38:55 amd kernel: Linux agpgart interface v0.100 (c) Dave Jones Mar 31 21:38:55 amd kernel: loop: loaded (max 8 devices) Mar 31 21:38:55 amd kernel: pcnet32.c:v1.27b 01.10.2002 [email protected] Mar 31 21:38:55 amd kernel: PPP generic driver version 2.4.2 Mar 31 21:38:55 amd kernel: PPP Deflate Compression module registered Mar 31 21:38:55 amd kernel: PPP BSD Compression module registered Mar 31 21:38:55 amd kernel: Linux Tulip driver version 1.1.13 (May 11, 2002) Mar 31 21:38:55 amd kernel: drivers/usb/host/uhci-hcd.c: USB Universal Host Controller Interface driver v2.0 Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver acm Mar 31 21:38:55 amd kernel: drivers/usb/class/cdc-acm.c: v0.21:USB Abstract Control Model driver for USB modems and ISDN adapte$Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver usblp Mar 31 21:38:55 amd kernel: drivers/usb/class/usblp.c: v0.13: USB Printer Device Class driver Mar 31 21:38:55 amd kernel: Initializing USB Mass Storage driver... Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver usb-storage Mar 31 21:38:55 amd kernel: USB Mass Storage support registered. Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver hid Mar 31 21:38:55 amd kernel: drivers/usb/input/hid-core.c: v2.0:USB HID core driver Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver vicam Mar 31 21:38:55 amd kernel: drivers/usb/net/cdc-ether.c: drivers/usb/net/cdc-ether.c: v0.98.5 22 Sep 2001 Brad Hards and anothe$Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new driver CDCEther Mar 31 21:38:55 amd kernel: drivers/usb/core/usb.c: registered new
driver usbnet
...and so on andsimilar.
Pavel
Signature · 2 lines
Horseback riding is like software... ...vgf orggre jura vgf serr.
Quoted 6 lines · Pavel Machek
Well, I think we should first kill all crappy messages -- that benefits everyone. I believe that if we kill all unneccessary (carrying no information except perhaps copyright or advertising) will help current problem a lot.
That may sometimes be true, but a few things may be useful to be able to turn back on.
-hpa
Hi!
Quoted 8 lines
Quoted 5 lines
Well, I think we should first kill all crappy messages -- that benefits everyone. I believe that if we kill all unneccessary (carrying no information except perhaps copyright or advertising) will help current problem a lot.
That may sometimes be true, but a few things may be useful to be able to turn back on.
Well, #define DEBUG in the driver seems like the way to go. I do not like "subsystem ID" idea, because subsystems are not really well defined etc.
Signature · 2 lines
Horseback riding is like software... ...vgf orggre jura vgf serr.
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
"Pavel" == Pavel Machek <[email protected]> writes:
Pavel> Well, #define DEBUG in the driver seems like the way to go. I Pavel> do not like "subsystem ID" idea, because subsystems are not Pavel> really well defined etc.
Which doesn't solve the problem as this means the end user will have to recompile his/her kernel to debug things. When Joe Random is sitting with his favorite distro CD trying to install it on a brand new motherboard doing funky things in it's ACPI routing or something like that, it's very useful for SuSE/Red Hat/Mandrake/Debian etc. to be able to instruct him to set this debug flag and tell them what happens.
Cheers,
Jes
Quoted 5 lines · Pavel Machek
Well, #define DEBUG in the driver seems like the way to go. I do not like "subsystem ID" idea, because subsystems are not really well defined etc.
I think that's a non-issue, because it's largely self-defining. It's basically whatever the developers want them to be, because they're the ones who it needs to make sense to.
It should, however, be an open set, not a closed set like in syslog.
-hpa
Quoted 10 lines · H. Peter Anvin
Quoted 5 lines · Pavel Machek
Well, #define DEBUG in the driver seems like the way to go. I do not like "subsystem ID" idea, because subsystems are not really well defined etc.
I think that's a non-issue, because it's largely self-defining. It's basically whatever the developers want them to be, because they're the ones who it needs to make sense to.
Exactly right. The worst cases are: 1) developers assign messages to a completely wrong subsystem or 2) don't assign the printk to any subsystem, in which case we're in exactly the same situation as we are in now.
Quoted 1 line
It should, however, be an open set, not a closed set like in syslog.
I agree. I'll try to make it as easy as possible to add another subsystem.
I'm going to work on the sysctl interface for this next.
mh
Signature · 1 line
Wild Open Source Inc. [email protected]
On Tue, 8 Apr 2003 18:55:23 -0400 Martin Hicks <[email protected]> wrote:
| On Tue, Apr 08, 2003 at 03:05:07PM -0700, H. Peter Anvin wrote: | > Pavel Machek wrote: | > > | > > Well, #define DEBUG in the driver seems like the way to go. I do not | > > like "subsystem ID" idea, because subsystems are not really well | > > defined etc. | > > | > | > I think that's a non-issue, because it's largely self-defining. It's | > basically whatever the developers want them to be, because they're the | > ones who it needs to make sense to. | | Exactly right. The worst cases are: 1) developers assign messages | to a completely wrong subsystem or 2) don't assign the printk to any | subsystem, in which case we're in exactly the same situation as we are | in now. | | > It should, however, be an open set, not a closed set like in syslog. | | I agree. I'll try to make it as easy as possible to add another | subsystem. | | I'm going to work on the sysctl interface for this next.
Eek, I have some opinions on this too.
I don't like the #define DEBUG approach. It's useless for users; it's a developer debug tool. It won't allow some support staff to ask users to enable module debugging (or subsystem debugging) and see what gets printed.
Martin, you are ahead of my schedule, but I was planning to use sysfs to add a 'debug' flag/file that could be dynamically altered on a per-module basis.
--
~Randy
Quoted 4 lines
I don't like the #define DEBUG approach. It's useless for users; it's a developer debug tool. It won't allow some support staff to ask users to enable module debugging (or subsystem debugging) and see what gets printed.
Agreed. Having a runtime-tweakable field would be very handy, and something that's been requested many times over.
Quoted 3 lines
Martin, you are ahead of my schedule, but I was planning to use sysfs to add a 'debug' flag/file that could be dynamically altered on a per-module basis.
Something I've pondered in the past is a per-subsystem (as in struct subsystem) debug field and log buffer. When the subsystem is registered, a sysfs 'debug' file is created, from which the user can set the noisiness level.
Quoted 1 line
From there, each subsystem can specify the size of a log buffer, which
would be allocated also when the subsystem is registered. Messages from the subsystem, and kobjects belonging to it, would be copied into the local log buffer.
Wrapper functions can be created, similar to the dev_* functions, which take a kobject as the first parameter. From this, the subsystem and log buffer, can be derived (or rather, passed to a lower-level helper).
This all falls under the 'gee-whiz-this-might-be-neat' category, and may inherently suck; I haven't tried it. Doing the core code is < 1 day's work, though there would be nothing that actually used it..
-pat
Quoted 8 lines · Patrick Mochel
Quoted 4 lines
I don't like the #define DEBUG approach. It's useless for users; it's a developer debug tool. It won't allow some support staff to ask users to enable module debugging (or subsystem debugging) and see what gets printed.
Agreed. Having a runtime-tweakable field would be very handy, and something that's been requested many times over.
Quoted 8 lines
Quoted 3 lines
Martin, you are ahead of my schedule, but I was planning to use sysfs to add a 'debug' flag/file that could be dynamically altered on a per-module basis.
Something I've pondered in the past is a per-subsystem (as in struct subsystem) debug field and log buffer. When the subsystem is registered, a sysfs 'debug' file is created, from which the user can set the noisiness level.
Would the debug level be for the entire subsystem? Do you think people would like to be able to set debug/logging level per driver or device, and not just subsystem?
Is debugging level here the same as logging level?
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in netdevice.h that can be set with Ethtool. I can see, for example, having the msg_enable not in the private data as it is now but in the subsystem or class structure for that device, such as in struct net_device. This could easily be exported through sysfs.
Thanks,
Dan
Quoted 15 lines
From there, each subsystem can specify the size of a log buffer, which would be allocated also when the subsystem is registered. Messages from the subsystem, and kobjects belonging to it, would be copied into the local log buffer.
Wrapper functions can be created, similar to the dev_* functions, which take a kobject as the first parameter. From this, the subsystem and log buffer, can be derived (or rather, passed to a lower-level helper).
This all falls under the 'gee-whiz-this-might-be-neat' category, and may inherently suck; I haven't tried it. Doing the core code is < 1 day's work, though there would be nothing that actually used it..
-pat
Quoted 4 lines
Would the debug level be for the entire subsystem? Do you think people would like to be able to set debug/logging level per driver or device, and not just subsystem?
I can see a use for doing per-object debug levels, but I'd rather not add the overhead to every object, especially when it would be used by a small minority of the populace.
Such a flag could easily be placed in the subsystem-specific object, and accessed through the logging/debugging wrappers.
Quoted 1 line
Is debugging level here the same as logging level?
Yes.
Quoted 7 lines
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in
netdevice.hthat can be set with Ethtool. I can see, for example, having themsg_enablenot in the private data as it is now but in the subsystem or class structure for that device, such as in structnet_device. This could easily be exported through sysfs.
It would be nice. Unfortunately, it's only a nifty pipe-dream at the moment, unless some lucky volunteer would like to step forward. ;)
-pat
Quoted 9 lines · Patrick Mochel
Quoted 8 lines
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in
netdevice.hthat can be set with Ethtool. I can see, for example, having themsg_enablenot in the private data as it is now but in the subsystem or class structure for that device, such as in structnet_device. This could easily be exported through sysfs.
Quoted 3 lines
It would be nice. Unfortunately, it's only a nifty pipe-dream at the moment, unless some lucky volunteer would like to step forward. ;)
I guess my question is this:
Is the patch I posted useful enough to go into the kernel? I think it is. It introduces very little overhead, and provides most of the functionality that you guys are discussing. It does use sysctl, and not sysfs but does that really matter?
mh
Signature · 1 line
Wild Open Source Inc. [email protected]
Quoted 12 lines · Martin Hicks
Quoted 10 lines · Patrick Mochel
Quoted 7 lines
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in
netdevice.hthat can be set with Ethtool. I can see, for example, having themsg_enablenot in the private data as it is now but in the subsystem or class structure for that device, such as in structnet_device. This could easily be exported through sysfs.It would be nice. Unfortunately, it's only a nifty pipe-dream at the moment, unless some lucky volunteer would like to step forward. ;)
Quoted 6 lines
I guess my question is this:
Is the patch I posted useful enough to go into the kernel? I think it is. It introduces very little overhead, and provides most of the functionality that you guys are discussing. It does use sysctl, and not sysfs but does that really matter?
I would rather not see the filtering applied to printk specifically like you've done it. I think this is still another stop gap measure for buffer overruns. I would like to see for:
1) Buffer overruns - a mechanism that wouldn't hit a buffer overrun, say a relayfs implementation of printk that could be easily configured in, or a mechanism that knows/reports when a overrun has happened like the Linux event logging project.
For relayfs, please see: http://www.opersys.com/relayfs/index.html
For event logging, please see: http://evlog.sourceforge.net/
2) Message filtering - a mechanism above printk that allows filtering on the fly and built into the new device model. Such a mechanism as Patrick described that could be put into the dev_* macros in device.h.
Thanks,
Dan
Quoted 1 line
mh
Quoted 21 lines · Daniel Stekloff
Quoted 12 lines · Martin Hicks
Quoted 10 lines · Patrick Mochel
Quoted 7 lines
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in
netdevice.hthat can be set with Ethtool. I can see, for example, having themsg_enablenot in the private data as it is now but in the subsystem or class structure for that device, such as in structnet_device. This could easily be exported through sysfs.It would be nice. Unfortunately, it's only a nifty pipe-dream at the moment, unless some lucky volunteer would like to step forward. ;)
Quoted 6 lines
I guess my question is this:
Is the patch I posted useful enough to go into the kernel? I think it is. It introduces very little overhead, and provides most of the functionality that you guys are discussing. It does use sysctl, and not sysfs but does that really matter?
Quoted 8 lines
I would rather not see the filtering applied to printk specifically like you've done it. I think this is still another stop gap measure for buffer overruns. I would like to see for:
1) Buffer overruns - a mechanism that wouldn't hit a buffer overrun, say a relayfs implementation of printk that could be easily configured in, or a mechanism that knows/reports when a overrun has happened like the Linux event logging project.
I don't think relayfs solves the problem either. This just adds an extra dependency for yet another pseudo-filesystem. printk is something that needs to "just work" even if the kernel is in the midst of crashing. Adding the extra complexity of all printk going out through a filesystem/buffer layer is not desirable, IMHO.
It seems that the relayfs solution for buffer overflows in the printk buffer is to just make lots of buffers. I really want to be able to turn off prink logging for stuff I don't care about, without the complexity of having fifteen different logs to look in and changing how get get log info from the kernel to syslog.
Quoted 4 lines
2) Message filtering - a mechanism above printk that allows filtering on the fly and built into the new device model. Such a mechanism as Patrick described that could be put into the dev_* macros in
device.h.
I haven't looked into these features too much. Is every piece of hardware in a machine considered a device?
i.e., can messages from CPU probing, Memory, NUMA nodes, etc. be filtered separately while changing the logging level on these devices at runtime?
The dev_* printk macros are all, of course, resolved at runtime. How does one control these printk's at runtime?
mh
Signature · 1 line
Wild Open Source Inc. [email protected]
Quoted 5 lines · Martin Hicks
I don't think relayfs solves the problem either. This just adds an extra dependency for yet another pseudo-filesystem. printk is something that needs to "just work" even if the kernel is in the midst of crashing. Adding the extra complexity of all printk going out through a filesystem/buffer layer is not desirable, IMHO.
I beg to differ. There's a point where we've got to stop saying "oh, this buffering mechanism is special and it requires its own code." relayfs is there to provide a unified light-weight mechanism for transfering large amounts of data from the kernel to user space.
Quoted 5 lines
It seems that the relayfs solution for buffer overflows in the printk buffer is to just make lots of buffers. I really want to be able to turn off prink logging for stuff I don't care about, without the complexity of having fifteen different logs to look in and changing how get get log info from the kernel to syslog.
Again, as I said earlier, relayfs doesn't care about filtering. That's to the upper layers to take care of. It so happens that relayfs simplifies filtering by allowing the upper layers to mux their data using separate channels. In no way is anyone forced to do that, though. It's there if you need it, and if you need to simply have a is_this_message_logged() function, then so be it, but that's yours to implement.
As for buffer overflows and printk, automatically resizeable log buffers using a water-mark scheme are on the relayfs to-do list.
Karim
===================================================
Karim Yaghmour
[email protected]
Embedded and Real-Time Linux Expert
===================================================
Quoted 10 lines · Patrick Mochel
Quoted 3 lines
Would the debug level be for the entire subsystem? Do you think people would like to be able to set debug/logging level per driver or device, and not just subsystem?
I can see a use for doing per-object debug levels, but I'd rather not add the overhead to every object, especially when it would be used by a small minority of the populace.
Such a flag could easily be placed in the subsystem-specific object, and accessed through the logging/debugging wrappers.
I was thinking this as well, having the dev_* macros make the check for the current logging level. That way each call to the macros wouldn't have to check the flag but could be part of the added value the macros give us.
Quoted 12 lines
Quoted 1 line
Is debugging level here the same as logging level?
Yes.
Quoted 7 lines
I like the idea of having logging levels, which include debug, defined by subsystem. Each subsystem will have separate requirements for logging. Networking, for instance, already has the NETIF_MSG* levels defined in
netdevice.hthat can be set with Ethtool. I can see, for example, having themsg_enablenot in the private data as it is now but in the subsystem or class structure for that device, such as in structnet_device. This could easily be exported through sysfs.
Quoted 2 lines
It would be nice. Unfortunately, it's only a nifty pipe-dream at the moment, unless some lucky volunteer would like to step forward. ;)
This is where I was going back when I sent you the patch for the network device class. Unfortunately, I haven't returned to looking at it. Too busy banging my head against other things... <grin>
Quoted 22 lines · Patrick Mochel
Quoted 4 lines
I don't like the #define DEBUG approach. It's useless for users; it's a developer debug tool. It won't allow some support staff to ask users to enable module debugging (or subsystem debugging) and see what gets printed.
Agreed. Having a runtime-tweakable field would be very handy, and something that's been requested many times over.
Quoted 3 lines
Martin, you are ahead of my schedule, but I was planning to use sysfs to add a 'debug' flag/file that could be dynamically altered on a per-module basis.
Something I've pondered in the past is a per-subsystem (as in struct subsystem) debug field and log buffer. When the subsystem is registered, a sysfs 'debug' file is created, from which the user can set the noisiness level.
Quoted 1 line
From there, each subsystem can specify the size of a log buffer, which
would be allocated also when the subsystem is registered. Messages from the subsystem, and kobjects belonging to it, would be copied into the local log buffer.
Quoted 7 lines
Wrapper functions can be created, similar to the dev_* functions, which take a kobject as the first parameter. From this, the subsystem and log buffer, can be derived (or rather, passed to a lower-level helper).
This all falls under the 'gee-whiz-this-might-be-neat' category, and may inherently suck; I haven't tried it. Doing the core code is < 1 day's work, though there would be nothing that actually used it..
I'm not sure that this addresses the core problem that I'm trying to deal with. The problem is that machines with certain configurations (large number of CPUs, Nodes, or a bunch of SCSI and disks) display far too many messages to the console, resulting in the log buffer being overflowed. The method that I'm proposing simply allows you to decide what gets logged when a printk() happens, depending on the message's priority and which subsystem it originated from.
mh
Signature · 1 line
Wild Open Source Inc. [email protected]
Quoted 7 lines · Martin Hicks
I'm not sure that this addresses the core problem that I'm trying to deal with. The problem is that machines with certain configurations (large number of CPUs, Nodes, or a bunch of SCSI and disks) display far too many messages to the console, resulting in the log buffer being overflowed. The method that I'm proposing simply allows you to decide what gets logged when a
printk()happens, depending on the message's priority and which subsystem it originated from.
I'm not going to address the "filtering" aspect of the problem, but I would like to point out that this issue of printk overflowing and having multiple streams of printk is already solved by relayfs:
http://www.opersys.com/relayfs/
With relayfs, one could easily have multi-channel printks (e.g. one for each "subsystem" and a main one for important messages of all subsystems.) The advantages of relayfs are obvious:
- No more lost printks.
- A unified buffering scheme for all subsystems that need to send data to user-space.
- Lockless per-cpu buffering.
- etc.
We've already started playing around with printk on relayfs, though we don't have code to offer at this time.
In terms of init-time printk'ing with relayfs, this is the scheme I suggest:
- Change all statically allocated printk buffers to __initdata.
- Add a registration function in kernel/printk.c which is called during initialization.
- Said function:
1) Allocates relayfs channel(s)
2) Atomically copies existing init-time data to channel
3) Starts using relayfs channel for all future transfers
That's it. Thereafter, all statically allocated printk buffers are dropped and all buffer management is left to relayfs.
[The filtering aspect is not taken care of by relayfs because it is not part of its "mandate". relayfs only aims at providing a very reliable lightweight high-speed data transfer mechanism for providing kernel data to user space. Higher-level mechanisms can easily use different relayfs channels to filter/mux data.]
Karim
===================================================
Karim Yaghmour
[email protected]
Embedded and Real-Time Linux Expert
===================================================
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
Quoted 1 line
"Pavel" == Pavel Machek <[email protected]> writes:
Pavel> Hi!
Quoted 6 lines
Quoted 6 lines
Killing the printk's means they are not around if you have an end user who is running into problems at boot time. Having a feature like this means they can default to 'off' then if a problem arises, whoever is doing the support can ask the user to try and enable printk's for say SCSI and get the input, without haven to rebuild the kernel from scratch.
Pavel> Well, I think we should first kill all crappy messages -- that Pavel> benefits everyone. I believe that if we kill all unneccessary Pavel> (carrying no information except perhaps copyright or Pavel> advertising) will help current problem a lot.
I agree that some messages can be eliminated, but not all of them. Even some of the ones you suggested might be valuable to keep, like the CPU flags. Generally this isn't a problem on a small box with 2 CPUs and 2 disks, but if you have 32 CPUs and 64 SCSI disks, the amount of data being printed becomes quite substantial.
So while I agree that it wouldn't hurt for us to eliminate some unncessary printk's, then I still think Martin's patch has a lot of merit.
Cheers,
Jes
Hello,
Here is the next iteration of this patch. This time it includes some documentation as well as a sysctl interface and a kernel command line option.
The patch is against 2.5-bk.
Any comments?
mh
Signature · 384 lines
Wild Open Source Inc. [email protected] # This is a BitKeeper generated patch for the following project: # Project Name: Linux kernel tree # This patch format is intended for GNU patch command version 2.5 or higher. # This patch includes the following deltas: # ChangeSet 1.1184 -> 1.1186 # include/linux/kernel.h 1.35 -> 1.36 # kernel/sysctl.c 1.41 -> 1.42 # include/linux/sysctl.h 1.42 -> 1.43 # kernel/printk.c 1.24 -> 1.25 # (new) -> 1.2 Documentation/printksubsystems.txt # # The following is the BitKeeper ChangeSet Log # -------------------------------------------- # 03/04/11 [email protected] 1.1185 # Add printk subsystems. # -------------------------------------------- # 03/04/11 [email protected] 1.1186 # Documentation updates. # -------------------------------------------- # diff -Nru a/Documentation/printksubsystems.txt b/Documentation/printksubsystems.txt --- /dev/null Wed Dec 31 16:00:00 1969 +++ b/Documentation/printksubsystems.txt Fri Apr 11 15:14:14 2003 @@ -0,0 +1,131 @@ + +Printk Subsystems +================= + +What and Why +------------ + +Printk subsystems were introduced to provide a mechanism to control +which messages are actually logged into the fixed length printk buffer. +As the Linux Kernel has been made to work on larger and larger +machines, the number of messages that are displayed on the console +during bootup have increased also. Certain subsystems are extremely +verbose and are easily able to overflow the fixed length printk buffer. + +Although simply making the printk buffer larger is possible, this is +just a stop gap solution. It was decided that there should be a +method to partition printk calls into different categories based +on which subsystem they originate from so they can be filtered at +run time. Please note that this depends on people using the KERN_* +printk priority system. + +Printk subsystems are a benefit to anyone but are particularly useful +for those who maintain or have customers who maintain (for example) +large SMP machines, large NUMA machines, or machines with many SCSI +controllers and disks. They allow you to control how verbose each +subsystem is during normal operation. If you run into a problem more +messages can be logged by increasing the loglevel for that particular +subsystem. The main point is that all of the printk strings are still +in the kernel, they just aren't placed into the printk log if they +aren't high enough priority. + + + +How to use it +------------- + +The way everyone currently calls printk is something like this: + +printk(KERN_NOTIFY "My message. Value = %d\n", foo); + +Another set of flags have been added that assign the message to a +particular printk subsystem. Currently these are: + +PRINTK_UNASS -- The default if no identifier is provided. +PRINTK_CORE -- For core messages (e.g., cpu messages, memory, etc.) +PRINTK_SCSI -- Messages related to SCSI. +PRINTK_NET -- Messages related to networking. +PRINTK_USB -- Messages related to USB. + +See include/linux/kernel.h for the latest list (just in case the above +isn't kept up-to-date). + +If the above printk was originating from somewhere in the network +hierarchy then the author should use: + +printk(PRINTK_NET KERN_NOTIFY "My message. Value = %d\n", foo); + + + +Configuration Parameters +------------------------ + +Each of the printk subsystems has a set of parameters associated with it. +These are the same values that are associated with the console loglevel +(/proc/sys/kernel/printk). There are 4 integer parameters: + +-Subsystem loglevel +-Default message loglevel +-Minimum console loglevel +-Default console loglevel + +The filtering is very simple. If the message that comes in is not assigned +to a printk subsystem it is assigned to PRINTK_UNASS. Then, if there +is no priority (KERN_*) assigned to the message, it is given a the +"default message loglevel" priority for the subsystem that the message +originated from. Finally, if the message loglevel value is less than the +subsystem loglevel value then the message is placed in the printk buffer. +It then makes it's way to other locations such as the console or syslog. + +Note that the console_printk's "default message loglevel" is no longer used +because if a message has no KERN_* flag prepended to the message then it is +assigned the printk subsystem's default message loglevel, not the +console_printk's default message loglevel. + +These printk subsystem values are configurable through the sysctl interface. +The sysctl files associated with this are located in +/proc/sys/kernel/printk_subsystem/ + +The subsystem loglevel is also configurable through a command line option. +The latter three values are only configurable through sysctl. If you +require a different initial value for any of the latter three values +you must recompile the kernel, changing the values of the prink_subsystem +array in kernel/printk.c + +To change the subsystem loglevel you simply provide a comma separated +list of values to the "printk_subsys" kernel command line option. To +use a default loglevel for a particular queue, assign the special value +"-1". + +E.g., To set the threshold for unassigned, core and scsi to 6, 5, 4 +(respectively) add the following to the kernel command line: + +printk_subsys=6,5,4 + +E.g., To set the loglevel of core and net to 5 add the following: + +printk_subsys=-1,5,-1,5 + + + +Adding a new printk subsystem +----------------------------- + +1) In include/linux/printk.h: + + - Add a new PRINTK_ define + - Modify LAST_PRINTK_SUBSYS + - Modify NUM_PRINTK_SUBSYSTEMS + +2) In kernel/printk.c modify the printk_subsystem initializer if you + would like different defaults for the new printk subsystem. + +3) In include/linux/sysctl.h add a new element to the enum with names + like PRINTK_SUBSYS_* that describes your new printk subsystem. + +4) In kernel/sysctl.c add a new entry to the printk_subsys_table. + +Recompile and you should have a new printk subsystem available for use. + +-- +Martin Hicks <[email protected]> -- April 10, 2003 diff -Nru a/include/linux/kernel.h b/include/linux/kernel.h --- a/include/linux/kernel.h Fri Apr 11 15:14:14 2003 +++ b/include/linux/kernel.h Fri Apr 11 15:14:14 2003 @@ -47,6 +47,17 @@ #define minimum_console_loglevel (console_printk[2]) #define default_console_loglevel (console_printk[3]) +/* Printk subsystem identifiers */ +#define PRINTK_UNASS "<A>" /* unassigned printk subsystem */ +#define PRINTK_CORE "<B>" /* from the core kernel */ +#define PRINTK_SCSI "<C>" /* from the SCSI subsystem */ +#define PRINTK_NET "<D>" /* from the Net subsystem */ +#define PRINTK_USB "<E>" /* from the USB subsystem */ + +#define FIRST_PRINTK_SUBSYS PRINTK_UNASS[1] +#define LAST_PRINTK_SUBSYS PRINTK_USB[1] +#define NUM_PRINTK_SUBSYSTEMS 5 + struct completion; #ifdef CONFIG_DEBUG_SPINLOCK_SLEEP diff -Nru a/include/linux/sysctl.h b/include/linux/sysctl.h --- a/include/linux/sysctl.h Fri Apr 11 15:14:14 2003 +++ b/include/linux/sysctl.h Fri Apr 11 15:14:14 2003 @@ -130,6 +130,7 @@ KERN_PIDMAX=55, /* int: PID # limit */ KERN_CORE_PATTERN=56, /* string: pattern for core-file names */ KERN_PANIC_ON_OOPS=57, /* int: whether we will panic on an oops */ + KERN_PRINTK_SUBSYS=58, /* intvec: controls printk subsystem log levels */ }; @@ -190,6 +191,16 @@ RANDOM_WRITE_THRESH=4, RANDOM_BOOT_ID=5, RANDOM_UUID=6 +}; + +/* /proc/sys/kernel/prink_subsystem */ +enum +{ + PRINTK_SUBSYS_UNASS=1, + PRINTK_SUBSYS_CORE=2, + PRINTK_SUBSYS_SCSI=3, + PRINTK_SUBSYS_NET=4, + PRINTK_SUBSYS_USB=5, }; /* /proc/sys/bus/isa */ diff -Nru a/kernel/printk.c b/kernel/printk.c --- a/kernel/printk.c Fri Apr 11 15:14:14 2003 +++ b/kernel/printk.c Fri Apr 11 15:14:14 2003 @@ -42,6 +42,9 @@ #define MINIMUM_CONSOLE_LOGLEVEL 1 /* Minimum loglevel we let people use */ #define DEFAULT_CONSOLE_LOGLEVEL 7 /* anything MORE serious than KERN_DEBUG */ +#define MINIMUM_SUBSYS_LOGLEVEL 1 +#define DEFAULT_SUBSYS_LOGLEVEL 8 + DECLARE_WAIT_QUEUE_HEAD(log_wait); int console_printk[4] = { @@ -51,6 +54,19 @@ DEFAULT_CONSOLE_LOGLEVEL, /* default_console_loglevel */ }; +/* [][0] == subsystem log level + * [][1] == default message loglevel + * [][2] == minimum subsystem loglevel + * [][3] == default subsystem loglevel */ +int printk_subsystem[NUM_PRINTK_SUBSYSTEMS][4] = { + [0 ... NUM_PRINTK_SUBSYSTEMS-1] = { + DEFAULT_SUBSYS_LOGLEVEL, + DEFAULT_MESSAGE_LOGLEVEL, + MINIMUM_SUBSYS_LOGLEVEL, + DEFAULT_SUBSYS_LOGLEVEL + } +}; + int oops_in_progress; /* @@ -141,6 +157,27 @@ __setup("console=", console_setup); + +/* + * Process the command line arguments for the printk subsystems. + */ +static int __init printk_subsys_setup(char *str) +{ + int i, ret, val; + + for (i = 0; i < NUM_PRINTK_SUBSYSTEMS; i++) { + ret = get_option(&str, &val); + if (!ret) + break; + if (val >= 0 && val <= 8) + printk_subsystem[i][0] = val; + } + + return 1; +} + +__setup("printk_subsys=", printk_subsys_setup); + /* * Commands to do_syslog: * @@ -390,10 +427,11 @@ { va_list args; unsigned long flags; - int printed_len; + int printed_len, msg_log_level, msg_subsystem, i; char *p; static char printk_buf[1024]; - static int log_level_unknown = 1; + static int begin_message = 1; + if (oops_in_progress) { /* If a crash is occurring, make sure we can't deadlock */ @@ -409,23 +447,45 @@ va_start(args, fmt); printed_len = vsnprintf(printk_buf, sizeof(printk_buf), fmt, args); va_end(args); - + /* - * Copy the output into log_buf. If the caller didn't provide - * appropriate log level tags, we insert them here + * Copy the output into log_buf. */ - for (p = printk_buf; *p; p++) { - if (log_level_unknown) { - if (p[0] != '<' || p[1] < '0' || p[1] > '7' || p[2] != '>') { + p = printk_buf; + while (*p) { + if (begin_message) { + /* Figure out if there is zero, one or two flags */ + msg_log_level = -1; + msg_subsystem = 0; /* A - Unassigned */ + for (i = 0; i < 2; i++) { + if (p[0] == '<' && p[2] == '>') { + if (p[1] >= '0' && p[1] <= '7') + msg_log_level = p[1] - '0'; + if (p[1] >= FIRST_PRINTK_SUBSYS && + p[1] <= LAST_PRINTK_SUBSYS) + msg_subsystem = p[1] - FIRST_PRINTK_SUBSYS; + } else + break; + p+=3; + } + + /* Decide if we print this message at all */ + if (msg_log_level == -1) + msg_log_level = printk_subsystem[msg_subsystem][1]; + + if (msg_log_level < printk_subsystem[msg_subsystem][0]) { + begin_message = 0; emit_log_char('<'); - emit_log_char(default_message_loglevel + '0'); + emit_log_char(msg_log_level + '0'); emit_log_char('>'); + } else { // Get out of this loop. Don't log anything. + break; } - log_level_unknown = 0; } emit_log_char(*p); if (*p == '\n') - log_level_unknown = 1; + begin_message = 1; + p++; } if (!cpu_online(smp_processor_id())) { diff -Nru a/kernel/sysctl.c b/kernel/sysctl.c --- a/kernel/sysctl.c Fri Apr 11 15:14:14 2003 +++ b/kernel/sysctl.c Fri Apr 11 15:14:14 2003 @@ -57,6 +57,7 @@ extern int cad_pid; extern int pid_max; extern int sysctl_lower_zone_protection; +extern int printk_subsystem[][4]; /* this is needed for the proc_dointvec_minmax for [fs_]overflow UID and GID */ static int maxolduid = 65535; @@ -122,6 +123,7 @@ static ctl_table debug_table[]; static ctl_table dev_table[]; extern ctl_table random_table[]; +static ctl_table printk_subsys_table[]; /* /proc declarations: */ @@ -265,6 +267,7 @@ 0600, NULL, &proc_dointvec}, {KERN_PANIC_ON_OOPS,"panic_on_oops", &panic_on_oops,sizeof(int),0644,NULL,&proc_dointvec}, + {KERN_PRINTK_SUBSYS, "printk_subsystem", NULL, 0, 0555, printk_subsys_table}, {0} }; @@ -363,6 +366,20 @@ static ctl_table dev_table[] = { {0} }; + +static ctl_table printk_subsys_table[] = { + {PRINTK_SUBSYS_UNASS, "unassigned", printk_subsystem[0], 4*sizeof(int), + 0644, NULL, &proc_dointvec}, + {PRINTK_SUBSYS_CORE, "core", printk_subsystem[1], 4*sizeof(int), + 0644, NULL, &proc_dointvec}, + {PRINTK_SUBSYS_SCSI, "scsi", printk_subsystem[2], 4*sizeof(int), + 0644, NULL, &proc_dointvec}, + {PRINTK_SUBSYS_NET, "net", printk_subsystem[3], 4*sizeof(int), + 0644, NULL, &proc_dointvec}, + {PRINTK_SUBSYS_USB, "usb", printk_subsystem[4], 4*sizeof(int), + 0644, NULL, &proc_dointvec}, + {0} +}; extern void init_irq_proc (void);