Improving or replacing snd_printk()

Improving or replacing snd_printk()

[Alan Stern]

Takashi:

Messages produced by snd_printk() aren't as informative as they could
be -- especially when CONFIG_SND_VERBOSE_PRINTK isn't enabled, which is
the case on most systems.

The routine uses printk() rather then dev_dbg(), dev_info(), or
dev_err().  As a result, the messages don't say what driver or device
is involved.  We just get something like:

[15919.883604] cannot submit urb (err = -18)

That's not much help to anybody.  If you didn't know what an urb was, 
you wouldn't even realize that this referred to a USB device.  And if 
you had multiple USB audio devices, you wouldn't know which one it 
referred to.

Has there been any thought of improving snd_printk(), or even better,
changing the call sites to use the dev_*() routines instead?

Alan Stern

Re: Improving or replacing snd_printk()

[Joe Perches]

On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
> Has there been any thought of improving snd_printk(), or even better,
> changing the call sites to use the dev_*() routines instead?

Perhaps better would be to add and use some combination of
type specific logging message functions/macros like:

void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)

allowing NULL as the type pointer when necessary/appropriate.

Re: Improving or replacing snd_printk()

[Alan Stern]

On Wed, 29 May 2013, Joe Perches wrote:

> On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
> > Has there been any thought of improving snd_printk(), or even better,
> > changing the call sites to use the dev_*() routines instead?
> 
> Perhaps better would be to add and use some combination of
> type specific logging message functions/macros like:
> 
> void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
> void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
> void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)
> 
> allowing NULL as the type pointer when necessary/appropriate.

Almost anything would be better than the current situation.  The only 
enhancement provided by CONFIG_SND_VERBOSE_PRINTK is to print the 
filename and line number, which is relatively unhelpful (unless there 
are multiple copies of the same message in several places).

Alan Stern

Re: [alsa-devel] Improving or replacing snd_printk()

[Jaroslav Kysela]

Date 30.5.2013 20:14, Alan Stern wrote:
> On Wed, 29 May 2013, Joe Perches wrote:
> 
>> On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
>>> Has there been any thought of improving snd_printk(), or even better,
>>> changing the call sites to use the dev_*() routines instead?
>>
>> Perhaps better would be to add and use some combination of
>> type specific logging message functions/macros like:
>>
>> void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
>> void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
>> void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)
>>
>> allowing NULL as the type pointer when necessary/appropriate.
> 
> Almost anything would be better than the current situation.  The only 
> enhancement provided by CONFIG_SND_VERBOSE_PRINTK is to print the 
> filename and line number, which is relatively unhelpful (unless there 
> are multiple copies of the same message in several places).

I don't think that it's useless to see the origin of the source message
from the first glance. It may be improved, of course, but adding more
and more functions with minor benefits is another step to another hell.

					Jaroslav

-- 
Jaroslav Kysela <perex@perex.cz>
Linux Kernel Sound Maintainer
ALSA Project; Red Hat, Inc.

Re: [alsa-devel] Improving or replacing snd_printk()

[Alan Stern]

On Thu, 30 May 2013, Jaroslav Kysela wrote:

> Date 30.5.2013 20:14, Alan Stern wrote:
> > On Wed, 29 May 2013, Joe Perches wrote:
> > 
> >> On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
> >>> Has there been any thought of improving snd_printk(), or even better,
> >>> changing the call sites to use the dev_*() routines instead?
> >>
> >> Perhaps better would be to add and use some combination of
> >> type specific logging message functions/macros like:
> >>
> >> void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
> >> void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
> >> void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)
> >>
> >> allowing NULL as the type pointer when necessary/appropriate.
> > 
> > Almost anything would be better than the current situation.  The only 
> > enhancement provided by CONFIG_SND_VERBOSE_PRINTK is to print the 
> > filename and line number, which is relatively unhelpful (unless there 
> > are multiple copies of the same message in several places).
> 
> I don't think that it's useless to see the origin of the source message
> from the first glance. It may be improved, of course, but adding more
> and more functions with minor benefits is another step to another hell.

Maybe so.  However, including the device and driver names in the log 
messages is a major benefit, not a minor one.

I'd be happy to have just a snd_<level> family of functions, with 
snd_printk and snd_printd deprecated.  Does anybody object?

Alan Stern

Re: [alsa-devel] Improving or replacing snd_printk()

[Joe Perches]

