ehci dynamic debug problem

ehci dynamic debug problem

[Johannes Stezenbach]

Hi,

I have a quirky device and enabled dynamic debug to
see the ehci driver debug messages to help me diagnose
the problem.  I see stuff like this:

[1790542.363321] ehci_hub_control:940: ehci_hcd 0000:00:1a.0: \xffffffd8\xffffff94\xffffff94\xffffffa8\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff}[<\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff\x01
[1790542.363470] ehci_hub_control:940: ehci_hcd 0000:00:1a.0: \xffffffd8\xffffff94\xffffff94\xffffffa8\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff}[<\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff\x01

The problem is in ehci-dbg.c:

#define dbg_port(ehci, label, port, status) { \
	char _buf [80]; \
	dbg_port_buf (_buf, sizeof _buf, label, port, status); \
	ehci_dbg (ehci, "%s\n", _buf); \
}

dbg_port_buf() is a no op when DEBUG is not defined, thus
the ehci_dbg() prints uninitialized memory.


Does dynamic debug offer an "is the message two lines below enabled" test?
Simply changing the "#ifdef DEBUG" for dbg_port_buf()
to "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
is probably not acceptable due to the overhead of dbg_port_buf()?


Thanks,
Johannes

Re: ehci dynamic debug problem

[Alan Stern]

On Fri, 13 Apr 2012, Johannes Stezenbach wrote:

> Hi,
> 
> I have a quirky device and enabled dynamic debug to
> see the ehci driver debug messages to help me diagnose
> the problem.  I see stuff like this:
> 
> [1790542.363321] ehci_hub_control:940: ehci_hcd 0000:00:1a.0: \xffffffd8\xffffff94\xffffff94\xffffffa8\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff}[<\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff\x01
> [1790542.363470] ehci_hub_control:940: ehci_hcd 0000:00:1a.0: \xffffffd8\xffffff94\xffffff94\xffffffa8\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff}[<\xffffff81\xffffffff\xffffffff\xffffffff\xffffffff\x01
> 
> The problem is in ehci-dbg.c:
> 
> #define dbg_port(ehci, label, port, status) { \
> 	char _buf [80]; \
> 	dbg_port_buf (_buf, sizeof _buf, label, port, status); \
> 	ehci_dbg (ehci, "%s\n", _buf); \
> }
> 
> dbg_port_buf() is a no op when DEBUG is not defined, thus
> the ehci_dbg() prints uninitialized memory.

Interesting.  I have never run across this, because I never use dynamic 
debug.

> Does dynamic debug offer an "is the message two lines below enabled" test?
> Simply changing the "#ifdef DEBUG" for dbg_port_buf()
> to "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> is probably not acceptable due to the overhead of dbg_port_buf()?

I don't understand your question.  Doesn't dbg_port_buf need to be 
defined whenever dynamic debugging is enabled?

Alternatively, the definition of dbg_port_buf (and related routines) in 
the !defined(DEBUG) case could be changed; you could add

	buf[0] = 0;

That way you wouldn't get garbage out, although you wouldn't get 
anything useful either.

Alan Stern

Re: ehci dynamic debug problem

[Johannes Stezenbach]

On Fri, Apr 13, 2012 at 10:35:59AM -0400, Alan Stern wrote:
> On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> > 
> > Does dynamic debug offer an "is the message two lines below enabled" test?
> > Simply changing the "#ifdef DEBUG" for dbg_port_buf()
> > to "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> > is probably not acceptable due to the overhead of dbg_port_buf()?
> 
> I don't understand your question.  Doesn't dbg_port_buf need to be 
> defined whenever dynamic debugging is enabled?
> 
> Alternatively, the definition of dbg_port_buf (and related routines) in 
> the !defined(DEBUG) case could be changed; you could add
> 
> 	buf[0] = 0;
> 
> That way you wouldn't get garbage out, although you wouldn't get 
> anything useful either.

The ideal solution I'm looking for gives useful output
when dynamic debugging is enabled for ehci, but does no
useless string formatting when CONFIG_DYNAMIC_DEBUG is y
but the dynamic debug for ehci is disabled.


Thanks,
Johannes

Re: ehci dynamic debug problem

[Alan Stern]

On Fri, 13 Apr 2012, Johannes Stezenbach wrote:

> On Fri, Apr 13, 2012 at 10:35:59AM -0400, Alan Stern wrote:
> > On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> > > 
> > > Does dynamic debug offer an "is the message two lines below enabled" test?
> > > Simply changing the "#ifdef DEBUG" for dbg_port_buf()
> > > to "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> > > is probably not acceptable due to the overhead of dbg_port_buf()?
> > 
> > I don't understand your question.  Doesn't dbg_port_buf need to be 
> > defined whenever dynamic debugging is enabled?
> > 
> > Alternatively, the definition of dbg_port_buf (and related routines) in 
> > the !defined(DEBUG) case could be changed; you could add
> > 
> > 	buf[0] = 0;
> > 
> > That way you wouldn't get garbage out, although you wouldn't get 
> > anything useful either.
> 
> The ideal solution I'm looking for gives useful output
> when dynamic debugging is enabled for ehci, but does no
> useless string formatting when CONFIG_DYNAMIC_DEBUG is y
> but the dynamic debug for ehci is disabled.

But there is no such thing as dynamic debug for ehci, is there?  
There's a separate dynamic debug setting for each dev_dbg statement.
So your ideal solution makes no sense.

Alan Stern

Re: ehci dynamic debug problem

[Johannes Stezenbach]

On Fri, Apr 13, 2012 at 11:19:37AM -0400, Alan Stern wrote:
> On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> 
> > On Fri, Apr 13, 2012 at 10:35:59AM -0400, Alan Stern wrote:
> > > On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> > > > 
> > > > Does dynamic debug offer an "is the message two lines below enabled" test?
> > > > Simply changing the "#ifdef DEBUG" for dbg_port_buf()
> > > > to "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> > > > is probably not acceptable due to the overhead of dbg_port_buf()?
> > > 
> > > I don't understand your question.  Doesn't dbg_port_buf need to be 
> > > defined whenever dynamic debugging is enabled?
> > > 
> > > Alternatively, the definition of dbg_port_buf (and related routines) in 
> > > the !defined(DEBUG) case could be changed; you could add
> > > 
> > > 	buf[0] = 0;
> > > 
> > > That way you wouldn't get garbage out, although you wouldn't get 
> > > anything useful either.
> > 
> > The ideal solution I'm looking for gives useful output
> > when dynamic debugging is enabled for ehci, but does no
> > useless string formatting when CONFIG_DYNAMIC_DEBUG is y
> > but the dynamic debug for ehci is disabled.
> 
> But there is no such thing as dynamic debug for ehci, is there?  
> There's a separate dynamic debug setting for each dev_dbg statement.
> So your ideal solution makes no sense.

When CONFIG_DYNAMIC_DEBUG=y but ehci debug is disabled
in /sys/kernel/debug/dynamic_debug/control, then
dbg_port() calls dbg_port_buf() which would
format the string, then calls ehci_dbg() which
calls dev_dbg() which discards it.

Does it make sense now?


Thanks,
Johannes

Re: ehci dynamic debug problem

[Alan Stern]

On Fri, 13 Apr 2012, Johannes Stezenbach wrote:

> > But there is no such thing as dynamic debug for ehci, is there?  
> > There's a separate dynamic debug setting for each dev_dbg statement.
> > So your ideal solution makes no sense.
> 
> When CONFIG_DYNAMIC_DEBUG=y but ehci debug is disabled

There is no such thing as ehci debug!  So how can it be disabled?
There's only an individual setting for each line of debugging code.

> in /sys/kernel/debug/dynamic_debug/control, then
> dbg_port() calls dbg_port_buf() which would
> format the string, then calls ehci_dbg() which
> calls dev_dbg() which discards it.
> 
> Does it make sense now?

No.  What happens if dynamic debug is enabled for one line that calls 
dbg_port_buf() but not for another?  There's no way to avoid the string 
formatting in both lines, even though one of them discards the result.

Alan Stern

Re: ehci dynamic debug problem

[Johannes Stezenbach]

