[PATCH/RFC 0/3] ath5k: add driver tracepoints

[PATCH/RFC 0/3] ath5k: add driver tracepoints

[Bob Copeland]

This series adds some tracepoints for reset and tx/rx, with an
eye toward replacing some of the debug printks we have today.
Stolen form iwlwifi is the idea of logging entire packets so
we can generate pcap files from the traces, via something like:

    $ mkdir -p ~/.trace-cmd/plugins
    $ cd ~/.trace-cmd/plugins
    $ wget 'http://bobcopeland.com/srcs/ath5k_trace.py'
    $ trace-cmd record -e mac80211 -e ath5k sleep 500
    $ trace-cmd report | less
    $ wireshark /tmp/pcap.out

I quite like the result, but I'd be interested to hear others'
opinions on the approach.  Right now I think these tracepoints
will be useful in seeing causes of excessive resets, and debugging
queue hangs.

[PATCH/RFC 1/3] ath5k: log descriptor chains at a new debug level

[Bob Copeland]

Descriptors are currently logged with ATH5K_DEBUG_RESET,
which isn't really apt, and also means we can't see just
the descriptor setup or just the resets.  Add a new
debug level just for that.

Signed-off-by: Bob Copeland <me@bobcopeland.com>
---
 drivers/net/wireless/ath/ath5k/debug.c |    5 +++--
 drivers/net/wireless/ath/ath5k/debug.h |    2 ++
 2 files changed, 5 insertions(+), 2 deletions(-)

diff --git a/drivers/net/wireless/ath/ath5k/debug.c b/drivers/net/wireless/ath/ath5k/debug.c
index ebb9c23..2222022 100644
--- a/drivers/net/wireless/ath/ath5k/debug.c
+++ b/drivers/net/wireless/ath/ath5k/debug.c
@@ -309,6 +309,7 @@ static const struct {
 	{ ATH5K_DEBUG_DUMP_TX,	"dumptx",	"print transmit skb content" },
 	{ ATH5K_DEBUG_DUMPBANDS, "dumpbands",	"dump bands" },
 	{ ATH5K_DEBUG_ANI,	"ani",		"adaptive noise immunity" },
+	{ ATH5K_DEBUG_DESC,	"desc",		"descriptor chains" },
 	{ ATH5K_DEBUG_ANY,	"all",		"show all debug levels" },
 };
 
@@ -937,7 +938,7 @@ ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
 	struct ath5k_rx_status rs = {};
 	int status;
 
-	if (likely(!(sc->debug.level & ATH5K_DEBUG_RESET)))
+	if (likely(!(sc->debug.level & ATH5K_DEBUG_DESC)))
 		return;
 
 	printk(KERN_DEBUG "rxdp %x, rxlink %p\n",
@@ -979,7 +980,7 @@ ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct ath5k_buf *bf)
 	struct ath5k_tx_status ts = {};
 	int done;
 
-	if (likely(!(sc->debug.level & ATH5K_DEBUG_RESET)))
+	if (likely(!(sc->debug.level & ATH5K_DEBUG_DESC)))
 		return;
 
 	done = sc->ah->ah_proc_tx_desc(sc->ah, bf->desc, &ts);
