ehci dynamic debug problem

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()?

Quoted 5 lines · Johannes Stezenbach

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.

Quoted 15 lines · Alan Stern

Quoted 5 lines · Johannes Stezenbach

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;

Quoted 2 lines

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.

Quoted 19 lines · Johannes Stezenbach

Quoted 17 lines · Alan Stern

Quoted 5 lines · Johannes Stezenbach

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.

Quoted 4 lines

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.

Quoted 3 lines

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?

Quoted 5 lines · Johannes Stezenbach

Quoted 3 lines

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.

Quoted 5 lines

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.

Quoted 1 line

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.

Quoted 5 lines

Quoted 1 line

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?

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?

Quoted 18 lines · Alan Stern

Quoted 5 lines · Johannes Stezenbach

Quoted 3 lines

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.

Quoted 6 lines

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?

Quoted 3 lines

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?

Quoted 3 lines · Johannes Stezenbach

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:

Quoted 7 lines · Jason Baron

Quoted 3 lines · Johannes Stezenbach

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

Sorry was away for a bit...

Quoted 3 lines

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:

...

drivers/usb/host/ehci-dbg.c dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status) · line 339

Quoted 1 line

drivers/usb/host/ehci-dbg.c +1 -0

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

Quoted 11 lines · Johannes Stezenbach

Quoted 10 lines · Jason Baron

Quoted 3 lines · Johannes Stezenbach

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:

Quoted 5 lines

...

drivers/usb/host/ehci-dbg.c dbg_port_buf (char *buf, unsigned len, const char *label, int port, u32 status) · line 339

Quoted 1 line

drivers/usb/host/ehci-dbg.c +1 -0

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