dynamic debug

dynamic debug

[Johannes Berg]

Joe, Jim, Jason,

Joe's conversion of mac80211 to pr_debug() was pretty much a disaster,
now people have to first select what they want in Kconfig, and then
still enable dynamic debug in debugfs... That doesn't make any sense at
all, and requires teaching everybody new tricks, so I'm basically
reverting it for now in favour of pr_info() instead of pr_debug().

I'd actually not mind using pr_debug() if it meant we could get rid of
all the Kconfig symbols, but that's not possible.

The biggest problem here really is that the dynamic debug infrastructure
lets us enable messages at runtime, which is great, but the granularity
is useless since you only have these possibilities:
 * module name
 * file name
 * function name
 * line number
 * format string match

The module is obviously way too broad for most modules, and the others
are way too fine-grained.

To actually make it useful, there needs to be a "key" that you can use,
e.g. in mac80211 I could do

DECLARE_DYNDBG_KEY(ps);

and in some C file, I'd have to do the matching DEFINE_DYNDBG_KEY(ps),
similar to how tracing works.

Then, I would get

 * an inline function ps_dbg()
 * a macro "is_ps_debug" or so, so that you can use the enable/disable
   bit of this key, say to create wrappers like netdev_ps_dbg
   (probably needs to be a macro if it uses jump labels which it should
   I think)

and probably some other magic. The DEFINE_ macro would create some
structure, and that would go into some special module section, so that
then the dyn debug core can collect all these keys and allow us to do
something like

 echo mac80211:ps > dynamic_debug/control

That would actually allow us to get rid of all our own Kconfig symbols
and would allow a lot of drivers to get rid of their own infrastructure
for enabling/disabling certain "log levels" etc...

johannes

Re: dynamic debug

[Joe Perches]

On Fri, 2012-06-22 at 14:23 +0200, Johannes Berg wrote:
> Joe, Jim, Jason,
> 
> Joe's conversion of mac80211 to pr_debug() was pretty much a disaster,

First I've heard of it.

> now people have to first select what they want in Kconfig, and then
> still enable dynamic debug in debugfs...

This doesn't parse for me.
Please illustrate further.

>  That doesn't make any sense at
> all, and requires teaching everybody new tricks, so I'm basically
> reverting it for now in favour of pr_info() instead of pr_debug().

Why not just add #define DEBUG?

> I'd actually not mind using pr_debug() if it meant we could get rid of
> all the Kconfig symbols, but that's not possible.
> 
> The biggest problem here really is that the dynamic debug infrastructure
> lets us enable messages at runtime, which is great, but the granularity
> is useless since you only have these possibilities:

What I think dyn_debug needs is a mask/level control.
so you can do the equivalent of
	echo val > /somewhere
to control the tested against value

see: https://lkml.org/lkml/2011/8/21/128

Re: dynamic debug

[Johannes Berg]

On Fri, 2012-06-22 at 07:26 -0700, Joe Perches wrote:
> On Fri, 2012-06-22 at 14:23 +0200, Johannes Berg wrote:
> > Joe, Jim, Jason,
> > 
> > Joe's conversion of mac80211 to pr_debug() was pretty much a disaster,
> 
> First I've heard of it.

Well I guess you didn't have the pleasure of having to work with bug
reporters whose mac80211 messages suddenly completely disappeared ...

> > now people have to first select what they want in Kconfig, and then
> > still enable dynamic debug in debugfs...
> 
> This doesn't parse for me.
> Please illustrate further.

mac80211 has Kconfig selectors for a bunch of verbose debug options. Now
you turn them on, but the messages still don't occur, you have to also
enable dynamic debug. This extra step not make any sense to most people
and I agree -- having fine-grained compile-time options only to have to
enable a coarse-grained runtime option seems odd.

I'd much rather have a coarse-grained Kconfig option (for those people
who want to save the binary size) and then allow enabling pieces at
runtime -- see below.

> >  That doesn't make any sense at
> > all, and requires teaching everybody new tricks, so I'm basically
> > reverting it for now in favour of pr_info() instead of pr_debug().
> 
> Why not just add #define DEBUG?

I guess that works? Doesn't really make a difference though. In reality,
most messages should be KERN_INFO anyway, so for those that aren't
hidden behind extra Kconfig options, we should use pr_info(). For those
that are, it doesn't really make a difference?

