2012-11-18 13:53:15

by Kondratiev, Vladimir

[permalink] [raw]
Subject: Re: [RFC] dynamic_debug: introduce debug_hex_dump()

On Sunday, November 18, 2012 11:47:58 AM Vladimir Kondratiev wrote:
> On Wednesday, November 14, 2012 07:27:47 PM Vladimir Kondratiev wrote:
> > +#define dynamic_hex_dump(prefix_str, prefix_type, rowsize, \
> > + groupsize, buf, len, ascii) \
> > +do { \
> > + DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, prefix_str); \
> > + if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT)) \
> > + print_hex_dump(KERN_DEBUG, prefix_str, \
> > + prefix_type, rowsize, groupsize, \
> > + buf, len, ascii); \
> > +} while (0)
>
> There is some problem with the code above. There are existing drivers
> that use print_hex_dump_bytes() with the prefix_str built dynamically,
> like this (see drivers/tty/ipwireless/hardware.c:362)
>
> static void dump_data_bytes(const char *type, const unsigned char *data,
> unsigned length)
> {
> char prefix[56];
>
> sprintf(prefix, IPWIRELESS_PCCARD_NAME ": %s %s ",
> type, data_type(data, length));
> print_hex_dump_bytes(prefix, 0, (void *)data,
> length < DUMP_MAX_BYTES ? length : DUMP_MAX_BYTES);
> }
>
> In this case, prefix_str is not constant, and this solution will not
> work.
>
> I see 2 drivers that use dynamic prefix:
>
> - mentioned above drivers/tty/ipwireless/hardware.c
> - drivers/isdn/hardware/mISDN/
>
> I see several options:
>
> 1) require prefix_str to be constant. Patch code mentioned. For example,
> code above may reads:
>
> static void dump_data_bytes(const char *type, const unsigned char *data,
> unsigned length)
> {
> pr_debug(IPWIRELESS_PCCARD_NAME ": %s %s\n",
> type, data_type(data, length));
> print_hex_dump_bytes(IPWIRELESS_PCCARD_NAME, 0, (void *)data,
> length < DUMP_MAX_BYTES ? length : DUMP_MAX_BYTES);
> }
>
> 2) introduce fixed format string in DEFINE_DYNAMIC_DEBUG_METADATA, like
>
> DEFINE_DYNAMIC_DEBUG_METADATA((descriptor, "hexdump");
>
> 3) remove print_hex_dump_bytes from this patch
>
> I think 1) is the best, opinions?
>
> Thanks, Vladimir

