[patch 0/3] dynamic_printk: new feature

[patch 0/3] dynamic_printk: new feature

[Jason Baron]

hi,

Add the ability to dynamically enable/disable pr_debug()/dev_dbg() in the
kernel. Yes, these calls could be converted to printk(KERN_DEBUG), but there
are enough to cause overhead. Additionally, the logs become difficult to read.
This work is dependent on the CONFIG_DYNAMIC_PRINTK, which when enabled adds
about 1% to the text size of the kernel. Mssages can be dynamically controlled
by module:

echo "add module_name" > /sys/kernel/debug/dynamic_printk/modules
echo "remove module_name" > /sys/kernel/debug/dynamic_printk/modules

There is also a special 'all' value that turns on all the debugging messages.
This 'all' value can also be enabled during boot by passing 'dynamic_printk' on
the kernel command line.

I hope that these patches are useful for people writing new kernel code, for
system debugging and testing. In enabling the 'all' feature on the kernel I was
running i got a bunch of messages...they are pretty interesting in and of
themselves...they could point to error conditions, or further optimizations.

If this patch is accepted, i'd like to convert the myriad 'debug' printks -
DEBUGP(), dprintk(), to a standard format, either pr_debug() or dev_dbg(), to
hook into this mechanism.

thanks,

-Jason

Re: [patch 0/3] dynamic_printk: new feature

[Andrew Morton]

On Tue, 29 Apr 2008 14:39:35 -0400
Jason Baron <jbaron@redhat.com> wrote:

> hi,
> 
> Add the ability to dynamically enable/disable pr_debug()/dev_dbg() in the
> kernel. Yes, these calls could be converted to printk(KERN_DEBUG), but there
> are enough to cause overhead. Additionally, the logs become difficult to read.
> This work is dependent on the CONFIG_DYNAMIC_PRINTK, which when enabled adds
> about 1% to the text size of the kernel. Mssages can be dynamically controlled
> by module:
> 
> echo "add module_name" > /sys/kernel/debug/dynamic_printk/modules
> echo "remove module_name" > /sys/kernel/debug/dynamic_printk/modules
> 
> There is also a special 'all' value that turns on all the debugging messages.
> This 'all' value can also be enabled during boot by passing 'dynamic_printk' on
> the kernel command line.
> 
> I hope that these patches are useful for people writing new kernel code, for
> system debugging and testing. In enabling the 'all' feature on the kernel I was
> running i got a bunch of messages...they are pretty interesting in and of
> themselves...they could point to error conditions, or further optimizations.
> 
> 

Without having looked at the implementation yet...