diff --git a/drivers/net/wireless/ath/ath5k/debug.h b/drivers/net/wireless/ath/ath5k/debug.h
index 606ae94..9b22722 100644
--- a/drivers/net/wireless/ath/ath5k/debug.h
+++ b/drivers/net/wireless/ath/ath5k/debug.h
@@ -95,6 +95,7 @@ struct ath5k_dbg_info {
  * @ATH5K_DEBUG_DUMP_TX: print transmit skb content
  * @ATH5K_DEBUG_DUMPBANDS: dump bands
  * @ATH5K_DEBUG_TRACE: trace function calls
+ * @ATH5K_DEBUG_DESC: descriptor setup
  * @ATH5K_DEBUG_ANY: show at any debug level
  *
  * The debug level is used to control the amount and type of debugging output
@@ -117,6 +118,7 @@ enum ath5k_debug_level {
 	ATH5K_DEBUG_DUMP_TX	= 0x00000200,
 	ATH5K_DEBUG_DUMPBANDS	= 0x00000400,
 	ATH5K_DEBUG_ANI		= 0x00002000,
+	ATH5K_DEBUG_DESC	= 0x00004000,
 	ATH5K_DEBUG_ANY		= 0xffffffff
 };
 
-- 
1.7.1.1

[PATCH/RFC 2/3] ath5k: use tracing for packet tx/rx dump

[Bob Copeland]

This adds a few tracepoints to ath5k driver transmit and
receive callbacks in order to record packet traffic.

The advantage of this approach over the previous debug
statements in the kernel printk buffer is that the debug
information is no longer an out-of-line function call,
and the trace can be combined with mac80211 tracepoints.

We record the entire packet in the trace buffer so that
the data can be extracted with external scripts.

The corresponding debug dump functions are removed.

Signed-off-by: Bob Copeland <me@bobcopeland.com>
---
 drivers/net/wireless/ath/ath5k/ath5k_trace.h |   97 ++++++++++++++++++++++++++
 drivers/net/wireless/ath/ath5k/base.c        |   12 ++-
 drivers/net/wireless/ath/ath5k/debug.c       |   20 -----
 drivers/net/wireless/ath/ath5k/debug.h       |    4 -
 4 files changed, 105 insertions(+), 28 deletions(-)
 create mode 100644 drivers/net/wireless/ath/ath5k/ath5k_trace.h

diff --git a/drivers/net/wireless/ath/ath5k/ath5k_trace.h b/drivers/net/wireless/ath/ath5k/ath5k_trace.h
new file mode 100644
index 0000000..00d9773
--- /dev/null
+++ b/drivers/net/wireless/ath/ath5k/ath5k_trace.h
@@ -0,0 +1,97 @@
+#if !defined(__TRACE_ATH5K_H) || defined(TRACE_HEADER_MULTI_READ)
+#define __TRACE_ATH5K_H
+
+#include <linux/tracepoint.h>
+#include "base.h"
+
+struct sk_buff;
+
+#define PRIV_ENTRY  __field(struct ath5k_softc *, priv)
+#define PRIV_ASSIGN __entry->priv = priv
+
+#undef TRACE_SYSTEM
+#define TRACE_SYSTEM ath5k
+
+TRACE_EVENT(ath5k_rx,
+	TP_PROTO(struct ath5k_softc *priv, struct sk_buff *skb),
+	TP_ARGS(priv, skb),
+	TP_STRUCT__entry(
+		PRIV_ENTRY
+		__field(unsigned long, skbaddr)
+		__dynamic_array(u8, frame, skb->len)
+	),
+	TP_fast_assign(
+		PRIV_ASSIGN;
+		__entry->skbaddr = (unsigned long) skb;
+		memcpy(__get_dynamic_array(frame), skb->data, skb->len);
+	),
+	TP_printk(
+		"[%p] RX skb=%lx", __entry->priv, __entry->skbaddr
+	)
+);
+
+TRACE_EVENT(ath5k_tx,
+	TP_PROTO(struct ath5k_softc *priv, struct sk_buff *skb,
+		 struct ath5k_txq *q),
+
+	TP_ARGS(priv, skb, q),
+
+	TP_STRUCT__entry(
+		PRIV_ENTRY
+		__field(unsigned long, skbaddr)
+		__field(u8, qnum)
+		__dynamic_array(u8, frame, skb->len)
+	),
+
+	TP_fast_assign(
+		PRIV_ASSIGN;
+		__entry->skbaddr = (unsigned long) skb;
+		__entry->qnum = (u8) q->qnum;
+		memcpy(__get_dynamic_array(frame), skb->data, skb->len);
+	),
+
+	TP_printk(
+		"[%p] TX skb=%lx q=%d", __entry->priv, __entry->skbaddr,
+		__entry->qnum
+	)
+);
+
+TRACE_EVENT(ath5k_tx_complete,
+	TP_PROTO(struct ath5k_softc *priv, struct sk_buff *skb,
+		 struct ath5k_txq *q, struct ath5k_tx_status *ts),
+
+	TP_ARGS(priv, skb, q, ts),
+
+	TP_STRUCT__entry(
+		PRIV_ENTRY
+		__field(unsigned long, skbaddr)
+		__field(u8, qnum)
+		__field(u8, ts_status)
+		__field(s8, ts_rssi)
+		__field(u8, ts_antenna)
+	),
+
+	TP_fast_assign(
+		PRIV_ASSIGN;
+		__entry->skbaddr = (unsigned long) skb;
+		__entry->qnum = (u8) q->qnum;
+		__entry->ts_status = ts->ts_status;
+		__entry->ts_rssi =  ts->ts_rssi;
+		__entry->ts_antenna = ts->ts_antenna;
+	),
+
+	TP_printk(
+		"[%p] TX end skb=%lx q=%d stat=%x rssi=%d ant=%x",
+		__entry->priv, __entry->skbaddr, __entry->qnum,
+		__entry->ts_status, __entry->ts_rssi, __entry->ts_antenna
+	)
+);
+
+#endif /* _TRACE_ATH5K_H */
+
+#undef TRACE_INCLUDE_PATH
+#define TRACE_INCLUDE_PATH ../../drivers/net/wireless/ath/ath5k
+#undef TRACE_INCLUDE_FILE
+#define TRACE_INCLUDE_FILE ath5k_trace
+
+#include <trace/define_trace.h>
diff --git a/drivers/net/wireless/ath/ath5k/base.c b/drivers/net/wireless/ath/ath5k/base.c
index 0d5de25..23a5679 100644
--- a/drivers/net/wireless/ath/ath5k/base.c
+++ b/drivers/net/wireless/ath/ath5k/base.c
@@ -61,6 +61,9 @@
 #include "debug.h"
 #include "ani.h"
 
+#define CREATE_TRACE_POINTS
+#include "ath5k_trace.h"
+
 static int modparam_nohwcrypt;
 module_param_named(nohwcrypt, modparam_nohwcrypt, bool, S_IRUGO);
 MODULE_PARM_DESC(nohwcrypt, "Disable hardware encryption.");
@@ -1962,7 +1965,7 @@ ath5k_receive_frame(struct ath5k_softc *sc, struct sk_buff *skb,
 	    sc->curband->bitrates[rxs->rate_idx].hw_value_short)
 		rxs->flag |= RX_FLAG_SHORTPRE;
 
-	ath5k_debug_dump_skb(sc, skb, "RX  ", 0);
+	trace_ath5k_rx(sc, skb);
 
 	ath5k_update_beacon_rssi(sc, skb, rs->rs_rssi);
 
@@ -2183,6 +2186,7 @@ ath5k_tx_processq(struct ath5k_softc *sc, struct ath5k_txq *txq)
 		else
 			sc->stats.antenna_tx[0]++; /* invalid */
 
+		trace_ath5k_tx_complete(sc, skb, txq, &ts);
 		ieee80211_tx_status(sc->hw, skb);
 
 		spin_lock(&sc->txbuflock);
@@ -2352,6 +2356,8 @@ ath5k_beacon_send(struct ath5k_softc *sc)
 	if (sc->opmode == NL80211_IFTYPE_AP)
 		ath5k_beacon_update(sc->hw, sc->vif);
 
+	trace_ath5k_tx(sc, bf->skb, &sc->txqs[sc->bhalq]);
+
 	ath5k_hw_set_txdp(ah, sc->bhalq, bf->daddr);
 	ath5k_hw_start_tx_dma(ah, sc->bhalq);
 	ATH5K_DBG(sc, ATH5K_DEBUG_BEACON, "TXDP[%u] = %llx (%p)\n",
@@ -2878,7 +2884,7 @@ static int ath5k_tx_queue(struct ieee80211_hw *hw, struct sk_buff *skb,
 	unsigned long flags;
 	int padsize;
 
-	ath5k_debug_dump_skb(sc, skb, "TX  ", 1);
+	trace_ath5k_tx(sc, skb, txq);
 
 	if (sc->opmode == NL80211_IFTYPE_MONITOR)
 		ATH5K_DBG(sc, ATH5K_DEBUG_XMIT, "tx in monitor (scan?)\n");
@@ -3410,8 +3416,6 @@ ath5k_beacon_update(struct ieee80211_hw *hw, struct ieee80211_vif *vif)
 		goto out;
 	}
 
-	ath5k_debug_dump_skb(sc, skb, "BC  ", 1);
-
 	ath5k_txbuf_free_skb(sc, sc->bbuf);
 	sc->bbuf->skb = skb;
 	ret = ath5k_beacon_setup(sc, sc->bbuf);
diff --git a/drivers/net/wireless/ath/ath5k/debug.c b/drivers/net/wireless/ath/ath5k/debug.c
index 2222022..d107cd6 100644
--- a/drivers/net/wireless/ath/ath5k/debug.c
+++ b/drivers/net/wireless/ath/ath5k/debug.c
@@ -305,8 +305,6 @@ static const struct {
 	{ ATH5K_DEBUG_CALIBRATE, "calib",	"periodic calibration" },
 	{ ATH5K_DEBUG_TXPOWER,	"txpower",	"transmit power setting" },
 	{ ATH5K_DEBUG_LED,	"led",		"LED management" },
-	{ ATH5K_DEBUG_DUMP_RX,	"dumprx",	"print received skb content" },
-	{ ATH5K_DEBUG_DUMP_TX,	"dumptx",	"print transmit skb content" },
 	{ ATH5K_DEBUG_DUMPBANDS, "dumpbands",	"dump bands" },
 	{ ATH5K_DEBUG_ANI,	"ani",		"adaptive noise immunity" },
 	{ ATH5K_DEBUG_DESC,	"desc",		"descriptor chains" },
@@ -955,24 +953,6 @@ ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
 }
 
 void
-ath5k_debug_dump_skb(struct ath5k_softc *sc,
-			struct sk_buff *skb, const char *prefix, int tx)
-{
-	char buf[16];
-
-	if (likely(!((tx && (sc->debug.level & ATH5K_DEBUG_DUMP_TX)) ||
-		     (!tx && (sc->debug.level & ATH5K_DEBUG_DUMP_RX)))))
-		return;
-
-	snprintf(buf, sizeof(buf), "%s %s", wiphy_name(sc->hw->wiphy), prefix);
-
-	print_hex_dump_bytes(buf, DUMP_PREFIX_NONE, skb->data,
-		min(200U, skb->len));
-
-	printk(KERN_DEBUG "\n");
-}
-
-void
 ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct ath5k_buf *bf)
 {
 	struct ath5k_desc *ds = bf->desc;
diff --git a/drivers/net/wireless/ath/ath5k/debug.h b/drivers/net/wireless/ath/ath5k/debug.h
index 9b22722..c260b00 100644
--- a/drivers/net/wireless/ath/ath5k/debug.h
+++ b/drivers/net/wireless/ath/ath5k/debug.h
@@ -91,8 +91,6 @@ struct ath5k_dbg_info {
  * @ATH5K_DEBUG_CALIBRATE: periodic calibration
  * @ATH5K_DEBUG_TXPOWER: transmit power setting
  * @ATH5K_DEBUG_LED: led management
- * @ATH5K_DEBUG_DUMP_RX: print received skb content
- * @ATH5K_DEBUG_DUMP_TX: print transmit skb content
  * @ATH5K_DEBUG_DUMPBANDS: dump bands
  * @ATH5K_DEBUG_TRACE: trace function calls
  * @ATH5K_DEBUG_DESC: descriptor setup
@@ -114,8 +112,6 @@ enum ath5k_debug_level {
 	ATH5K_DEBUG_CALIBRATE	= 0x00000020,
 	ATH5K_DEBUG_TXPOWER	= 0x00000040,
 	ATH5K_DEBUG_LED		= 0x00000080,
-	ATH5K_DEBUG_DUMP_RX	= 0x00000100,
-	ATH5K_DEBUG_DUMP_TX	= 0x00000200,
 	ATH5K_DEBUG_DUMPBANDS	= 0x00000400,
 	ATH5K_DEBUG_ANI		= 0x00002000,
 	ATH5K_DEBUG_DESC	= 0x00004000,
-- 
1.7.1.1

[PATCH/RFC 3/3] ath5k: trace resets

[Bob Copeland]

This change adds a tracepoint for ath5k_reset.  We record the
reason for each reset and the new channel frequency.

Signed-off-by: Bob Copeland <me@bobcopeland.com>
---
 drivers/net/wireless/ath/ath5k/ath5k_trace.h |   38 +++++++++++++++++
 drivers/net/wireless/ath/ath5k/base.c        |   56 +++++++-------------------
 drivers/net/wireless/ath/ath5k/base.h        |   12 ++++++
 drivers/net/wireless/ath/ath5k/debug.c       |    7 ++-
 drivers/net/wireless/ath/ath5k/debug.h       |    2 -
 5 files changed, 70 insertions(+), 45 deletions(-)

diff --git a/drivers/net/wireless/ath/ath5k/ath5k_trace.h b/drivers/net/wireless/ath/ath5k/ath5k_trace.h
index 00d9773..3a5112d 100644
--- a/drivers/net/wireless/ath/ath5k/ath5k_trace.h
+++ b/drivers/net/wireless/ath/ath5k/ath5k_trace.h
@@ -12,6 +12,44 @@ struct sk_buff;
 #undef TRACE_SYSTEM
 #define TRACE_SYSTEM ath5k
 
+TRACE_EVENT(ath5k_reset,
+	TP_PROTO(struct ath5k_softc *priv, struct ieee80211_channel *chan,
+		 enum ath5k_reset_reason reason),
+
+	TP_ARGS(priv, chan, reason),
+	TP_STRUCT__entry(
+		PRIV_ENTRY
+		__field(u32, reason)
+		__field(u16, freq)
+	),
+	TP_fast_assign(
+		PRIV_ASSIGN;
+		__entry->reason = reason;
+		__entry->freq = chan->center_freq;
+	),
+	TP_printk(
+		"[%p] reset reason=%d freq=%u", __entry->priv,
+		__entry->reason, __entry->freq
+	)
+);
+
+TRACE_EVENT(ath5k_reset_end,
+	TP_PROTO(struct ath5k_softc *priv, int result),
+
+	TP_ARGS(priv, result),
+	TP_STRUCT__entry(
+		PRIV_ENTRY
+		__field(s32, result)
+	),
+	TP_fast_assign(
+		PRIV_ASSIGN;
+		__entry->result = (s32) result;
+	),
+	TP_printk(
+		"[%p] reset ret=%d", __entry->priv, __entry->result
+	)
+);
+
 TRACE_EVENT(ath5k_rx,
 	TP_PROTO(struct ath5k_softc *priv, struct sk_buff *skb),
 	TP_ARGS(priv, skb),
diff --git a/drivers/net/wireless/ath/ath5k/base.c b/drivers/net/wireless/ath/ath5k/base.c
index 23a5679..44732b5 100644
--- a/drivers/net/wireless/ath/ath5k/base.c
+++ b/drivers/net/wireless/ath/ath5k/base.c
@@ -224,7 +224,8 @@ static struct pci_driver ath5k_pci_driver = {
 static int ath5k_tx(struct ieee80211_hw *hw, struct sk_buff *skb);
 static int ath5k_tx_queue(struct ieee80211_hw *hw, struct sk_buff *skb,
 		struct ath5k_txq *txq);
-static int ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan);
+static int ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan,
+		       enum ath5k_reset_reason ath5k_reset_reason);
 static int ath5k_start(struct ieee80211_hw *hw);
 static void ath5k_stop(struct ieee80211_hw *hw);
 static int ath5k_add_interface(struct ieee80211_hw *hw,
@@ -1120,17 +1121,13 @@ ath5k_setup_bands(struct ieee80211_hw *hw)
 static int
 ath5k_chan_set(struct ath5k_softc *sc, struct ieee80211_channel *chan)
 {
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
-		  "channel set, resetting (%u -> %u MHz)\n",
-		  sc->curchan->center_freq, chan->center_freq);
-
 	/*
 	 * To switch channels clear any pending DMA operations;
 	 * wait long enough for the RX fifo to drain, reset the
 	 * hardware at the new frequency, and then re-enable
 	 * the relevant bits of the h/w.
 	 */
-	return ath5k_reset(sc, chan);
+	return ath5k_reset(sc, chan, RESET_SET_CHANNEL);
 }
 
 static void
@@ -1615,8 +1612,6 @@ ath5k_txq_drainq(struct ath5k_softc *sc, struct ath5k_txq *txq)
 	 */
 	spin_lock_bh(&txq->lock);
 	list_for_each_entry_safe(bf, bf0, &txq->q, list) {
-		ath5k_debug_printtxbuf(sc, bf);
-
 		ath5k_txbuf_free_skb(sc, bf);
 
 		spin_lock_bh(&sc->txbuflock);
@@ -1641,18 +1636,9 @@ ath5k_txq_cleanup(struct ath5k_softc *sc)
 	if (likely(!test_bit(ATH_STAT_INVALID, sc->status))) {
 		/* don't touch the hardware if marked invalid */
 		ath5k_hw_stop_tx_dma(ah, sc->bhalq);
-		ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "beacon queue %x\n",
-			ath5k_hw_get_txdp(ah, sc->bhalq));
 		for (i = 0; i < ARRAY_SIZE(sc->txqs); i++)
-			if (sc->txqs[i].setup) {
+			if (sc->txqs[i].setup)
 				ath5k_hw_stop_tx_dma(ah, sc->txqs[i].qnum);
-				ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "txq [%u] %x, "
-					"link %p\n",
-					sc->txqs[i].qnum,
-					ath5k_hw_get_txdp(ah,
-							sc->txqs[i].qnum),
-					sc->txqs[i].link);
-			}
 	}
 
 	for (i = 0; i < ARRAY_SIZE(sc->txqs); i++)
@@ -1693,9 +1679,6 @@ ath5k_rx_start(struct ath5k_softc *sc)
 
 	common->rx_bufsize = roundup(IEEE80211_MAX_LEN, common->cachelsz);
 
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "cachelsz %u rx_bufsize %u\n",
-		  common->cachelsz, common->rx_bufsize);
-
 	spin_lock_bh(&sc->rxbuflock);
 	sc->rxlink = NULL;
 	list_for_each_entry(bf, &sc->rxbuf, list) {
@@ -2329,8 +2312,7 @@ ath5k_beacon_send(struct ath5k_softc *sc)
 			ATH5K_DBG(sc, ATH5K_DEBUG_BEACON,
 				"stuck beacon time (%u missed)\n",
 				sc->bmisscount);
-			ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
-				  "stuck beacon, resetting\n");
+			sc->reset_reason = RESET_STUCK_BEACON;
 			ieee80211_queue_work(sc->hw, &sc->reset_work);
 		}
 		return;
@@ -2561,8 +2543,6 @@ ath5k_init(struct ath5k_softc *sc)
 
 	mutex_lock(&sc->lock);
 
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "mode %d\n", sc->opmode);
-
 	/*
 	 * Stop anything previously setup.  This is safe
 	 * no matter this is the first time through or not.
@@ -2582,7 +2562,7 @@ ath5k_init(struct ath5k_softc *sc)
 		AR5K_INT_RXORN | AR5K_INT_TXDESC | AR5K_INT_TXEOL |
 		AR5K_INT_FATAL | AR5K_INT_GLOBAL | AR5K_INT_MIB;
 
-	ret = ath5k_reset(sc, NULL);
+	ret = ath5k_reset(sc, NULL, RESET_INIT);
 	if (ret)
 		goto done;
 
@@ -2608,9 +2588,6 @@ ath5k_stop_locked(struct ath5k_softc *sc)
 {
 	struct ath5k_hw *ah = sc->ah;
 
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "invalid %u\n",
-			test_bit(ATH_STAT_INVALID, sc->status));
-
 	/*
 	 * Shutdown the hardware and driver:
 	 *    stop output from above
@@ -2686,9 +2663,6 @@ ath5k_stop_hw(struct ath5k_softc *sc)
 		 * on the device (same as initial state after attach) and
 		 * leave it idle (keep MAC/BB on warm reset) */
 		ret = ath5k_hw_on_hold(sc->ah);