In case of option 1), patches follows. Note there is change in the initial patch as well (I forgot to exclude print_hex_dump_bytes() from compilation in hexdump.c. Please, comment.


2012-11-18 13:57:46

by Kondratiev, Vladimir

[permalink] [raw]
Subject: [PATCH 2/2] dynamic_debug: use constant format in print_hex_dump_bytes()

>From cff77ecaa9a1f875327a0530f0ebc7998427bbf4 Mon Sep 17 00:00:00 2001
From: Vladimir Kondratiev <[email protected]>
Date: Sun, 18 Nov 2012 15:47:09 +0200
Subject: [PATCH 2/2] dynamic_debug: use constant format in
print_hex_dump_bytes()

In order to convert print_hex_dump_bytes() to dynamic debug,
it should be wrapped in macro (DEFINE_DYNAMIC_DEBUG_METADATA)
to define metadata. This, in turn, require 'format' to be constant string.
For practical purposes, it is reasonable to use as 'format' the
'prefix_str' argument for the print_hex_dump_bytes()

This patch fixes usage of dynamically generated prefixes. General approach
is to print desired prefix using pr_debug(), following with hex dump using "short"
prefix string. This will preserve desired information with little impact on readability.

In fact, result should be even better for human, albeit it may break automatic log
parser, should it be based on prefix string.

Signed-off-by: Vladimir Kondratiev <[email protected]>
---
drivers/isdn/hardware/mISDN/avmfritz.c | 12 ++++--------
drivers/isdn/hardware/mISDN/mISDNipac.c | 22 ++++++++--------------
drivers/isdn/hardware/mISDN/netjet.c | 16 ++++++----------
drivers/isdn/hardware/mISDN/w6692.c | 19 ++++++++-----------
drivers/net/wireless/ath/ath6kl/debug.c | 3 ++-
drivers/net/wireless/libertas_tf/deb_defs.h | 6 ++----
drivers/tty/ipwireless/hardware.c | 9 ++++-----
7 files changed, 34 insertions(+), 53 deletions(-)

diff --git a/drivers/isdn/hardware/mISDN/avmfritz.c b/drivers/isdn/hardware/mISDN/avmfritz.c
index dceaec8..d24f85b 100644
--- a/drivers/isdn/hardware/mISDN/avmfritz.c
+++ b/drivers/isdn/hardware/mISDN/avmfritz.c
@@ -104,7 +104,6 @@ enum {
#define AVM_ISACX_DATA 0x08

/* data struct */
-#define LOG_SIZE 63

struct hdlc_stat_reg {
#ifdef __BIG_ENDIAN
@@ -141,7 +140,6 @@ struct fritzcard {
struct isac_hw isac;
struct hdlc_hw hdlc[2];
struct bchannel bch[2];
- char log[LOG_SIZE + 1];
};

static LIST_HEAD(Cards);
@@ -438,9 +436,8 @@ hdlc_empty_fifo(struct bchannel *bch, int count)
cnt += 4;
}
if (p && (debug & DEBUG_HW_BFIFO)) {
- snprintf(fc->log, LOG_SIZE, "B%1d-recv %s %d ",
- bch->nr, fc->name, count);
- print_hex_dump_bytes(fc->log, DUMP_PREFIX_OFFSET, p, count);
+ pr_debug("B%1d-recv %s %d\n", bch->nr, fc->name, count);
+ print_hex_dump_bytes("recv", DUMP_PREFIX_OFFSET, p, count);
}
}

@@ -509,9 +506,8 @@ hdlc_fill_fifo(struct bchannel *bch)
}
}
if ((debug & DEBUG_HW_BFIFO) && !fillempty) {
- snprintf(fc->log, LOG_SIZE, "B%1d-send %s %d ",
- bch->nr, fc->name, count);
- print_hex_dump_bytes(fc->log, DUMP_PREFIX_OFFSET, p, count);
+ pr_debug("B%1d-send %s %d\n", bch->nr, fc->name, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, p, count);
}
}

diff --git a/drivers/isdn/hardware/mISDN/mISDNipac.c b/drivers/isdn/hardware/mISDN/mISDNipac.c
index ccd7d85..1e35dcb 100644
--- a/drivers/isdn/hardware/mISDN/mISDNipac.c
+++ b/drivers/isdn/hardware/mISDN/mISDNipac.c
@@ -137,11 +137,8 @@ isac_empty_fifo(struct isac_hw *isac, int count)
isac->read_fifo(isac->dch.hw, isac->off, ptr, count);
WriteISAC(isac, ISAC_CMDR, 0x80);
if (isac->dch.debug & DEBUG_HW_DFIFO) {
- char pfx[MISDN_MAX_IDLEN + 16];
-
- snprintf(pfx, MISDN_MAX_IDLEN + 15, "D-recv %s %d ",
- isac->name, count);
- print_hex_dump_bytes(pfx, DUMP_PREFIX_OFFSET, ptr, count);
+ pr_debug("D-recv %s %d\n", isac->name, count);
+ print_hex_dump_bytes("recv", DUMP_PREFIX_OFFSET, ptr, count);
}
}