We should have done this ten years ago :(

We're now in the situation where numerous different subsystems have
implemented private mechnisms for tuning their printk verbosity levels.

Have you taken a look across the tree with a view to converting some of
them?  If so, how sizeable/messy/feasible would that task be?



The situation is far, far worse with compile-time debugging selection.  We
have over two hundred different implementations of dprintk!

Have you considered the feasibility of ploddingly converting each of those
drivers, one at a time over to the new infrastructure?  Because that's what
we should do, I'm afraid.

An implication of this is that once a dprintk-using driver has been
converted over to use your new infrastructure, it should still be possible
to fully disable the debugging at compile time.  Do you handle that?

> If this patch is accepted, i'd like to convert the myriad 'debug' printks -
> DEBUGP(), dprintk(), to a standard format, either pr_debug() or dev_dbg(), to
> hook into this mechanism.

ah, so you have looked.  How nasty will it be?


A couple of things:

- Your design handles a boolean on/off control.  But some code implements
  a verbosity-level control.  Thoughts on this?

- I expect that other code implements a field-selector control, for the
  lack of a better term: an greater-than-one number of separate boolean
  controls.  How to handle this?


Thanks for working on this.  If we can get this underway and get a decent
amount of conversion done, it will be a huuuuuuuuuuuuge cleanup to the
kernel.  But we will need to design it carefully first.

I guess one good testcase would be ALSA.  It has pretty fancy debugging
control (which I apparently have never been smart enough to understand). 
Did you take a look at what they're doing, with a view to
can-we-switch-ALSA-to-use-this?

Re: [patch 0/3] dynamic_printk: new feature

[Joe Perches]

On Wed, 2008-04-30 at 12:45 -0700, Andrew Morton wrote: 
> Have you taken a look across the tree with a view to converting some of
> them?  If so, how sizeable/messy/feasible would that task be?

I've done that.
There have been many attempts at this.

http://lkml.org/lkml/2007/9/22/110
http://lkml.org/lkml/2007/9/27/274

It's not particularly difficult.
It's just a few scripts and some message massaging.
It's also a lot of what some call unnecessary churn.
I think it useful though.

I also have scripts to remove file/function/line numbers
from messages and use a generic method to integrate and
optionally display them via pr_<level>.

akin to:

#define pr_info(fmt, arg...) \
do { \
	char prefix[MAX_PREFIX_LEN]; \
	if (pr_enabled(prefix, sizeof(prefix), PR_INFO)) { \
		printk("%s" fmt, prefix, ##arg); \
	} \
} while (0)

where pr_enabled optionally formats KBUILD_MODNAME/__func__/__LINE__
and of course <level> to prefix with appropriate
CONFIG_PR_USE_MODNAME/FUNCTION/LINE controls for
embedded size minimization when kallsyms is not
available.

pr_enabled can also be #defined to 0 to eliminate
the strings and printk calls.

> - Your design handles a boolean on/off control.  But some code implements
>   a verbosity-level control.  Thoughts on this?

It seems there is still resistance to even ethtool style
msglevel.

Extending Jason's approach to test a module message level
seems simple enough and could/should be universal.

I think that message rate limiting should also be done here.
Also I think this facility would help in localization.

> But we will need to design it carefully first.

Agreed.  The "useless churn!" cries need also to be ignored
or at least damped down.

I'd also like to consider including mechanisms to
consolidate what are now consecutive calls to printk
to print partial lines into block start/end calls.
Perhaps pr_start, pr_cont, pr_end.

These calls should never fail under memory pressure.

Vegard Nossum had what I think is a good idea to
include a pointer to a printk reassembly buffer
in struct task_struct.

That could remove the need to pass round a pointer
when using block style printk calls.  

> I guess one good testcase would be ALSA.  It has pretty fancy debugging
> control (which I apparently have never been smart enough to understand). 
> Did you take a look at what they're doing, with a view to
> can-we-switch-ALSA-to-use-this?

If you're referring to include/sound/core.h, it seems simple enough.

Would it be accepted though?

Re: [patch 0/3] dynamic_printk: new feature

[Jason Baron]

On Wed, Apr 30, 2008 at 12:45:06PM -0700, Andrew Morton wrote:
> We're now in the situation where numerous different subsystems have
> implemented private mechnisms for tuning their printk verbosity levels.
> 
> Have you taken a look across the tree with a view to converting some of
> them?  If so, how sizeable/messy/feasible would that task be?
> 
> 

i really only focused on pr_debug()/dev_dbg(), with an eye towards
widening the scope as we go...but I agree that it would be nice to
understand the scope for the start...i find ~5000 call sites to
dprintk(), which would be ideal candidates for this type of
infrastructure.

> 
> The situation is far, far worse with compile-time debugging selection.  We
> have over two hundred different implementations of dprintk!
> 
> Have you considered the feasibility of ploddingly converting each of those
> drivers, one at a time over to the new infrastructure?  Because that's what
> we should do, I'm afraid.
> 
> An implication of this is that once a dprintk-using driver has been
> converted over to use your new infrastructure, it should still be possible
> to fully disable the debugging at compile time.  Do you handle that?
> 

that's correct. the way i've handled this in the patch is:

if DEBUG 
	you get the current compiled in behavior per .c file
elif DYNAMIC_PRINTK
	you get the dynamic runtime configurable debugging
else
	its compiled out

> > If this patch is accepted, i'd like to convert the myriad 'debug' printks -
> > DEBUGP(), dprintk(), to a standard format, either pr_debug() or dev_dbg(), to
> > hook into this mechanism.
> 
> ah, so you have looked.  How nasty will it be?
> 
> 
> A couple of things:
> 
> - Your design handles a boolean on/off control.  But some code implements
>   a verbosity-level control.  Thoughts on this?
> 

right, i think though it could easily be extended to level control.
Basically the patch associates the on/off per KBUILD_MODNAME, however we
could also associate a level per KBUILD_MODNAME. This level could be set
either by the generic debugfs interface, via module parameters at module
load time, or in the the module __init sections as appropriate.


> - I expect that other code implements a field-selector control, for the
>   lack of a better term: an greater-than-one number of separate boolean
>   controls.  How to handle this?
> 
> 

hmmm...i think this is handled by having the driver call the conditions
in its scope and then call out to the generic infrastructure if the
conditions are met.

> Thanks for working on this.  If we can get this underway and get a decent
> amount of conversion done, it will be a huuuuuuuuuuuuge cleanup to the
> kernel.  But we will need to design it carefully first.
> 
> I guess one good testcase would be ALSA.  It has pretty fancy debugging
> control (which I apparently have never been smart enough to understand). 
> Did you take a look at what they're doing, with a view to
> can-we-switch-ALSA-to-use-this?
> 
> 

ok. i'll take a more detailed look at the pontentially wider scope of this change.

thanks,

-Jason

Re: [patch 0/3] dynamic_printk: new feature

[Greg KH]

First off, I agree with Andrew, this is a very welcome thing to do.  If
there's anything I can do to help this out, please let me know.

On Wed, Apr 30, 2008 at 05:01:50PM -0400, Jason Baron wrote:
> On Wed, Apr 30, 2008 at 12:45:06PM -0700, Andrew Morton wrote:
> > We're now in the situation where numerous different subsystems have
> > implemented private mechnisms for tuning their printk verbosity levels.
> > 
> > Have you taken a look across the tree with a view to converting some of
> > them?  If so, how sizeable/messy/feasible would that task be?
> > 
> > 
> 
> i really only focused on pr_debug()/dev_dbg(), with an eye towards
> widening the scope as we go...but I agree that it would be nice to
> understand the scope for the start...i find ~5000 call sites to
> dprintk(), which would be ideal candidates for this type of
> infrastructure.

That's a good first start :)

Lots of the existing printk() type wrappers can also use the dev_*
versions as well (like the ALSA ones for example.)  So it might be
easier to focus on the existing users of these two functions, and then
work to convert the other different variants over to the dev_printk ones
where possible and d_printk where not (you don't always have a struct
device to use at the moment, which is required by dev_printk)

If you want to start with the USB core and drivers, I'll be glad to help
ensure those patches go in as well.

thanks,

greg k-h

Re: [patch 0/3] dynamic_printk: new feature

[Nick Andrew]

On Wed, Apr 30, 2008 at 12:45:06PM -0700, Andrew Morton wrote:
> > Add the ability to dynamically enable/disable pr_debug()/dev_dbg() in the
> > kernel.

Yes, that's the kind of thing I've been thinking about adding myself.

> > echo "add module_name" > /sys/kernel/debug/dynamic_printk/modules
> > echo "remove module_name" > /sys/kernel/debug/dynamic_printk/modules

How about not just debug messages but setting a loglevel for each module
(and/or subsystem?); kernel messages emitted beneath the loglevel value
to be discarded.

> We're now in the situation where numerous different subsystems have
> implemented private mechnisms for tuning their printk verbosity levels.

And it grows over time; just in the last week a patch came through to
V4L ...

	From: Andy Walls <awalls@radix.net>

	Replace the unconditional printk() messages with printk() messages that are
	enabled/disabled by a "debug" module parameter.

	[...]
	+#define dprintk(level, fmt, arg...)

> Have you considered the feasibility of ploddingly converting each of those
> drivers, one at a time over to the new infrastructure?  Because that's what
> we should do, I'm afraid.

I can help with that.

Nick.
-- 
PGP Key ID = 0x418487E7                      http://www.nick-andrew.net/
PGP Key fingerprint = B3ED 6894 8E49 1770 C24A  67E3 6266 6EB9 4184 87E7