-
-		ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
-				"putting device to sleep\n");
 	}
 	ath5k_txbuf_free_skb(sc, sc->bbuf);
 
@@ -2743,8 +2717,7 @@ ath5k_intr(int irq, void *dev_id)
 			 * Fatal errors are unrecoverable.
 			 * Typically these are caused by DMA errors.
 			 */
-			ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
-				  "fatal int, resetting\n");
+			sc->reset_reason = RESET_FATAL;
 			ieee80211_queue_work(sc->hw, &sc->reset_work);
 		} else if (unlikely(status & AR5K_INT_RXORN)) {
 			/*
@@ -2758,8 +2731,7 @@ ath5k_intr(int irq, void *dev_id)
 			 */
 			sc->stats.rxorn_intr++;
 			if (ah->ah_mac_srev < AR5K_SREV_AR5212) {
-				ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
-					  "rx overrun, resetting\n");
+				sc->reset_reason = RESET_RXORN;
 				ieee80211_queue_work(sc->hw, &sc->reset_work);
 			}
 			else
@@ -2829,7 +2801,7 @@ ath5k_tasklet_calibrate(unsigned long data)
 		 * Rfgain is out of bounds, reset the chip
 		 * to load new gain values.
 		 */
-		ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "calibration, resetting\n");
+		sc->reset_reason = RESET_CALIBRATION;
 		ieee80211_queue_work(sc->hw, &sc->reset_work);
 	}
 	if (ath5k_hw_phy_calibrate(ah, sc->curchan))