@@ -175,11 +172,8 @@ isac_fill_fifo(struct isac_hw *isac)
isac->dch.timer.expires = jiffies + ((DBUSY_TIMER_VALUE * HZ)/1000);
add_timer(&isac->dch.timer);
if (isac->dch.debug & DEBUG_HW_DFIFO) {
- char pfx[MISDN_MAX_IDLEN + 16];
-
- snprintf(pfx, MISDN_MAX_IDLEN + 15, "D-send %s %d ",
- isac->name, count);
- print_hex_dump_bytes(pfx, DUMP_PREFIX_OFFSET, ptr, count);
+ pr_debug("D-send %s %d\n", isac->name, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, ptr, count);
}
}

@@ -962,9 +956,9 @@ hscx_empty_fifo(struct hscx_hw *hscx, u8 count)
hscx_cmdr(hscx, 0x80); /* RMC */

if (hscx->bch.debug & DEBUG_HW_BFIFO) {
- snprintf(hscx->log, 64, "B%1d-recv %s %d ",
+ pr_debug("B%1d-recv %s %d\n",
hscx->bch.nr, hscx->ip->name, count);
- print_hex_dump_bytes(hscx->log, DUMP_PREFIX_OFFSET, p, count);
+ print_hex_dump_bytes("recv", DUMP_PREFIX_OFFSET, p, count);
}
}

@@ -1007,9 +1001,9 @@ hscx_fill_fifo(struct hscx_hw *hscx)
hscx_cmdr(hscx, more ? 0x08 : 0x0a);

if (hscx->bch.tx_skb && (hscx->bch.debug & DEBUG_HW_BFIFO)) {
- snprintf(hscx->log, 64, "B%1d-send %s %d ",
+ pr_debug("B%1d-send %s %d\n",
hscx->bch.nr, hscx->ip->name, count);
- print_hex_dump_bytes(hscx->log, DUMP_PREFIX_OFFSET, p, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, p, count);
}
}