On Fri, Apr 13, 2012 at 02:13:58PM -0400, Alan Stern wrote:
> On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> 
> > > But there is no such thing as dynamic debug for ehci, is there?  
> > > There's a separate dynamic debug setting for each dev_dbg statement.
> > > So your ideal solution makes no sense.
> > 
> > When CONFIG_DYNAMIC_DEBUG=y but ehci debug is disabled
> 
> There is no such thing as ehci debug!  So how can it be disabled?
> There's only an individual setting for each line of debugging code.
> 
> > in /sys/kernel/debug/dynamic_debug/control, then
> > dbg_port() calls dbg_port_buf() which would
> > format the string, then calls ehci_dbg() which
> > calls dev_dbg() which discards it.
> > 
> > Does it make sense now?
> 
> No.  What happens if dynamic debug is enabled for one line that calls 
> dbg_port_buf() but not for another?  There's no way to avoid the string 
> formatting in both lines, even though one of them discards the result.

That's why I said in my initial mail:

  Does dynamic debug offer an "is the message two lines below enabled" test?

What I meant is that dbg_port() could test if it
needs to call dbg_port_buf() for this call site.


Anyway, maybe the dbg_*_buf() are not called often enough to worry?

If you're OK with "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
then maybe you should just do that?


Thanks
Johannes

Re: ehci dynamic debug problem

[Alan Stern]

On Fri, 13 Apr 2012, Johannes Stezenbach wrote:

> > > Does it make sense now?
> > 
> > No.  What happens if dynamic debug is enabled for one line that calls 
> > dbg_port_buf() but not for another?  There's no way to avoid the string 
> > formatting in both lines, even though one of them discards the result.
> 
> That's why I said in my initial mail:
> 
>   Does dynamic debug offer an "is the message two lines below enabled" test?
> 
> What I meant is that dbg_port() could test if it
> needs to call dbg_port_buf() for this call site.

Oh.  As far as I know, that's not possible.

> Anyway, maybe the dbg_*_buf() are not called often enough to worry?

Probably not.

> If you're OK with "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> then maybe you should just do that?

Yes, that sounds best.

Alan Stern

Re: ehci dynamic debug problem

[Alan Stern]

On Fri, 13 Apr 2012, Johannes Stezenbach wrote:

> Anyway, maybe the dbg_*_buf() are not called often enough to worry?
> 
> If you're OK with "#if defined(DEBUG) || defined(CONFIG_DYNAMIC_DEBUG)"
> then maybe you should just do that?

Actually I'm pretty busy now.  If you would like to submit a patch to 
do this, it would be great.

Alan Stern

Re: ehci dynamic debug problem

[Jason Baron]

On Fri, Apr 13, 2012 at 09:03:11PM +0200, Johannes Stezenbach wrote:
> On Fri, Apr 13, 2012 at 02:13:58PM -0400, Alan Stern wrote:
> > On Fri, 13 Apr 2012, Johannes Stezenbach wrote:
> > 
> > > > But there is no such thing as dynamic debug for ehci, is there?  
> > > > There's a separate dynamic debug setting for each dev_dbg statement.
> > > > So your ideal solution makes no sense.
> > > 
> > > When CONFIG_DYNAMIC_DEBUG=y but ehci debug is disabled
> > 
> > There is no such thing as ehci debug!  So how can it be disabled?
> > There's only an individual setting for each line of debugging code.
> > 
> > > in /sys/kernel/debug/dynamic_debug/control, then
> > > dbg_port() calls dbg_port_buf() which would
> > > format the string, then calls ehci_dbg() which
> > > calls dev_dbg() which discards it.
> > > 
> > > Does it make sense now?
> > 
> > No.  What happens if dynamic debug is enabled for one line that calls 
> > dbg_port_buf() but not for another?  There's no way to avoid the string 
> > formatting in both lines, even though one of them discards the result.
> 
> That's why I said in my initial mail:
> 
>   Does dynamic debug offer an "is the message two lines below enabled" test?
> 

Sorry was away for a bit...

dynamic debug doesn't offer any is enabled test, its hidden from the
user. That said, in this case, you can delay the printing to the buffer
with:


diff --git a/drivers/usb/host/ehci-dbg.c b/drivers/usb/host/ehci-dbg.c
index d6d74d2..fd90ccd 100644
--- a/drivers/usb/host/ehci-dbg.c
+++ b/drivers/usb/host/ehci-dbg.c
@@ -254,7 +255,7 @@ dbg_command_buf (char *buf, unsigned len, const char *label, u32 command)
 		);
 }
 
-static int
+static char *
 dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status)
 {
 	char	*sig;
@@ -267,7 +268,7 @@ dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status)
 	default: sig = "?"; break;
 	}
 