@@ -2938,12 +2910,13 @@ drop_packet:
  * This should be called with sc->lock.
  */
 static int
-ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan)
+ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan,
+            enum ath5k_reset_reason reason)
 {
 	struct ath5k_hw *ah = sc->ah;
 	int ret;
 
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "resetting\n");
+	trace_ath5k_reset(sc, chan, reason);
 
 	ath5k_hw_set_imr(ah, 0);
 	synchronize_irq(sc->pdev->irq);
@@ -2990,8 +2963,9 @@ ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan)
 
 	ieee80211_wake_queues(sc->hw);
 
-	return 0;
+	ret = 0;
 err:
+	trace_ath5k_reset_end(sc, ret);
 	return ret;
 }
 
@@ -3001,7 +2975,7 @@ static void ath5k_reset_work(struct work_struct *work)
 		reset_work);
 
 	mutex_lock(&sc->lock);
-	ath5k_reset(sc, sc->curchan);
+	ath5k_reset(sc, sc->curchan, sc->reset_reason);
 	mutex_unlock(&sc->lock);
 }
 
diff --git a/drivers/net/wireless/ath/ath5k/base.h b/drivers/net/wireless/ath/ath5k/base.h
index dc1241f..cb6e2be 100644
--- a/drivers/net/wireless/ath/ath5k/base.h
+++ b/drivers/net/wireless/ath/ath5k/base.h
@@ -140,6 +140,17 @@ struct ath5k_statistics {
 	unsigned int rxeol_intr;
 };
 
+/* Reset tracing */
+enum ath5k_reset_reason {
+	RESET_INIT,
+	RESET_SET_CHANNEL,
+	RESET_STUCK_BEACON,
+	RESET_FATAL,
+	RESET_RXORN,
+	RESET_CALIBRATION,
+	RESET_DEBUGFS,
+};
+
 #if CHAN_DEBUG
 #define ATH_CHAN_MAX	(26+26+26+200+200)
 #else
@@ -192,6 +203,7 @@ struct ath5k_softc {
 				led_on;		/* pin setting for LED on */
 
 	struct work_struct	reset_work;	/* deferred chip reset */
+	enum ath5k_reset_reason	reset_reason;	/* reason for resetting */
 
 	unsigned int		rxbufsize;	/* rx size based on mtu */
 	struct list_head	rxbuf;		/* receive buffer */
diff --git a/drivers/net/wireless/ath/ath5k/debug.c b/drivers/net/wireless/ath/ath5k/debug.c
index d107cd6..9ddbfd5 100644
--- a/drivers/net/wireless/ath/ath5k/debug.c
+++ b/drivers/net/wireless/ath/ath5k/debug.c
@@ -278,7 +278,7 @@ static ssize_t write_file_reset(struct file *file,
 				 size_t count, loff_t *ppos)
 {
 	struct ath5k_softc *sc = file->private_data;
-	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "debug file triggered reset\n");
+	sc->reset_reason = RESET_DEBUGFS;
 	ieee80211_queue_work(sc->hw, &sc->reset_work);
 	return count;
 }
@@ -297,7 +297,6 @@ static const struct {
 	const char *name;
 	const char *desc;
 } dbg_info[] = {
-	{ ATH5K_DEBUG_RESET,	"reset",	"reset and initialization" },
 	{ ATH5K_DEBUG_INTR,	"intr",		"interrupt handling" },
 	{ ATH5K_DEBUG_MODE,	"mode",		"mode init/setup" },
 	{ ATH5K_DEBUG_XMIT,	"xmit",		"basic xmit operation" },
@@ -931,6 +930,7 @@ ath5k_debug_printrxbuf(struct ath5k_buf *bf, int done,
 void
 ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
 {
+#if 0
 	struct ath5k_desc *ds;
 	struct ath5k_buf *bf;
 	struct ath5k_rx_status rs = {};
@@ -950,11 +950,13 @@ ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
 			ath5k_debug_printrxbuf(bf, status == 0, &rs);
 	}
 	spin_unlock_bh(&sc->rxbuflock);
+#endif
 }
 
 void
 ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct ath5k_buf *bf)
 {
+#if 0
 	struct ath5k_desc *ds = bf->desc;
 	struct ath5k_hw_5212_tx_desc *td = &ds->ud.ds_tx5212;
 	struct ath5k_tx_status ts = {};
@@ -971,6 +973,7 @@ ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct ath5k_buf *bf)
 		td->tx_ctl.tx_control_2, td->tx_ctl.tx_control_3,
 		td->tx_stat.tx_status_0, td->tx_stat.tx_status_1,
 		done ? ' ' : (ts.ts_status == 0) ? '*' : '!');
+#endif
 }
 
 #endif /* ifdef CONFIG_ATH5K_DEBUG */