On Thu, 2013-05-30 at 15:43 -0400, Alan Stern wrote:
> On Thu, 30 May 2013, Jaroslav Kysela wrote:
> 
> > Date 30.5.2013 20:14, Alan Stern wrote:
> > > On Wed, 29 May 2013, Joe Perches wrote:
> > > 
> > >> On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
> > >>> Has there been any thought of improving snd_printk(), or even better,
> > >>> changing the call sites to use the dev_*() routines instead?
> > >>
> > >> Perhaps better would be to add and use some combination of
> > >> type specific logging message functions/macros like:
> > >>
> > >> void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
> > >> void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
> > >> void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)
> > >>
> > >> allowing NULL as the type pointer when necessary/appropriate.
> > > 
> > > Almost anything would be better than the current situation.  The only 
> > > enhancement provided by CONFIG_SND_VERBOSE_PRINTK is to print the 
> > > filename and line number, which is relatively unhelpful (unless there 
> > > are multiple copies of the same message in several places).
> > 
> > I don't think that it's useless to see the origin of the source message
> > from the first glance. It may be improved, of course, but adding more
> > and more functions with minor benefits is another step to another hell.
> 
> Maybe so.  However, including the device and driver names in the log 
> messages is a major benefit, not a minor one.
> 
> I'd be happy to have just a snd_<level> family of functions, with 
> snd_printk and snd_printd deprecated.  Does anybody object?

Not me.

I think the benefit of the consolidated family of
macros/functions is avoiding the visual clutter of:

	dev_<level>(&pointer->deref->deref->dev,
		    fmt, ...)

and potential uses of

	if (pointer->deref && pointer->deref->deref)
		dev_<level>(etc...)
	else
		pr_<level>("unregistered dev: " fmt, ...)

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Thu, 30 May 2013 20:49:09 +0200,
Jaroslav Kysela wrote:
> 
> Date 30.5.2013 20:14, Alan Stern wrote:
> > On Wed, 29 May 2013, Joe Perches wrote:
> > 
> >> On Wed, 2013-05-29 at 15:27 -0400, Alan Stern wrote:
> >>> Has there been any thought of improving snd_printk(), or even better,
> >>> changing the call sites to use the dev_*() routines instead?
> >>
> >> Perhaps better would be to add and use some combination of
> >> type specific logging message functions/macros like:
> >>
> >> void snd_<level>(const struct snd_device *dev, const char *fmt, ...)
> >> void snd_card_<level>(const struct snd_card *card, const char *fmt, ...)
> >> void snd_ac97_<level>(const struct snd_ac97 *ac97, const char *fmt, ...)
> >>
> >> allowing NULL as the type pointer when necessary/appropriate.
> > 
> > Almost anything would be better than the current situation.  The only 
> > enhancement provided by CONFIG_SND_VERBOSE_PRINTK is to print the 
> > filename and line number, which is relatively unhelpful (unless there 
> > are multiple copies of the same message in several places).
> 
> I don't think that it's useless to see the origin of the source message
> from the first glance. It may be improved, of course, but adding more
> and more functions with minor benefits is another step to another hell.

Agreed.  Especially the debug messages would be better to be precise.

The problem is that many messages with snd_printk() like below have
too little information without CONFIG_SND_VERBOSE_PRINTK:
	snd_printk(KERN_ERR "cannot submit urb (err = %d)\n", err);

It's a problem only with snd_printk(), as CONFIG_SND_VERBOSE_PRINTK
influences on the behavior of snd_printk() and not on the debug prints
with snd_printd() & co.

Hence, the goal we should achieve is rather to drop
CONFIG_SND_VERBOSE_PRINTK.  *This* is the useless thing.

Meanwhile, many snd_printk() messages might start looking annoying
with the extra information.  If so, such lines should be replaced with
the standard prints like dev_*().  I think almost all snd_printk()
like below are better replaced with standard ones.

So, alternatively, we can begin with replacing some snd_printk() with
the standard functions, then dropping CONFIG_SND_VERBOSE_PRINTK.

I think most of snd_printd() and snd_printdd() can be kept as is.
These are just debug messages, after all.

Thoughts?


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Joe Perches]

On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> It's a problem only with snd_printk(), as CONFIG_SND_VERBOSE_PRINTK
> influences on the behavior of snd_printk() and not on the debug prints
> with snd_printd() & co.