diff --git a/drivers/isdn/hardware/mISDN/netjet.c b/drivers/isdn/hardware/mISDN/netjet.c
index 9bcade5..7e16270 100644
--- a/drivers/isdn/hardware/mISDN/netjet.c
+++ b/drivers/isdn/hardware/mISDN/netjet.c
@@ -71,8 +71,6 @@ struct tiger_ch {
#define TX_UNDERRUN 0x0100
#define RX_OVERRUN 0x0100

-#define LOG_SIZE 64
-
struct tiger_hw {
struct list_head list;
struct pci_dev *pdev;
@@ -94,7 +92,6 @@ struct tiger_hw {
u8 auxd;
u8 last_is0;
u8 irqmask0;
- char log[LOG_SIZE];
};

static LIST_HEAD(Cards);
@@ -423,10 +420,9 @@ read_dma(struct tiger_ch *bc, u32 idx, int cnt)
if (stat > 0) { /* valid frame received */
p = skb_put(bc->bch.rx_skb, stat);
if (debug & DEBUG_HW_BFIFO) {
- snprintf(card->log, LOG_SIZE,
- "B%1d-recv %s %d ", bc->bch.nr,
+ pr_debug("B%1d-recv %s %d\n", bc->bch.nr,
card->name, stat);
- print_hex_dump_bytes(card->log,
+ print_hex_dump_bytes("recv",
DUMP_PREFIX_OFFSET, p,
stat);
}
@@ -527,9 +523,9 @@ fill_hdlc_flag(struct tiger_ch *bc)
card->send.start[bc->idx++] = v;
}
if (debug & DEBUG_HW_BFIFO) {
- snprintf(card->log, LOG_SIZE, "B%1d-send %s %d ",
+ pr_debug("B%1d-send %s %d\n",
bc->bch.nr, card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, p, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, p, count);
}
}

@@ -601,9 +597,9 @@ fill_dma(struct tiger_ch *bc)
}
}
if (debug & DEBUG_HW_BFIFO) {
- snprintf(card->log, LOG_SIZE, "B%1d-send %s %d ",
+ pr_debug("B%1d-send %s %d\n",
bc->bch.nr, card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, p, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, p, count);
}
if (bc->free)
bc_next_frame(bc);
diff --git a/drivers/isdn/hardware/mISDN/w6692.c b/drivers/isdn/hardware/mISDN/w6692.c
index 335fe64..da4198b 100644
--- a/drivers/isdn/hardware/mISDN/w6692.c
+++ b/drivers/isdn/hardware/mISDN/w6692.c
@@ -81,7 +81,6 @@ struct w6692_hw {
u8 state;
struct w6692_ch bc[2];
struct dchannel dch;
- char log[64];
};

static LIST_HEAD(Cards);
@@ -279,9 +278,8 @@ W6692_empty_Dfifo(struct w6692_hw *card, int count)
insb(card->addr + W_D_RFIFO, ptr, count);
WriteW6692(card, W_D_CMDR, W_D_CMDR_RACK);
if (debug & DEBUG_HW_DFIFO) {
- snprintf(card->log, 63, "D-recv %s %d ",
- card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, ptr, count);
+ pr_debug("D-recv %s %d\n", card->name, count);
+ print_hex_dump_bytes("recv", DUMP_PREFIX_OFFSET, ptr, count);
}
}

@@ -315,9 +313,8 @@ W6692_fill_Dfifo(struct w6692_hw *card)
dch->timer.expires = jiffies + ((DBUSY_TIMER_VALUE * HZ) / 1000);
add_timer(&dch->timer);
if (debug & DEBUG_HW_DFIFO) {
- snprintf(card->log, 63, "D-send %s %d ",
- card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, ptr, count);
+ pr_debug("D-send %s %d\n", card->name, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, ptr, count);
}
}

@@ -493,9 +490,9 @@ W6692_empty_Bfifo(struct w6692_ch *wch, int count)
insb(wch->addr + W_B_RFIFO, ptr, count);
WriteW6692B(wch, W_B_CMDR, W_B_CMDR_RACK | W_B_CMDR_RACT);
if (debug & DEBUG_HW_DFIFO) {
- snprintf(card->log, 63, "B%1d-recv %s %d ",
+ pr_debug("B%1d-recv %s %d\n",
wch->bch.nr, card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, ptr, count);
+ print_hex_dump_bytes("recv", DUMP_PREFIX_OFFSET, ptr, count);
}
}

@@ -537,9 +534,9 @@ W6692_fill_Bfifo(struct w6692_ch *wch)
}
WriteW6692B(wch, W_B_CMDR, cmd);
if ((debug & DEBUG_HW_BFIFO) && !fillempty) {
- snprintf(card->log, 63, "B%1d-send %s %d ",
+ pr_debug("B%1d-send %s %d\n",
wch->bch.nr, card->name, count);
- print_hex_dump_bytes(card->log, DUMP_PREFIX_OFFSET, ptr, count);
+ print_hex_dump_bytes("send", DUMP_PREFIX_OFFSET, ptr, count);
}
}