> > I'd actually not mind using pr_debug() if it meant we could get rid of
> > all the Kconfig symbols, but that's not possible.
> > 
> > The biggest problem here really is that the dynamic debug infrastructure
> > lets us enable messages at runtime, which is great, but the granularity
> > is useless since you only have these possibilities:
> 
> What I think dyn_debug needs is a mask/level control.
> so you can do the equivalent of
> 	echo val > /somewhere
> to control the tested against value
> 
> see: https://lkml.org/lkml/2011/8/21/128

Yeah, that sounds about right. I think having names rather than bitmaps
would be more user-friendly, and with a bit of magic it could also use
jump_level instead of "var & bit" which is even more efficient.

johannes

Re: dynamic debug

[Joe Perches]

On Fri, 2012-06-22 at 16:34 +0200, Johannes Berg wrote:
> On Fri, 2012-06-22 at 07:26 -0700, Joe Perches wrote:
> > On Fri, 2012-06-22 at 14:23 +0200, Johannes Berg wrote:
> > > Joe, Jim, Jason,
> > > 
> > > Joe's conversion of mac80211 to pr_debug() was pretty much a disaster,
> > 
> > First I've heard of it.
> 
> Well I guess you didn't have the pleasure of having to work with bug
> reporters whose mac80211 messages suddenly completely disappeared ...

Nor it seems the pleasure of interaction with a maintainer
that forwards notices like this.

> > > now people have to first select what they want in Kconfig, and then
> > > still enable dynamic debug in debugfs...
> > 
> > This doesn't parse for me.
> > Please illustrate further.
> 
> mac80211 has Kconfig selectors for a bunch of verbose debug options. Now
> you turn them on, but the messages still don't occur, you have to also
> enable dynamic debug. This extra step not make any sense to most people
> and I agree -- having fine-grained compile-time options only to have to
> enable a coarse-grained runtime option seems odd.
> 
> I'd much rather have a coarse-grained Kconfig option (for those people
> who want to save the binary size) and then allow enabling pieces at
> runtime -- see below.
> 
> > >  That doesn't make any sense at
> > > all, and requires teaching everybody new tricks, so I'm basically
> > > reverting it for now in favour of pr_info() instead of pr_debug().
> > 
> > Why not just add #define DEBUG?
> 
> I guess that works?

That works.

>  Doesn't really make a difference though. In reality,
> most messages should be KERN_INFO anyway, so for those that aren't
> hidden behind extra Kconfig options, we should use pr_info().

Why?  Aren't these then possibly some mixture of errors or
notices or info level messages?

Re: dynamic debug

[Johannes Berg]

On Fri, 2012-06-22 at 07:41 -0700, Joe Perches wrote:

> > > > Joe's conversion of mac80211 to pr_debug() was pretty much a disaster,
> > > 
> > > First I've heard of it.
> > 
> > Well I guess you didn't have the pleasure of having to work with bug
> > reporters whose mac80211 messages suddenly completely disappeared ...
> 
> Nor it seems the pleasure of interaction with a maintainer
> that forwards notices like this.