Are you're perhaps confused about how CONFIG_SND_VERBOSE_PRINTK
works with or varies between snd_printd and snd_printk?

#if defined(CONFIG_SND_DEBUG) || defined(CONFIG_SND_VERBOSE_PRINTK)
__printf(4, 5)
void __snd_printk(unsigned int level, const char *file, int line,
		  const char *format, ...);

...

#define snd_printk(fmt, args...) \
	__snd_printk(0, __FILE__, __LINE__, fmt, ##args)

#ifdef CONFIG_SND_DEBUG
[...]
#define snd_printd(fmt, args...) \
	__snd_printk(1, __FILE__, __LINE__, fmt, ##args)

I don't see a difference.

> Hence, the goal we should achieve is rather to drop
> CONFIG_SND_VERBOSE_PRINTK.  *This* is the useless thing.

Maybe.

> Meanwhile, many snd_printk() messages might start looking annoying
> with the extra information.  If so, such lines should be replaced with
> the standard prints like dev_*().  I think almost all snd_printk()
> like below are better replaced with standard ones.

below?  Was there something that was supposed to be below?
Are you referring to the KERN_ERR/urb example above?

> So, alternatively, we can begin with replacing some snd_printk() with
> the standard functions, then dropping CONFIG_SND_VERBOSE_PRINTK.

Dropping CONFIG_SND_VERBOSE_PRINTK would simplify code a bit.

> I think most of snd_printd() and snd_printdd() can be kept as is.
> These are just debug messages, after all.

Some of those are emitted at levels other than KERN_DEBUG.
I think that odd.

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Fri, 31 May 2013 00:06:07 -0700,
Joe Perches wrote:
> 
> On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> > It's a problem only with snd_printk(), as CONFIG_SND_VERBOSE_PRINTK
> > influences on the behavior of snd_printk() and not on the debug prints
> > with snd_printd() & co.
> 
> Are you're perhaps confused about how CONFIG_SND_VERBOSE_PRINTK
> works with or varies between snd_printd and snd_printk?
> 
> #if defined(CONFIG_SND_DEBUG) || defined(CONFIG_SND_VERBOSE_PRINTK)
> __printf(4, 5)
> void __snd_printk(unsigned int level, const char *file, int line,
> 		  const char *format, ...);
> 
> ...
> 
> #define snd_printk(fmt, args...) \
> 	__snd_printk(0, __FILE__, __LINE__, fmt, ##args)
> 
> #ifdef CONFIG_SND_DEBUG
> [...]
> #define snd_printd(fmt, args...) \
> 	__snd_printk(1, __FILE__, __LINE__, fmt, ##args)
> 
> I don't see a difference.

Erm, indeed.  I thought we enabled the verobse prinkt always for debug
prints.  But it's not.  It's more reason for dropping
CONFIG_SND_VERBOSE_PRINTK :)

> > Hence, the goal we should achieve is rather to drop
> > CONFIG_SND_VERBOSE_PRINTK.  *This* is the useless thing.
> 
> Maybe.
> 
> > Meanwhile, many snd_printk() messages might start looking annoying
> > with the extra information.  If so, such lines should be replaced with
> > the standard prints like dev_*().  I think almost all snd_printk()
> > like below are better replaced with standard ones.
> 
> below?  Was there something that was supposed to be below?
> Are you referring to the KERN_ERR/urb example above?

Sorry, scratch it.  Just a typo during changing the lines.

> > So, alternatively, we can begin with replacing some snd_printk() with
> > the standard functions, then dropping CONFIG_SND_VERBOSE_PRINTK.
> 
> Dropping CONFIG_SND_VERBOSE_PRINTK would simplify code a bit.
> 
> > I think most of snd_printd() and snd_printdd() can be kept as is.
> > These are just debug messages, after all.
> 
> Some of those are emitted at levels other than KERN_DEBUG.
> I think that odd.

Yeah, they aren't good, but it's a different topic.


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Joe Perches]

On Fri, 2013-05-31 at 09:23 +0200, Takashi Iwai wrote:
> At Fri, 31 May 2013 00:06:07 -0700, Joe Perches wrote:
> > On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> > > I think most of snd_printd() and snd_printdd() can be kept as is.
> > > These are just debug messages, after all.
> > Some of those are emitted at levels other than KERN_DEBUG.
> > I think that odd.
> Yeah, they aren't good, but it's a different topic.

Not really, I think it's systemic and fallout from
accretive implementation rather than design.

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Fri, 31 May 2013 00:30:09 -0700,
Joe Perches wrote:
> 
> On Fri, 2013-05-31 at 09:23 +0200, Takashi Iwai wrote:
> > At Fri, 31 May 2013 00:06:07 -0700, Joe Perches wrote:
> > > On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> > > > I think most of snd_printd() and snd_printdd() can be kept as is.
> > > > These are just debug messages, after all.
> > > Some of those are emitted at levels other than KERN_DEBUG.
> > > I think that odd.
> > Yeah, they aren't good, but it's a different topic.
> 
> Not really, I think it's systemic and fallout from
> accretive implementation rather than design.

Maybe.

But you shouldn't mix up with the fix for the missing verbosity and
the fix for wrong KERN_ prefix, at least, in the patch level.  They
need to be fixed individually.


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Joe Perches]

On Fri, 2013-05-31 at 09:35 +0200, Takashi Iwai wrote:
> At Fri, 31 May 2013 00:30:09 -0700, Joe Perches wrote:
> > On Fri, 2013-05-31 at 09:23 +0200, Takashi Iwai wrote:
> > > At Fri, 31 May 2013 00:06:07 -0700, Joe Perches wrote:
> > > > On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> > > > > I think most of snd_printd() and snd_printdd() can be kept as is.
> > > > > These are just debug messages, after all.
> > > > Some of those are emitted at levels other than KERN_DEBUG.
> > > > I think that odd.
> > > Yeah, they aren't good, but it's a different topic.
> > 
> > Not really, I think it's systemic and fallout from
> > accretive implementation rather than design.
> 
> Maybe.
> 
> But you shouldn't mix up with the fix for the missing verbosity and
> the fix for wrong KERN_ prefix, at least, in the patch level.  They
> need to be fixed individually.

I think that's best too.

I don't see the complexity/hell in adding functions
for specific types of struct * to reduce the complexity
of the code though.  Centralizing those indirections
into functions also generally reduces overall code size.

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Fri, 31 May 2013 00:38:01 -0700,
Joe Perches wrote:
> 
> On Fri, 2013-05-31 at 09:35 +0200, Takashi Iwai wrote:
> > At Fri, 31 May 2013 00:30:09 -0700, Joe Perches wrote:
> > > On Fri, 2013-05-31 at 09:23 +0200, Takashi Iwai wrote:
> > > > At Fri, 31 May 2013 00:06:07 -0700, Joe Perches wrote:
> > > > > On Fri, 2013-05-31 at 08:37 +0200, Takashi Iwai wrote:
> > > > > > I think most of snd_printd() and snd_printdd() can be kept as is.
> > > > > > These are just debug messages, after all.
> > > > > Some of those are emitted at levels other than KERN_DEBUG.
> > > > > I think that odd.
> > > > Yeah, they aren't good, but it's a different topic.
> > > 
> > > Not really, I think it's systemic and fallout from
> > > accretive implementation rather than design.
> > 
> > Maybe.
> > 
> > But you shouldn't mix up with the fix for the missing verbosity and
> > the fix for wrong KERN_ prefix, at least, in the patch level.  They
> > need to be fixed individually.
> 
> I think that's best too.
> 
> I don't see the complexity/hell in adding functions
> for specific types of struct * to reduce the complexity
> of the code though.  Centralizing those indirections
> into functions also generally reduces overall code size.

I don't mind to add the struct pointer to new snd_*() -- if we really
introduce them.  The bigger question is whether we really need to
introduce such, and if yes, what variants.  And for that, I don't
think we need to add many functions.  Maybe snd_card_<level>() would
be good.  But others don't seem to make sense to me (remember that I
suggest dropping CONFIG_SND_VERBOSE_PRINTK).


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Alan Stern]