diff --git a/drivers/net/wireless/ath/ath6kl/debug.c b/drivers/net/wireless/ath/ath6kl/debug.c
index 15cfe30..ee8688c 100644
--- a/drivers/net/wireless/ath/ath6kl/debug.c
+++ b/drivers/net/wireless/ath/ath6kl/debug.c
@@ -85,7 +85,8 @@ void ath6kl_dbg_dump(enum ATH6K_DEBUG_MASK mask,
if (msg)
ath6kl_dbg(mask, "%s\n", msg);

- print_hex_dump_bytes(prefix, DUMP_PREFIX_OFFSET, buf, len);
+ pr_debug("%s dump\n", prefix);
+ print_hex_dump_bytes("", DUMP_PREFIX_OFFSET, buf, len);
}
}
EXPORT_SYMBOL(ath6kl_dbg_dump);
diff --git a/drivers/net/wireless/libertas_tf/deb_defs.h b/drivers/net/wireless/libertas_tf/deb_defs.h
index 4bd3dc5..6efa6a7 100644
--- a/drivers/net/wireless/libertas_tf/deb_defs.h
+++ b/drivers/net/wireless/libertas_tf/deb_defs.h
@@ -88,13 +88,11 @@ do { if ((lbtf_debug & (grp)) == (grp)) \
#ifdef DEBUG
static inline void lbtf_deb_hex(unsigned int grp, const char *prompt, u8 *buf, int len)
{
- char newprompt[32];
-
if (len &&
(lbtf_debug & LBTF_DEB_HEX) &&
(lbtf_debug & grp)) {
- snprintf(newprompt, sizeof(newprompt), DRV_NAME " %s: ", prompt);
- print_hex_dump_bytes(prompt, DUMP_PREFIX_NONE, buf, len);
+ pr_debug(DRV_NAME " %s\n", prompt);
+ print_hex_dump_bytes(DRV_NAME, DUMP_PREFIX_NONE, buf, len);
}
}
#else
diff --git a/drivers/tty/ipwireless/hardware.c b/drivers/tty/ipwireless/hardware.c
index b4ba067..fede217 100644
--- a/drivers/tty/ipwireless/hardware.c
+++ b/drivers/tty/ipwireless/hardware.c
@@ -362,12 +362,11 @@ static char *data_type(const unsigned char *buf, unsigned length)
static void dump_data_bytes(const char *type, const unsigned char *data,
unsigned length)
{
- char prefix[56];
-
- sprintf(prefix, IPWIRELESS_PCCARD_NAME ": %s %s ",
+ pr_debug(IPWIRELESS_PCCARD_NAME ": %s %s\n",
type, data_type(data, length));
- print_hex_dump_bytes(prefix, 0, (void *)data,
- length < DUMP_MAX_BYTES ? length : DUMP_MAX_BYTES);
+ print_hex_dump_bytes(IPWIRELESS_PCCARD_NAME, DUMP_PREFIX_NONE,
+ (void *)data,
+ min_t(unsigned, length, DUMP_MAX_BYTES));
}

static void swap_packet_bitfield_to_le(unsigned char *data)
--
1.7.10.4

2012-11-18 13:59:36

by Kondratiev, Vladimir

[permalink] [raw]
Subject: [PATCH 1/2] dynamic_debug: dynamic hex dump

>From 26bb3835fe438622d108716420c3cc191f2e881b Mon Sep 17 00:00:00 2001
From: Vladimir Kondratiev <[email protected]>
Date: Sun, 18 Nov 2012 15:37:20 +0200
Subject: [PATCH 1/2] dynamic_debug: dynamic hex dump

Introduce print_hex_dump_debug() that can be dynamically controlled, similar to
pr_debug.

Also, make print_hex_dump_bytes() dynamically controlled

Implement only 'p' flag (_DPRINTK_FLAGS_PRINT) to keep it simple since hex dump prints
multiple lines and long prefix would impact readability.
To provide line/file etc. information, use pr_debug or similar
before/after print_hex_dump_debug()

Signed-off-by: Vladimir Kondratiev <[email protected]>
---
Documentation/dynamic-debug-howto.txt | 11 +++++++++--
include/linux/dynamic_debug.h | 10 ++++++++++
include/linux/printk.h | 17 +++++++++++++++++
lib/hexdump.c | 4 +++-
4 files changed, 39 insertions(+), 3 deletions(-)

diff --git a/Documentation/dynamic-debug-howto.txt b/Documentation/dynamic-debug-howto.txt
index 6e16849..b39a771 100644
--- a/Documentation/dynamic-debug-howto.txt
+++ b/Documentation/dynamic-debug-howto.txt
@@ -6,8 +6,12 @@ This document describes how to use the dynamic debug (dyndbg) feature.

Dynamic debug is designed to allow you to dynamically enable/disable
kernel code to obtain additional kernel information. Currently, if
-CONFIG_DYNAMIC_DEBUG is set, then all pr_debug()/dev_dbg() calls can
-be dynamically enabled per-callsite.
+CONFIG_DYNAMIC_DEBUG is set, then all pr_debug()/dev_dbg() and
+print_hex_dump_debug()/print_hex_dump_bytes() calls can be dynamically
+enabled per-callsite.
+
+If CONFIG_DYNAMIC_DEBUG is not set, print_hex_dump_debug() is just
+shortcut for print_hex_dump(KERN_DEBUG).

Dynamic debug has even more useful features:

@@ -202,6 +206,9 @@ The flags are:
t Include thread ID in messages not generated from interrupt context
_ No flags are set. (Or'd with others on input)

+For print_hex_dump_debug() and print_hex_dump_bytes(), only 'p' flag
+have meaning, other flags ignored.
+
For display, the flags are preceded by '='
(mnemonic: what the flags are currently equal to).

diff --git a/include/linux/dynamic_debug.h b/include/linux/dynamic_debug.h
index 6dd4787..17565ab 100644
--- a/include/linux/dynamic_debug.h
+++ b/include/linux/dynamic_debug.h
@@ -95,6 +95,16 @@ do { \
##__VA_ARGS__); \
} while (0)

+#define dynamic_hex_dump(prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii) \
+do { \
+ DEFINE_DYNAMIC_DEBUG_METADATA(descriptor, prefix_str); \
+ if (unlikely(descriptor.flags & _DPRINTK_FLAGS_PRINT)) \
+ print_hex_dump(KERN_DEBUG, prefix_str, \
+ prefix_type, rowsize, groupsize, \
+ buf, len, ascii); \
+} while (0)
+
#else

#include <linux/string.h>
diff --git a/include/linux/printk.h b/include/linux/printk.h
index 9afc01e..02c95cf 100644
--- a/include/linux/printk.h
+++ b/include/linux/printk.h
@@ -321,8 +321,13 @@ extern void hex_dump_to_buffer(const void *buf, size_t len,
extern void print_hex_dump(const char *level, const char *prefix_str,
int prefix_type, int rowsize, int groupsize,
const void *buf, size_t len, bool ascii);
+#if defined(CONFIG_DYNAMIC_DEBUG)
+#define print_hex_dump_bytes(prefix_str, prefix_type, buf, len) \
+ dynamic_hex_dump(prefix_str, prefix_type, 16, 1, buf, len, true)
+#else
extern void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
const void *buf, size_t len);
+#endif /* defined(CONFIG_DYNAMIC_DEBUG) */
#else
static inline void print_hex_dump(const char *level, const char *prefix_str,
int prefix_type, int rowsize, int groupsize,
@@ -336,4 +341,16 @@ static inline void print_hex_dump_bytes(const char *prefix_str, int prefix_type,

#endif

+#if defined(CONFIG_DYNAMIC_DEBUG)
+#define print_hex_dump_debug(prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii) \
+ dynamic_hex_dump(prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii)
+#else
+#define print_hex_dump_debug(prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii) \
+ print_hex_dump(KERN_DEBUG, prefix_str, prefix_type, rowsize, \
+ groupsize, buf, len, ascii)
+#endif /* defined(CONFIG_DYNAMIC_DEBUG) */
+
#endif
diff --git a/lib/hexdump.c b/lib/hexdump.c
index 6540d65..3f0494c 100644
--- a/lib/hexdump.c
+++ b/lib/hexdump.c
@@ -227,6 +227,7 @@ void print_hex_dump(const char *level, const char *prefix_str, int prefix_type,
}
EXPORT_SYMBOL(print_hex_dump);

+#if !defined(CONFIG_DYNAMIC_DEBUG)
/**
* print_hex_dump_bytes - shorthand form of print_hex_dump() with default params
* @prefix_str: string to prefix each line with;
@@ -246,4 +247,5 @@ void print_hex_dump_bytes(const char *prefix_str, int prefix_type,
buf, len, true);
}
EXPORT_SYMBOL(print_hex_dump_bytes);
-#endif
+#endif /* !defined(CONFIG_DYNAMIC_DEBUG) */
+#endif /* defined(CONFIG_PRINTK) */
--
1.7.10.4