-	return scnprintf (buf, len,
+	scnprintf (buf, len,
 		"%s%sport:%d status %06x %d %s%s%s%s%s%s "
 		"sig=%s%s%s%s%s%s%s%s%s%s%s",
 		label, label [0] ? " " : "", port, status,
@@ -293,6 +294,8 @@ dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status)
 		(status & PORT_PE) ? " PE" : "",
 		(status & PORT_CSC) ? " CSC" : "",
 		(status & PORT_CONNECT) ? " CONNECT" : "");
+
+	return buf;
 }
 
 #else
@@ -333,8 +336,7 @@ dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status)
 
 #define dbg_port(ehci, label, port, status) { \
 	char _buf [80]; \
-	dbg_port_buf (_buf, sizeof _buf, label, port, status); \
-	ehci_dbg (ehci, "%s\n", _buf); \
+	ehci_dbg (ehci, "%s\n", dbg_port_buf (_buf, sizeof _buf, label, port, status)); \
 }
 
 /*-------------------------------------------------------------------------*/


That seems to do what you want, at least with my compiler - gcc (GCC)
4.6.2 20111027 (Red Hat 4.6.2-1).

Thanks,

-Jason

Re: ehci dynamic debug problem

[Johannes Stezenbach]

On Mon, Apr 16, 2012 at 11:54:24AM -0400, Jason Baron wrote:
> On Fri, Apr 13, 2012 at 09:03:11PM +0200, Johannes Stezenbach wrote:
> > 
> >   Does dynamic debug offer an "is the message two lines below enabled" test?
> > 
> 
> Sorry was away for a bit...
> 
> dynamic debug doesn't offer any is enabled test, its hidden from the
> user. That said, in this case, you can delay the printing to the buffer
> with:
...
> +	ehci_dbg (ehci, "%s\n", dbg_port_buf (_buf, sizeof _buf, label, port, status)); \

I think arguments are evaluated before dev_dbg is called so this
won't help.


Thanks
Johannes

Re: ehci dynamic debug problem

[Jason Baron]

On Mon, Apr 16, 2012 at 06:41:39PM +0200, Johannes Stezenbach wrote:
> On Mon, Apr 16, 2012 at 11:54:24AM -0400, Jason Baron wrote:
> > On Fri, Apr 13, 2012 at 09:03:11PM +0200, Johannes Stezenbach wrote:
> > > 
> > >   Does dynamic debug offer an "is the message two lines below enabled" test?
> > > 
> > 
> > Sorry was away for a bit...
> > 
> > dynamic debug doesn't offer any is enabled test, its hidden from the
> > user. That said, in this case, you can delay the printing to the buffer
> > with:
> ...
> > +	ehci_dbg (ehci, "%s\n", dbg_port_buf (_buf, sizeof _buf, label, port, status)); \
> 
> I think arguments are evaluated before dev_dbg is called so this
> won't help.
> 
> 

I looked at the disassembly - and this argument was in fact *not* evaluated
before the call. So I think this approach is worthwhile.

Thanks,

-Jason

Re: ehci dynamic debug problem

[Johannes Stezenbach]

On Mon, Apr 16, 2012 at 01:15:46PM -0400, Jason Baron wrote:
> On Mon, Apr 16, 2012 at 06:41:39PM +0200, Johannes Stezenbach wrote:
> > On Mon, Apr 16, 2012 at 11:54:24AM -0400, Jason Baron wrote:
> > > On Fri, Apr 13, 2012 at 09:03:11PM +0200, Johannes Stezenbach wrote:
> > > > 
> > > >   Does dynamic debug offer an "is the message two lines below enabled" test?
> > > > 
> > > 
> > > Sorry was away for a bit...
> > > 
> > > dynamic debug doesn't offer any is enabled test, its hidden from the
> > > user. That said, in this case, you can delay the printing to the buffer
> > > with:
> > ...
> > > +	ehci_dbg (ehci, "%s\n", dbg_port_buf (_buf, sizeof _buf, label, port, status)); \
> > 
> > I think arguments are evaluated before dev_dbg is called so this
> > won't help.
> 
> I looked at the disassembly - and this argument was in fact *not* evaluated
> before the call. So I think this approach is worthwhile.

OK, I was in a hurry before but now that I looked at
dynamic_dev_dbg() definition in include/linux/dynamic_debug.h
I see that it works.  IMHO it's a good solution.


Thank you,
Johannes