diff --git a/drivers/net/wireless/ath/ath5k/debug.h b/drivers/net/wireless/ath/ath5k/debug.h
index c260b00..8a484f2 100644
--- a/drivers/net/wireless/ath/ath5k/debug.h
+++ b/drivers/net/wireless/ath/ath5k/debug.h
@@ -83,7 +83,6 @@ struct ath5k_dbg_info {
 /**
  * enum ath5k_debug_level - ath5k debug level
  *
- * @ATH5K_DEBUG_RESET: reset processing
  * @ATH5K_DEBUG_INTR: interrupt handling
  * @ATH5K_DEBUG_MODE: mode init/setup
  * @ATH5K_DEBUG_XMIT: basic xmit operation
@@ -104,7 +103,6 @@ struct ath5k_dbg_info {
  * be combined together by bitwise OR.
  */
 enum ath5k_debug_level {
-	ATH5K_DEBUG_RESET	= 0x00000001,
 	ATH5K_DEBUG_INTR	= 0x00000002,
 	ATH5K_DEBUG_MODE	= 0x00000004,
 	ATH5K_DEBUG_XMIT	= 0x00000008,
-- 
1.7.1.1

Re: [PATCH/RFC 1/3] ath5k: log descriptor chains at a new debug level

[Bruno Randolf]

On Sun July 18 2010 04:35:34 Bob Copeland wrote:
> Descriptors are currently logged with ATH5K_DEBUG_RESET,
> which isn't really apt, and also means we can't see just
> the descriptor setup or just the resets.  Add a new
> debug level just for that.
> 
> Signed-off-by: Bob Copeland <me@bobcopeland.com>
> ---
>  drivers/net/wireless/ath/ath5k/debug.c |    5 +++--
>  drivers/net/wireless/ath/ath5k/debug.h |    2 ++
>  2 files changed, 5 insertions(+), 2 deletions(-)
> 
> diff --git a/drivers/net/wireless/ath/ath5k/debug.c
> b/drivers/net/wireless/ath/ath5k/debug.c index ebb9c23..2222022 100644
> --- a/drivers/net/wireless/ath/ath5k/debug.c
> +++ b/drivers/net/wireless/ath/ath5k/debug.c
> @@ -309,6 +309,7 @@ static const struct {
>  	{ ATH5K_DEBUG_DUMP_TX,	"dumptx",	"print transmit skb content" },
>  	{ ATH5K_DEBUG_DUMPBANDS, "dumpbands",	"dump bands" },
>  	{ ATH5K_DEBUG_ANI,	"ani",		"adaptive noise immunity" },
> +	{ ATH5K_DEBUG_DESC,	"desc",		"descriptor chains" },
>  	{ ATH5K_DEBUG_ANY,	"all",		"show all debug levels" },
>  };
> 
> @@ -937,7 +938,7 @@ ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct
> ath5k_hw *ah) struct ath5k_rx_status rs = {};
>  	int status;
> 
> -	if (likely(!(sc->debug.level & ATH5K_DEBUG_RESET)))
> +	if (likely(!(sc->debug.level & ATH5K_DEBUG_DESC)))
>  		return;
> 
>  	printk(KERN_DEBUG "rxdp %x, rxlink %p\n",
> @@ -979,7 +980,7 @@ ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct
> ath5k_buf *bf) struct ath5k_tx_status ts = {};
>  	int done;
> 
> -	if (likely(!(sc->debug.level & ATH5K_DEBUG_RESET)))
> +	if (likely(!(sc->debug.level & ATH5K_DEBUG_DESC)))
>  		return;
> 
>  	done = sc->ah->ah_proc_tx_desc(sc->ah, bf->desc, &ts);
> diff --git a/drivers/net/wireless/ath/ath5k/debug.h
> b/drivers/net/wireless/ath/ath5k/debug.h index 606ae94..9b22722 100644
> --- a/drivers/net/wireless/ath/ath5k/debug.h
> +++ b/drivers/net/wireless/ath/ath5k/debug.h
> @@ -95,6 +95,7 @@ struct ath5k_dbg_info {
>   * @ATH5K_DEBUG_DUMP_TX: print transmit skb content
>   * @ATH5K_DEBUG_DUMPBANDS: dump bands
>   * @ATH5K_DEBUG_TRACE: trace function calls
> + * @ATH5K_DEBUG_DESC: descriptor setup
>   * @ATH5K_DEBUG_ANY: show at any debug level
>   *
>   * The debug level is used to control the amount and type of debugging
> output @@ -117,6 +118,7 @@ enum ath5k_debug_level {
>  	ATH5K_DEBUG_DUMP_TX	= 0x00000200,
>  	ATH5K_DEBUG_DUMPBANDS	= 0x00000400,
>  	ATH5K_DEBUG_ANI		= 0x00002000,
> +	ATH5K_DEBUG_DESC	= 0x00004000,
>  	ATH5K_DEBUG_ANY		= 0xffffffff
>  };

Acked-by: Bruno Randolf <br1@einfach.org>

Re: [ath5k-devel] [PATCH/RFC 0/3] ath5k: add driver tracepoints

[Bruno Randolf]

On Sun July 18 2010 04:35:33 Bob Copeland wrote:
> This series adds some tracepoints for reset and tx/rx, with an
> eye toward replacing some of the debug printks we have today.
> Stolen form iwlwifi is the idea of logging entire packets so
> we can generate pcap files from the traces, via something like:
> 
>     $ mkdir -p ~/.trace-cmd/plugins
>     $ cd ~/.trace-cmd/plugins
>     $ wget 'http://bobcopeland.com/srcs/ath5k_trace.py'
>     $ trace-cmd record -e mac80211 -e ath5k sleep 500
>     $ trace-cmd report | less
>     $ wireshark /tmp/pcap.out
> 
> I quite like the result, but I'd be interested to hear others'
> opinions on the approach.  Right now I think these tracepoints
> will be useful in seeing causes of excessive resets, and debugging
> queue hangs.

hmm, this is really nice stuff, but i'm not sure what to do on embedded boards 
where we don't have python or where it's not possible to use tracing in 
general due to (low) performance reasons. in these cases the kernel printks 
are just so much more easy to use... i would actually prefer to keep them... 
additionally to the new tracing you made, maybe? otoh we could probably get 
tracing enabled on all boards if we really need it, it's just some extra 
work...

bruno

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bruno Randolf]

On Sun July 18 2010 04:35:36 Bob Copeland wrote:
> This change adds a tracepoint for ath5k_reset.  We record the
> reason for each reset and the new channel frequency.
> 
> Signed-off-by: Bob Copeland <me@bobcopeland.com>
> ---
>  drivers/net/wireless/ath/ath5k/ath5k_trace.h |   38 +++++++++++++++++
>  drivers/net/wireless/ath/ath5k/base.c        |   56
> +++++++------------------- drivers/net/wireless/ath/ath5k/base.h        | 
>  12 ++++++
>  drivers/net/wireless/ath/ath5k/debug.c       |    7 ++-
>  drivers/net/wireless/ath/ath5k/debug.h       |    2 -
>  5 files changed, 70 insertions(+), 45 deletions(-)
> 
> diff --git a/drivers/net/wireless/ath/ath5k/ath5k_trace.h
> b/drivers/net/wireless/ath/ath5k/ath5k_trace.h index 00d9773..3a5112d
> 100644
> --- a/drivers/net/wireless/ath/ath5k/ath5k_trace.h
> +++ b/drivers/net/wireless/ath/ath5k/ath5k_trace.h
> @@ -12,6 +12,44 @@ struct sk_buff;
>  #undef TRACE_SYSTEM
>  #define TRACE_SYSTEM ath5k
> 
> +TRACE_EVENT(ath5k_reset,
> +	TP_PROTO(struct ath5k_softc *priv, struct ieee80211_channel *chan,
> +		 enum ath5k_reset_reason reason),
> +
> +	TP_ARGS(priv, chan, reason),
> +	TP_STRUCT__entry(
> +		PRIV_ENTRY
> +		__field(u32, reason)
> +		__field(u16, freq)
> +	),
> +	TP_fast_assign(
> +		PRIV_ASSIGN;
> +		__entry->reason = reason;
> +		__entry->freq = chan->center_freq;
> +	),
> +	TP_printk(
> +		"[%p] reset reason=%d freq=%u", __entry->priv,
> +		__entry->reason, __entry->freq
> +	)
> +);
> +
> +TRACE_EVENT(ath5k_reset_end,
> +	TP_PROTO(struct ath5k_softc *priv, int result),
> +
> +	TP_ARGS(priv, result),
> +	TP_STRUCT__entry(
> +		PRIV_ENTRY
> +		__field(s32, result)
> +	),
> +	TP_fast_assign(
> +		PRIV_ASSIGN;
> +		__entry->result = (s32) result;
> +	),
> +	TP_printk(
> +		"[%p] reset ret=%d", __entry->priv, __entry->result
> +	)
> +);
> +
>  TRACE_EVENT(ath5k_rx,
>  	TP_PROTO(struct ath5k_softc *priv, struct sk_buff *skb),
>  	TP_ARGS(priv, skb),
> diff --git a/drivers/net/wireless/ath/ath5k/base.c
> b/drivers/net/wireless/ath/ath5k/base.c index 23a5679..44732b5 100644
> --- a/drivers/net/wireless/ath/ath5k/base.c
> +++ b/drivers/net/wireless/ath/ath5k/base.c
> @@ -224,7 +224,8 @@ static struct pci_driver ath5k_pci_driver = {
>  static int ath5k_tx(struct ieee80211_hw *hw, struct sk_buff *skb);
>  static int ath5k_tx_queue(struct ieee80211_hw *hw, struct sk_buff *skb,
>  		struct ath5k_txq *txq);
> -static int ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel
> *chan); +static int ath5k_reset(struct ath5k_softc *sc, struct
> ieee80211_channel *chan, +		       enum ath5k_reset_reason
> ath5k_reset_reason);
>  static int ath5k_start(struct ieee80211_hw *hw);
>  static void ath5k_stop(struct ieee80211_hw *hw);
>  static int ath5k_add_interface(struct ieee80211_hw *hw,
> @@ -1120,17 +1121,13 @@ ath5k_setup_bands(struct ieee80211_hw *hw)
>  static int
>  ath5k_chan_set(struct ath5k_softc *sc, struct ieee80211_channel *chan)
>  {
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
> -		  "channel set, resetting (%u -> %u MHz)\n",
> -		  sc->curchan->center_freq, chan->center_freq);
> -
>  	/*
>  	 * To switch channels clear any pending DMA operations;
>  	 * wait long enough for the RX fifo to drain, reset the
>  	 * hardware at the new frequency, and then re-enable
>  	 * the relevant bits of the h/w.
>  	 */
> -	return ath5k_reset(sc, chan);
> +	return ath5k_reset(sc, chan, RESET_SET_CHANNEL);
>  }
> 
>  static void
> @@ -1615,8 +1612,6 @@ ath5k_txq_drainq(struct ath5k_softc *sc, struct
> ath5k_txq *txq) */
>  	spin_lock_bh(&txq->lock);
>  	list_for_each_entry_safe(bf, bf0, &txq->q, list) {
> -		ath5k_debug_printtxbuf(sc, bf);
> -
>  		ath5k_txbuf_free_skb(sc, bf);
> 
>  		spin_lock_bh(&sc->txbuflock);
> @@ -1641,18 +1636,9 @@ ath5k_txq_cleanup(struct ath5k_softc *sc)
>  	if (likely(!test_bit(ATH_STAT_INVALID, sc->status))) {
>  		/* don't touch the hardware if marked invalid */
>  		ath5k_hw_stop_tx_dma(ah, sc->bhalq);
> -		ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "beacon queue %x\n",
> -			ath5k_hw_get_txdp(ah, sc->bhalq));
>  		for (i = 0; i < ARRAY_SIZE(sc->txqs); i++)
> -			if (sc->txqs[i].setup) {
> +			if (sc->txqs[i].setup)
>  				ath5k_hw_stop_tx_dma(ah, sc->txqs[i].qnum);
> -				ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "txq [%u] %x, "
> -					"link %p\n",
> -					sc->txqs[i].qnum,
> -					ath5k_hw_get_txdp(ah,
> -							sc->txqs[i].qnum),
> -					sc->txqs[i].link);
> -			}
>  	}
> 
>  	for (i = 0; i < ARRAY_SIZE(sc->txqs); i++)
> @@ -1693,9 +1679,6 @@ ath5k_rx_start(struct ath5k_softc *sc)
> 
>  	common->rx_bufsize = roundup(IEEE80211_MAX_LEN, common->cachelsz);
> 
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "cachelsz %u rx_bufsize %u\n",
> -		  common->cachelsz, common->rx_bufsize);
> -
>  	spin_lock_bh(&sc->rxbuflock);
>  	sc->rxlink = NULL;
>  	list_for_each_entry(bf, &sc->rxbuf, list) {
> @@ -2329,8 +2312,7 @@ ath5k_beacon_send(struct ath5k_softc *sc)
>  			ATH5K_DBG(sc, ATH5K_DEBUG_BEACON,
>  				"stuck beacon time (%u missed)\n",
>  				sc->bmisscount);
> -			ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
> -				  "stuck beacon, resetting\n");
> +			sc->reset_reason = RESET_STUCK_BEACON;
>  			ieee80211_queue_work(sc->hw, &sc->reset_work);
>  		}
>  		return;
> @@ -2561,8 +2543,6 @@ ath5k_init(struct ath5k_softc *sc)
> 
>  	mutex_lock(&sc->lock);
> 
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "mode %d\n", sc->opmode);
> -
>  	/*
>  	 * Stop anything previously setup.  This is safe
>  	 * no matter this is the first time through or not.
> @@ -2582,7 +2562,7 @@ ath5k_init(struct ath5k_softc *sc)
>  		AR5K_INT_RXORN | AR5K_INT_TXDESC | AR5K_INT_TXEOL |
>  		AR5K_INT_FATAL | AR5K_INT_GLOBAL | AR5K_INT_MIB;
> 
> -	ret = ath5k_reset(sc, NULL);
> +	ret = ath5k_reset(sc, NULL, RESET_INIT);
>  	if (ret)
>  		goto done;
> 
> @@ -2608,9 +2588,6 @@ ath5k_stop_locked(struct ath5k_softc *sc)
>  {
>  	struct ath5k_hw *ah = sc->ah;
> 
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "invalid %u\n",
> -			test_bit(ATH_STAT_INVALID, sc->status));
> -
>  	/*
>  	 * Shutdown the hardware and driver:
>  	 *    stop output from above
> @@ -2686,9 +2663,6 @@ ath5k_stop_hw(struct ath5k_softc *sc)
>  		 * on the device (same as initial state after attach) and
>  		 * leave it idle (keep MAC/BB on warm reset) */
>  		ret = ath5k_hw_on_hold(sc->ah);
> -
> -		ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
> -				"putting device to sleep\n");
>  	}
>  	ath5k_txbuf_free_skb(sc, sc->bbuf);
> 
> @@ -2743,8 +2717,7 @@ ath5k_intr(int irq, void *dev_id)
>  			 * Fatal errors are unrecoverable.
>  			 * Typically these are caused by DMA errors.
>  			 */
> -			ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
> -				  "fatal int, resetting\n");
> +			sc->reset_reason = RESET_FATAL;
>  			ieee80211_queue_work(sc->hw, &sc->reset_work);
>  		} else if (unlikely(status & AR5K_INT_RXORN)) {
>  			/*
> @@ -2758,8 +2731,7 @@ ath5k_intr(int irq, void *dev_id)
>  			 */
>  			sc->stats.rxorn_intr++;
>  			if (ah->ah_mac_srev < AR5K_SREV_AR5212) {
> -				ATH5K_DBG(sc, ATH5K_DEBUG_RESET,
> -					  "rx overrun, resetting\n");
> +				sc->reset_reason = RESET_RXORN;
>  				ieee80211_queue_work(sc->hw, &sc->reset_work);
>  			}
>  			else
> @@ -2829,7 +2801,7 @@ ath5k_tasklet_calibrate(unsigned long data)
>  		 * Rfgain is out of bounds, reset the chip
>  		 * to load new gain values.
>  		 */
> -		ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "calibration, resetting\n");
> +		sc->reset_reason = RESET_CALIBRATION;
>  		ieee80211_queue_work(sc->hw, &sc->reset_work);
>  	}
>  	if (ath5k_hw_phy_calibrate(ah, sc->curchan))
> @@ -2938,12 +2910,13 @@ drop_packet:
>   * This should be called with sc->lock.
>   */
>  static int
> -ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan)
> +ath5k_reset(struct ath5k_softc *sc, struct ieee80211_channel *chan,
> +            enum ath5k_reset_reason reason)
>  {
>  	struct ath5k_hw *ah = sc->ah;
>  	int ret;
> 
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "resetting\n");
> +	trace_ath5k_reset(sc, chan, reason);
> 
>  	ath5k_hw_set_imr(ah, 0);
>  	synchronize_irq(sc->pdev->irq);
> @@ -2990,8 +2963,9 @@ ath5k_reset(struct ath5k_softc *sc, struct
> ieee80211_channel *chan)
> 
>  	ieee80211_wake_queues(sc->hw);
> 
> -	return 0;
> +	ret = 0;
>  err:
> +	trace_ath5k_reset_end(sc, ret);
>  	return ret;
>  }
> 
> @@ -3001,7 +2975,7 @@ static void ath5k_reset_work(struct work_struct
> *work) reset_work);
> 
>  	mutex_lock(&sc->lock);
> -	ath5k_reset(sc, sc->curchan);
> +	ath5k_reset(sc, sc->curchan, sc->reset_reason);
>  	mutex_unlock(&sc->lock);
>  }
> 
> diff --git a/drivers/net/wireless/ath/ath5k/base.h
> b/drivers/net/wireless/ath/ath5k/base.h index dc1241f..cb6e2be 100644
> --- a/drivers/net/wireless/ath/ath5k/base.h
> +++ b/drivers/net/wireless/ath/ath5k/base.h
> @@ -140,6 +140,17 @@ struct ath5k_statistics {
>  	unsigned int rxeol_intr;
>  };
> 
> +/* Reset tracing */
> +enum ath5k_reset_reason {
> +	RESET_INIT,
> +	RESET_SET_CHANNEL,
> +	RESET_STUCK_BEACON,
> +	RESET_FATAL,
> +	RESET_RXORN,
> +	RESET_CALIBRATION,
> +	RESET_DEBUGFS,
> +};
> +
>  #if CHAN_DEBUG
>  #define ATH_CHAN_MAX	(26+26+26+200+200)
>  #else
> @@ -192,6 +203,7 @@ struct ath5k_softc {
>  				led_on;		/* pin setting for LED on */
> 
>  	struct work_struct	reset_work;	/* deferred chip reset */
> +	enum ath5k_reset_reason	reset_reason;	/* reason for resetting */
> 
>  	unsigned int		rxbufsize;	/* rx size based on mtu */
>  	struct list_head	rxbuf;		/* receive buffer */
> diff --git a/drivers/net/wireless/ath/ath5k/debug.c
> b/drivers/net/wireless/ath/ath5k/debug.c index d107cd6..9ddbfd5 100644
> --- a/drivers/net/wireless/ath/ath5k/debug.c
> +++ b/drivers/net/wireless/ath/ath5k/debug.c
> @@ -278,7 +278,7 @@ static ssize_t write_file_reset(struct file *file,
>  				 size_t count, loff_t *ppos)
>  {
>  	struct ath5k_softc *sc = file->private_data;
> -	ATH5K_DBG(sc, ATH5K_DEBUG_RESET, "debug file triggered reset\n");
> +	sc->reset_reason = RESET_DEBUGFS;
>  	ieee80211_queue_work(sc->hw, &sc->reset_work);
>  	return count;
>  }
> @@ -297,7 +297,6 @@ static const struct {
>  	const char *name;
>  	const char *desc;
>  } dbg_info[] = {
> -	{ ATH5K_DEBUG_RESET,	"reset",	"reset and initialization" },
>  	{ ATH5K_DEBUG_INTR,	"intr",		"interrupt handling" },
>  	{ ATH5K_DEBUG_MODE,	"mode",		"mode init/setup" },
>  	{ ATH5K_DEBUG_XMIT,	"xmit",		"basic xmit operation" },
> @@ -931,6 +930,7 @@ ath5k_debug_printrxbuf(struct ath5k_buf *bf, int done,
>  void
>  ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
>  {
> +#if 0
>  	struct ath5k_desc *ds;
>  	struct ath5k_buf *bf;
>  	struct ath5k_rx_status rs = {};
> @@ -950,11 +950,13 @@ ath5k_debug_printrxbuffs(struct ath5k_softc *sc,
> struct ath5k_hw *ah) ath5k_debug_printrxbuf(bf, status == 0, &rs);
>  	}
>  	spin_unlock_bh(&sc->rxbuflock);
> +#endif
>  }
> 
>  void
>  ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct ath5k_buf *bf)
>  {
> +#if 0
>  	struct ath5k_desc *ds = bf->desc;
>  	struct ath5k_hw_5212_tx_desc *td = &ds->ud.ds_tx5212;
>  	struct ath5k_tx_status ts = {};
> @@ -971,6 +973,7 @@ ath5k_debug_printtxbuf(struct ath5k_softc *sc, struct
> ath5k_buf *bf) td->tx_ctl.tx_control_2, td->tx_ctl.tx_control_3,
>  		td->tx_stat.tx_status_0, td->tx_stat.tx_status_1,
>  		done ? ' ' : (ts.ts_status == 0) ? '*' : '!');
> +#endif
>  }
> 
>  #endif /* ifdef CONFIG_ATH5K_DEBUG */
> diff --git a/drivers/net/wireless/ath/ath5k/debug.h
> b/drivers/net/wireless/ath/ath5k/debug.h index c260b00..8a484f2 100644
> --- a/drivers/net/wireless/ath/ath5k/debug.h
> +++ b/drivers/net/wireless/ath/ath5k/debug.h
> @@ -83,7 +83,6 @@ struct ath5k_dbg_info {
>  /**
>   * enum ath5k_debug_level - ath5k debug level
>   *
> - * @ATH5K_DEBUG_RESET: reset processing
>   * @ATH5K_DEBUG_INTR: interrupt handling
>   * @ATH5K_DEBUG_MODE: mode init/setup
>   * @ATH5K_DEBUG_XMIT: basic xmit operation
> @@ -104,7 +103,6 @@ struct ath5k_dbg_info {
>   * be combined together by bitwise OR.
>   */
>  enum ath5k_debug_level {
> -	ATH5K_DEBUG_RESET	= 0x00000001,
>  	ATH5K_DEBUG_INTR	= 0x00000002,
>  	ATH5K_DEBUG_MODE	= 0x00000004,
>  	ATH5K_DEBUG_XMIT	= 0x00000008,

again, here my same concerns: printing the reasons for resets is something 
which is useful on embedded boards and production setups which can't have 
tracing enabled. which is why i want to object against this change!

also adding a reason argument to the reset function just for tracing seems to 
be... umm... not so nice... couldn't you add the tracepoints before? 
and: didn't we want to split channel change out of reset anyhow?

bruno

Re: [ath5k-devel] [PATCH/RFC 0/3] ath5k: add driver tracepoints

[Johannes Berg]

On Tue, 2010-07-20 at 14:11 +0900, Bruno Randolf wrote:

> hmm, this is really nice stuff, but i'm not sure what to do on embedded boards 
> where we don't have python or where it's not possible to use tracing in 
> general due to (low) performance reasons

err, tracing has much better performance than printk, and you can get
the trace into a file that you can analyse offline on a "real" machine.
No need for python on the board, and tracing improves performance over
printk.

johannes

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bob Copeland]

On Tue, Jul 20, 2010 at 02:20:49PM +0900, Bruno Randolf wrote:
> > @@ -931,6 +930,7 @@ ath5k_debug_printrxbuf(struct ath5k_buf *bf, int done,
> >  void
> >  ath5k_debug_printrxbuffs(struct ath5k_softc *sc, struct ath5k_hw *ah)
> >  {
> > +#if 0

(The above, by the way, is a mistake I'll fix; I forgot to remove it after
doing patch 1/3.)

> again, here my same concerns: printing the reasons for resets is something 
> which is useful on embedded boards and production setups which can't have 
> tracing enabled. which is why i want to object against this change!

What Johannes said wrt performance: during tracing, only the binary
representations of the data are written to the trace ring buffer, so
unlike the current debug code, we aren't doing printk formatting until
the trace buffer is read.  You can save the raw binary data from the
trace and do formatting on another machine.

Another advantage is better granularity: if you only care about watching
tx on the cab queue, you can dynamically filter based on the tracepoint
arguments, something like:

  # echo "qnum == 6" > /debug/tracing/events/ath5k/ath5k_tx/filter

With the debug printks, you have to hack the driver or grep and hope
the printk buffer didn't overflow and spill what you were looking for.

One thing I do need to look into is reducing the size, right now
text size went up by about 4k when adding these tracepoints.

> also adding a reason argument to the reset function just for tracing seems to 
> be... umm... not so nice... couldn't you add the tracepoints before? 

Yeah, it's kind of hacky, but not without precedent; ieee80211_wake_queues
does something similar.  But I'm not tied to it, adding another tracepoint
for when and why the reset was scheduled would be OK, or maybe we just
drop the reason and plan on using ftrace to figure that out.  It's still
worth keeping tracepoints when reset actually runs and finishes since that
is the most useful information for tracking down race conditions.

> and: didn't we want to split channel change out of reset anyhow?

Of course.  When we do so we probably won't need the frequency argument,
but I think that's otherwise orthogonal to this...

-- 
Bob Copeland %% www.bobcopeland.com

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bruno Randolf]

On Tue July 20 2010 23:52:00 Bob Copeland wrote:
> > again, here my same concerns: printing the reasons for resets is
> > something which is useful on embedded boards and production setups which
> > can't have tracing enabled. which is why i want to object against this
> > change!
> 
> What Johannes said wrt performance: during tracing, only the binary
> representations of the data are written to the trace ring buffer, so
> unlike the current debug code, we aren't doing printk formatting until
> the trace buffer is read.  You can save the raw binary data from the
> trace and do formatting on another machine.

that's true, but try to run a kernel with tracing compiled in and NOT runtime 
enabled on a small embedded board (soekris net48xx for example) and you'll see 
the difference. without tracing you can get 22Mbps, with tracing max 15Mbps 
UDP thruput. that means you cannot run a kernel with tracing enabled on a 
production system, which also means you cannot log the reasons for a reset 
there any more. and most of the problems we what to trace (e.g. stuck queue) 
happen only after days or weeks of operation in production environments...
 
> Another advantage is better granularity: if you only care about watching
> tx on the cab queue, you can dynamically filter based on the tracepoint
> arguments, something like:
> 
>   # echo "qnum == 6" > /debug/tracing/events/ath5k/ath5k_tx/filter
> 
> With the debug printks, you have to hack the driver or grep and hope
> the printk buffer didn't overflow and spill what you were looking for.

no doubt, i can see the advantages...

so let's go ahead with tracing, since we can always build less performant 
tracing kernels when we want to track down problems.

bruno

Re: [ath5k-devel] [PATCH/RFC 3/3] ath5k: trace resets

[Luis R. Rodriguez]

On Tue, Jul 20, 2010 at 06:04:59PM -0700, Bruno Randolf wrote:
> On Tue July 20 2010 23:52:00 Bob Copeland wrote:
> > > again, here my same concerns: printing the reasons for resets is
> > > something which is useful on embedded boards and production setups which
> > > can't have tracing enabled. which is why i want to object against this
> > > change!
> > 
> > What Johannes said wrt performance: during tracing, only the binary
> > representations of the data are written to the trace ring buffer, so
> > unlike the current debug code, we aren't doing printk formatting until
> > the trace buffer is read.  You can save the raw binary data from the
> > trace and do formatting on another machine.
> 
> that's true, but try to run a kernel with tracing compiled in and NOT runtime 
> enabled on a small embedded board (soekris net48xx for example) and you'll see 
> the difference. without tracing you can get 22Mbps, with tracing max 15Mbps 
> UDP thruput. that means you cannot run a kernel with tracing enabled on a 
> production system, which also means you cannot log the reasons for a reset 
> there any more. and most of the problems we what to trace (e.g. stuck queue) 
> happen only after days or weeks of operation in production environments...
>  
> > Another advantage is better granularity: if you only care about watching
> > tx on the cab queue, you can dynamically filter based on the tracepoint
> > arguments, something like:
> > 
> >   # echo "qnum == 6" > /debug/tracing/events/ath5k/ath5k_tx/filter
> > 
> > With the debug printks, you have to hack the driver or grep and hope
> > the printk buffer didn't overflow and spill what you were looking for.
> 
> no doubt, i can see the advantages...
> 
> so let's go ahead with tracing, since we can always build less performant 
> tracing kernels when we want to track down problems.

FWIW I intend on adding tracing as well to ath9k_hw on the hw-ops.
Hence the hw-ops.h file, etc.

  Luis

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bob Copeland]

On Wed, Jul 21, 2010 at 10:04:59AM +0900, Bruno Randolf wrote:
> the difference. without tracing you can get 22Mbps, with tracing max 15Mbps 
> UDP thruput.

If so, and it's not an i-cache effect, then something is wrong with
the tracing subsystem.  It's supposed to compile to something like

if (tracing) {
   trace_callback();
}

That is exactly what we have with the debug infrastructure, but
the debug stuff is theoretically a bit worse since it tests for
tracing inside the callback.

Oh well, I guess I need to get my hands on one of these boards.

-- 
Bob Copeland %% www.bobcopeland.com

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bruno Randolf]