I told you before that I didn't like you wholesale converting it. I
might have been more open to it if you'd actually let me work on it and
convert some printk(KERN_DEBUG, ... to pr_info(). Now I'm stuck in a
situation where a lot of people will no longer see the messages they
expect, and I have to walk them through new, unexpected steps to make
them show up if I'm debugging a problem.

And heck, it's not even predictable since dynamic debug could be turned
on or off too.

> >  Doesn't really make a difference though. In reality,
> > most messages should be KERN_INFO anyway, so for those that aren't
> > hidden behind extra Kconfig options, we should use pr_info().
> 
> Why?  Aren't these then possibly some mixture of errors or
> notices or info level messages?

Yes, I believe that they are, but since you assumed that all KERN_DEBUG
messages were essentially useless by converting them to off-by-default,
I'm now changing it to assuming they're useful by converting them to
pr_info, we can change them back later.

However, most messages that aren't hidden behind Kconfig options are
actually useful, even if they were printed at KERN_DEBUG before.

johannes

Re: dynamic debug

[Johannes Berg]

On Fri, 2012-06-22 at 07:41 -0700, Joe Perches wrote:

> > > >  That doesn't make any sense at
> > > > all, and requires teaching everybody new tricks, so I'm basically
> > > > reverting it for now in favour of pr_info() instead of pr_debug().
> > > 
> > > Why not just add #define DEBUG?
> > 
> > I guess that works?
> 
> That works.

Are you sure? It doesn't really seem to work ...

#if defined(CONFIG_DYNAMIC_DEBUG)
/* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
#define pr_debug(fmt, ...) \
        dynamic_pr_debug(fmt, ##__VA_ARGS__)
#elif defined(DEBUG)
#define pr_debug(fmt, ...) \
        printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)



So basically, if you have CONFIG_DYNAMIC_DEBUG, you *still* need to
enable it with the dynamic debug framework, right?


johannes

Re: dynamic debug

[Joe Perches]

On Fri, 2012-06-22 at 17:21 +0200, Johannes Berg wrote:
> On Fri, 2012-06-22 at 07:41 -0700, Joe Perches wrote:
> 
> > > > >  That doesn't make any sense at
> > > > > all, and requires teaching everybody new tricks, so I'm basically
> > > > > reverting it for now in favour of pr_info() instead of pr_debug().
> > > > 
> > > > Why not just add #define DEBUG?
> > > 
> > > I guess that works?
> > 
> > That works.
> 
> Are you sure? It doesn't really seem to work ...
> 
> #if defined(CONFIG_DYNAMIC_DEBUG)
> /* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
> #define pr_debug(fmt, ...) \
>         dynamic_pr_debug(fmt, ##__VA_ARGS__)
> #elif defined(DEBUG)
> #define pr_debug(fmt, ...) \
>         printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> 
> 
> 
> So basically, if you have CONFIG_DYNAMIC_DEBUG, you *still* need to
> enable it with the dynamic debug framework, right?

No.

In dynamic_debug.h, there's a mechanism to enable all
dynamic_pr_debug lines when DEBUG is #defined

#if defined DEBUG
#define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
#else
#define _DPRINTK_FLAGS_DEFAULT 0
#endif

Re: dynamic debug

[Johannes Berg]

On Fri, 2012-06-22 at 08:32 -0700, Joe Perches wrote:

> > Are you sure? It doesn't really seem to work ...
> > 
> > #if defined(CONFIG_DYNAMIC_DEBUG)
> > /* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
> > #define pr_debug(fmt, ...) \
> >         dynamic_pr_debug(fmt, ##__VA_ARGS__)
> > #elif defined(DEBUG)
> > #define pr_debug(fmt, ...) \
> >         printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> > 
> > 
> > 
> > So basically, if you have CONFIG_DYNAMIC_DEBUG, you *still* need to
> > enable it with the dynamic debug framework, right?
> 
> No.
> 
> In dynamic_debug.h, there's a mechanism to enable all
> dynamic_pr_debug lines when DEBUG is #defined
> 
> #if defined DEBUG
> #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
> #else
> #define _DPRINTK_FLAGS_DEFAULT 0
> #endif

Hah. Too much indirection I guess.

Thanks.

I'll respin my patches.

johannes

Re: dynamic debug

[Johannes Berg]

On Fri, 2012-06-22 at 08:32 -0700, Joe Perches wrote:

> > Are you sure? It doesn't really seem to work ...
> > 
> > #if defined(CONFIG_DYNAMIC_DEBUG)
> > /* dynamic_pr_debug() uses pr_fmt() internally so we don't need it here */
> > #define pr_debug(fmt, ...) \
> >         dynamic_pr_debug(fmt, ##__VA_ARGS__)
> > #elif defined(DEBUG)
> > #define pr_debug(fmt, ...) \
> >         printk(KERN_DEBUG pr_fmt(fmt), ##__VA_ARGS__)
> > 
> > 
> > 
> > So basically, if you have CONFIG_DYNAMIC_DEBUG, you *still* need to
> > enable it with the dynamic debug framework, right?
> 
> No.
> 
> In dynamic_debug.h, there's a mechanism to enable all
> dynamic_pr_debug lines when DEBUG is #defined
> 
> #if defined DEBUG
> #define _DPRINTK_FLAGS_DEFAULT _DPRINTK_FLAGS_PRINT
> #else
> #define _DPRINTK_FLAGS_DEFAULT 0
> #endif

Gee, ok, so this was only added in 3.3 ...

johannes