[alsa-devel] Improving or replacing snd_printk()
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
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.
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
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
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
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, ...)
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
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.
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
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.
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
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.
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
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
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
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
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
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.
participants (4)
-
Alan Stern -
Jaroslav Kysela -
Joe Perches -
Takashi Iwai