On Wed July 21 2010 12:41:50 Bob Copeland wrote:
> On Wed, Jul 21, 2010 at 10:04:59AM +0900, Bruno Randolf wrote:
> > the difference. without tracing you can get 22Mbps, with tracing max
> > 15Mbps UDP thruput.
> 
> If so, and it's not an i-cache effect, then something is wrong with
> the tracing subsystem.  It's supposed to compile to something like
> 
> if (tracing) {
>    trace_callback();
> }
> 
> That is exactly what we have with the debug infrastructure, but
> the debug stuff is theoretically a bit worse since it tests for
> tracing inside the callback.

but that's for all tracepoints all over the kernel... i think it's natural 
that this takes some CPU time. note that on these boards even the 22Mbps are 
limited by the CPU processing power.

> Oh well, I guess I need to get my hands on one of these boards.

could be helpful, allthough i have to admit that these boards are getting old 
and more current embedded boards usually do have faster CPUs...

bruno

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Ben Gamari]

On Wed, 21 Jul 2010 14:17:23 +0900, Bruno Randolf <br1@einfach.org> wrote:
> but that's for all tracepoints all over the kernel... i think it's natural 
> that this takes some CPU time. note that on these boards even the 22Mbps are 
> limited by the CPU processing power.
> 
The key word here is some. The numbers that you pointed out suggest that
the effect here is quite large. I find it hard to believe that something
isn't going wrong here. A single branch instruction really shouldn't be
this onerous unless it's in a fast path, in which case it should
probably be a compile-time option. What is the difference in image size
between kernels with and without tracing?

- Ben

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Johannes Berg]

On Wed, 2010-07-21 at 14:17 +0900, Bruno Randolf wrote:

> but that's for all tracepoints all over the kernel...

Well you definitely don't want to enable like function graph tracing,
that's expected to be more expensive unless you also have the callsite
patching version of it. But _just_ enabling tracing + the ath5k tracer
definitely will not have this effect.

johannes

Re: [PATCH/RFC 3/3] ath5k: trace resets

[Bruno Randolf]

On Wed July 21 2010 16:53:21 Johannes Berg wrote:
> On Wed, 2010-07-21 at 14:17 +0900, Bruno Randolf wrote:
> > but that's for all tracepoints all over the kernel...
> 
> Well you definitely don't want to enable like function graph tracing,
> that's expected to be more expensive unless you also have the callsite
> patching version of it. But _just_ enabling tracing + the ath5k tracer
> definitely will not have this effect.

true. i just checked it again and enabling tracing does not affect the 
performance as i have wrongly stated before. i must have had some other 
debugging stuff enabled as well. sorry...

bruno