On Fri, 31 May 2013, Takashi Iwai wrote:

> > I don't see the complexity/hell in adding functions
> > for specific types of struct * to reduce the complexity
> > of the code though.  Centralizing those indirections
> > into functions also generally reduces overall code size.
> 
> I don't mind to add the struct pointer to new snd_*() -- if we really
> introduce them.  The bigger question is whether we really need to
> introduce such, and if yes, what variants.  And for that, I don't
> think we need to add many functions.  Maybe snd_card_<level>() would
> be good.  But others don't seem to make sense to me (remember that I
> suggest dropping CONFIG_SND_VERBOSE_PRINTK).

struct snd_card contains pointers to two different devices: dev and 
card_dev.  Some contexts might want to use one of them for log messages 
while other contexts might want to use the other.

I guess defining snd_card_*() to use card->card_dev makes the most 
sense.  If some code wants to use card->dev instead, it can pass that 
as the first argument to dev_*().

The most commonly used levels seem to be err, warn, info, and dbg.  
Those ought to be enough.  In fact, you probably could getting along 
without warn -- just err, info, and dbg.

Alan Stern

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Fri, 31 May 2013 10:24:51 -0400 (EDT),
Alan Stern wrote:
> 
> On Fri, 31 May 2013, Takashi Iwai wrote:
> 
> > > I don't see the complexity/hell in adding functions
> > > for specific types of struct * to reduce the complexity
> > > of the code though.  Centralizing those indirections
> > > into functions also generally reduces overall code size.
> > 
> > I don't mind to add the struct pointer to new snd_*() -- if we really
> > introduce them.  The bigger question is whether we really need to
> > introduce such, and if yes, what variants.  And for that, I don't
> > think we need to add many functions.  Maybe snd_card_<level>() would
> > be good.  But others don't seem to make sense to me (remember that I
> > suggest dropping CONFIG_SND_VERBOSE_PRINTK).
> 
> struct snd_card contains pointers to two different devices: dev and 
> card_dev.  Some contexts might want to use one of them for log messages 
> while other contexts might want to use the other.

