dynamic_printk: new feature

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

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?

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?

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 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

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.

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.

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

thanks,

-Jason

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.

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.

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.

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

Would it be accepted though?

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

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.

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

From: Andy Walls <[email protected]>

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

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

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

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.

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