Yes, there are some corner cases, indeed.

Also, another expected problem is that neither card->card_dev nor
card->dev are set when snd_card_err() is called.  Many drivers set the
device pointers at the late stage just before the device
registration.  So, systematic replacements won't work as expected in
many cases.  (The same is applied for replacement with dev_*(), too.)


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Alan Stern]

On Fri, 31 May 2013, Takashi Iwai wrote:

> > struct snd_card contains pointers to two different devices: dev and 
> > card_dev.  Some contexts might want to use one of them for log messages 
> > while other contexts might want to use the other.
> 
> Yes, there are some corner cases, indeed.
> 
> Also, another expected problem is that neither card->card_dev nor
> card->dev are set when snd_card_err() is called.  Many drivers set the
> device pointers at the late stage just before the device
> registration.  So, systematic replacements won't work as expected in
> many cases.  (The same is applied for replacement with dev_*(), too.)

Given that the drivers would have to be edited to fix up the snd_printk 
calls, the device pointer assignments can be moved to an earlier stage 
at the same time.  But doing this would require understanding how the 
driver works to some extent; it couldn't be done blindly.

Alan Stern

Re: [alsa-devel] Improving or replacing snd_printk()

[Takashi Iwai]

At Fri, 31 May 2013 11:33:44 -0400 (EDT),
Alan Stern wrote:
> 
> On Fri, 31 May 2013, Takashi Iwai wrote:
> 
> > > struct snd_card contains pointers to two different devices: dev and 
> > > card_dev.  Some contexts might want to use one of them for log messages 
> > > while other contexts might want to use the other.
> > 
> > Yes, there are some corner cases, indeed.
> > 
> > Also, another expected problem is that neither card->card_dev nor
> > card->dev are set when snd_card_err() is called.  Many drivers set the
> > device pointers at the late stage just before the device
> > registration.  So, systematic replacements won't work as expected in
> > many cases.  (The same is applied for replacement with dev_*(), too.)
> 
> Given that the drivers would have to be edited to fix up the snd_printk 
> calls, the device pointer assignments can be moved to an earlier stage 
> at the same time.  But doing this would require understanding how the 
> driver works to some extent; it couldn't be done blindly.

Yep, that's what I meant as "systematic replacements".


Takashi

Re: [alsa-devel] Improving or replacing snd_printk()

[Joe Perches]

On Fri, 2013-05-31 at 16:34 +0200, Takashi Iwai wrote:
> Also, another expected problem is that neither card->card_dev nor
> card->dev are set when snd_card_err() is called.  Many drivers set the
> device pointers at the late stage just before the device
> registration.  So, systematic replacements won't work as expected in
> many cases.  (The same is applied for replacement with dev_*(), too.)

If all the pointers are null, then the logging function could
use pr_<level> and %pf, __builtin_return_addr() or another
method to look up the module name.