Date: Mon, 24 Sep 2012 20:35:57 +0000 (UTC) From: Adrian Chadd <adrian@FreeBSD.org> To: src-committers@freebsd.org, svn-src-all@freebsd.org, svn-src-head@freebsd.org Subject: svn commit: r240899 - head/sys/dev/ath Message-ID: <201209242035.q8OKZvUM093772@svn.freebsd.org>
next in thread | raw e-mail | index | archive | help
Author: adrian Date: Mon Sep 24 20:35:56 2012 New Revision: 240899 URL: http://svn.freebsd.org/changeset/base/240899 Log: Migrate the ath(4) KTR logging to use an ATH_KTR() macro. This should eventually be unified with ATH_DEBUG() so I can get both from one macro; that may take some time. Add some new probes for TX and TX completion. Modified: head/sys/dev/ath/if_ath.c head/sys/dev/ath/if_ath_debug.h head/sys/dev/ath/if_ath_rx.c head/sys/dev/ath/if_ath_rx_edma.c head/sys/dev/ath/if_ath_sysctl.c head/sys/dev/ath/if_ath_tx.c head/sys/dev/ath/if_athvar.h Modified: head/sys/dev/ath/if_ath.c ============================================================================== --- head/sys/dev/ath/if_ath.c Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath.c Mon Sep 24 20:35:56 2012 (r240899) @@ -1519,9 +1519,9 @@ ath_intr(void *arg) */ ath_hal_getisr(ah, &status); /* NB: clears ISR too */ DPRINTF(sc, ATH_DEBUG_INTR, "%s: status 0x%x\n", __func__, status); - CTR1(ATH_KTR_INTR, "ath_intr: mask=0x%.8x", status); + ATH_KTR(sc, ATH_KTR_INTERRUPTS, 1, "ath_intr: mask=0x%.8x", status); #ifdef ATH_KTR_INTR_DEBUG - CTR5(ATH_KTR_INTR, + ATH_KTR(sc, ATH_KTR_INTERRUPTS, 5, "ath_intr: ISR=0x%.8x, ISR_S0=0x%.8x, ISR_S1=0x%.8x, ISR_S2=0x%.8x, ISR_S5=0x%.8x", ah->ah_intrstate[0], ah->ah_intrstate[1], @@ -1597,7 +1597,7 @@ ath_intr(void *arg) } if (status & HAL_INT_RXEOL) { int imask; - CTR0(ATH_KTR_ERR, "ath_intr: RXEOL"); + ATH_KTR(sc, ATH_KTR_ERROR, 0, "ath_intr: RXEOL"); ATH_PCU_LOCK(sc); /* * NB: the hardware should re-read the link when @@ -1663,6 +1663,11 @@ ath_intr(void *arg) ATH_PCU_LOCK(sc); txqs = 0xffffffff; ath_hal_gettxintrtxqs(sc->sc_ah, &txqs); + ATH_KTR(sc, ATH_KTR_INTERRUPTS, 3, + "ath_intr: TX; txqs=0x%08x, txq_active was 0x%08x, now 0x%08x", + txqs, + sc->sc_txq_active, + sc->sc_txq_active | txqs); sc->sc_txq_active |= txqs; ATH_PCU_UNLOCK(sc); } @@ -1701,7 +1706,7 @@ ath_intr(void *arg) } if (status & HAL_INT_RXORN) { /* NB: hal marks HAL_INT_FATAL when RXORN is fatal */ - CTR0(ATH_KTR_ERR, "ath_intr: RXORN"); + ATH_KTR(sc, ATH_KTR_ERROR, 0, "ath_intr: RXORN"); sc->sc_stats.ast_rxorn++; } } @@ -3637,6 +3642,14 @@ ath_tx_processq(struct ath_softc *sc, st __func__, txq->axq_qnum, (caddr_t)(uintptr_t) ath_hal_gettxbuf(sc->sc_ah, txq->axq_qnum), txq->axq_link); + + ATH_KTR(sc, ATH_KTR_TXCOMP, 4, + "ath_tx_processq: txq=%u head %p link %p depth %p", + txq->axq_qnum, + (caddr_t)(uintptr_t) ath_hal_gettxbuf(sc->sc_ah, txq->axq_qnum), + txq->axq_link, + txq->axq_depth); + nacked = 0; for (;;) { ATH_TXQ_LOCK(txq); @@ -3648,17 +3661,21 @@ ath_tx_processq(struct ath_softc *sc, st } ds = bf->bf_lastds; /* XXX must be setup correctly! */ ts = &bf->bf_status.ds_txstat; + status = ath_hal_txprocdesc(ah, ds, ts); #ifdef ATH_DEBUG if (sc->sc_debug & ATH_DEBUG_XMIT_DESC) ath_printtxbuf(sc, bf, txq->axq_qnum, 0, status == HAL_OK); - else if ((sc->sc_debug & ATH_DEBUG_RESET) && (dosched == 0)) { + else if ((sc->sc_debug & ATH_DEBUG_RESET) && (dosched == 0)) ath_printtxbuf(sc, bf, txq->axq_qnum, 0, status == HAL_OK); - } #endif + if (status == HAL_EINPROGRESS) { + ATH_KTR(sc, ATH_KTR_TXCOMP, 3, + "ath_tx_processq: txq=%u, bf=%p ds=%p, HAL_EINPROGRESS", + txq->axq_qnum, bf, ds); ATH_TXQ_UNLOCK(txq); break; } @@ -3684,6 +3701,10 @@ ath_tx_processq(struct ath_softc *sc, st txq->axq_aggr_depth--; ni = bf->bf_node; + + ATH_KTR(sc, ATH_KTR_TXCOMP, 5, + "ath_tx_processq: txq=%u, bf=%p, ds=%p, ni=%p, ts_status=0x%08x", + txq->axq_qnum, bf, ds, ni, ts->ts_status); /* * If unicast frame was ack'd update RSSI, * including the last rx time used to @@ -3702,8 +3723,6 @@ ath_tx_processq(struct ath_softc *sc, st * Update statistics and call completion */ ath_tx_process_buf_completion(sc, txq, ts, bf); - - } #ifdef IEEE80211_SUPPORT_SUPERG /* @@ -3720,6 +3739,10 @@ ath_tx_processq(struct ath_softc *sc, st ATH_TXQ_UNLOCK(txq); } + ATH_KTR(sc, ATH_KTR_TXCOMP, 1, + "ath_tx_processq: txq=%u: done", + txq->axq_qnum); + return nacked; } @@ -3742,6 +3765,9 @@ ath_tx_proc_q0(void *arg, int npending) sc->sc_txq_active &= ~txqs; ATH_PCU_UNLOCK(sc); + ATH_KTR(sc, ATH_KTR_TXCOMP, 1, + "ath_tx_proc_q0: txqs=0x%08x", txqs); + if (TXQACTIVE(txqs, 0) && ath_tx_processq(sc, &sc->sc_txq[0], 1)) /* XXX why is lastrx updated in tx code? */ sc->sc_lastrx = ath_hal_gettsf64(sc->sc_ah); @@ -3780,6 +3806,9 @@ ath_tx_proc_q0123(void *arg, int npendin sc->sc_txq_active &= ~txqs; ATH_PCU_UNLOCK(sc); + ATH_KTR(sc, ATH_KTR_TXCOMP, 1, + "ath_tx_proc_q0123: txqs=0x%08x", txqs); + /* * Process each active queue. */ @@ -3829,6 +3858,8 @@ ath_tx_proc(void *arg, int npending) sc->sc_txq_active &= ~txqs; ATH_PCU_UNLOCK(sc); + ATH_KTR(sc, ATH_KTR_TXCOMP, 1, "ath_tx_proc: txqs=0x%08x", txqs); + /* * Process each active queue. */ Modified: head/sys/dev/ath/if_ath_debug.h ============================================================================== --- head/sys/dev/ath/if_ath_debug.h Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath_debug.h Mon Sep 24 20:35:56 2012 (r240899) @@ -70,8 +70,21 @@ enum { ATH_DEBUG_ANY = 0xffffffffffffffffULL }; -#define ATH_KTR_INTR KTR_SPARE4 -#define ATH_KTR_ERR KTR_SPARE3 +enum { + ATH_KTR_RXPROC = 0x00000001, + ATH_KTR_TXPROC = 0x00000002, + ATH_KTR_TXCOMP = 0x00000004, + ATH_KTR_SWQ = 0x00000008, + ATH_KTR_INTERRUPTS = 0x00000010, + ATH_KTR_ERROR = 0x00000020, + ATH_KTR_NODE = 0x00000040, + ATH_KTR_TX = 0x00000080, +}; + +#define ATH_KTR(_sc, _km, _kf, ...) do { \ + if (sc->sc_ktrdebug & (_km)) \ + CTR##_kf(KTR_DEV, __VA_ARGS__); \ + } while (0) extern uint64_t ath_debug; @@ -92,8 +105,7 @@ extern void ath_printrxbuf(struct ath_so extern void ath_printtxbuf(struct ath_softc *, const struct ath_buf *bf, u_int qnum, u_int ix, int done); #else /* ATH_DEBUG */ -#define ATH_KTR_INTR 0 -#define ATH_KTR_ERR 0 +#define ATH_KTR(_sc, _km, _kf, ...) do { } while (0) #define IFF_DUMPPKTS(sc, m) \ ((sc->sc_ifp->if_flags & (IFF_DEBUG|IFF_LINK2)) == (IFF_DEBUG|IFF_LINK2)) Modified: head/sys/dev/ath/if_ath_rx.c ============================================================================== --- head/sys/dev/ath/if_ath_rx.c Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath_rx.c Mon Sep 24 20:35:56 2012 (r240899) @@ -900,7 +900,7 @@ rx_proc_next: if (ngood) sc->sc_lastrx = tsf; - CTR2(ATH_KTR_INTR, "ath_rx_proc: npkts=%d, ngood=%d", npkts, ngood); + ATH_KTR(sc, ATH_KTR_RXPROC, 2, "ath_rx_proc: npkts=%d, ngood=%d", npkts, ngood); /* Queue DFS tasklet if needed */ if (resched && ath_dfs_tasklet_needed(sc, sc->sc_curchan)) taskqueue_enqueue(sc->sc_tq, &sc->sc_dfstask); @@ -912,7 +912,7 @@ rx_proc_next: */ ATH_PCU_LOCK(sc); if (resched && sc->sc_kickpcu) { - CTR0(ATH_KTR_ERR, "ath_rx_proc: kickpcu"); + ATH_KTR(sc, ATH_KTR_ERROR, 0, "ath_rx_proc: kickpcu"); device_printf(sc->sc_dev, "%s: kickpcu; handled %d packets\n", __func__, npkts); @@ -957,7 +957,7 @@ ath_legacy_rx_tasklet(void *arg, int npe { struct ath_softc *sc = arg; - CTR1(ATH_KTR_INTR, "ath_rx_proc: pending=%d", npending); + ATH_KTR(sc, ATH_KTR_RXPROC, 1, "ath_rx_proc: pending=%d", npending); DPRINTF(sc, ATH_DEBUG_RX_PROC, "%s: pending %u\n", __func__, npending); ATH_PCU_LOCK(sc); if (sc->sc_inreset_cnt > 0) { Modified: head/sys/dev/ath/if_ath_rx_edma.c ============================================================================== --- head/sys/dev/ath/if_ath_rx_edma.c Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath_rx_edma.c Mon Sep 24 20:35:56 2012 (r240899) @@ -421,13 +421,15 @@ ath_edma_recv_proc_queue(struct ath_soft if (ngood) sc->sc_lastrx = tsf; - CTR2(ATH_KTR_INTR, "ath edma rx proc: npkts=%d, ngood=%d", + ATH_KTR(sc, ATH_KTR_INTERRUPTS, 2, + "ath edma rx proc: npkts=%d, ngood=%d", npkts, ngood); /* Handle resched and kickpcu appropriately */ ATH_PCU_LOCK(sc); if (dosched && sc->sc_kickpcu) { - CTR0(ATH_KTR_ERR, "ath_edma_recv_proc_queue(): kickpcu"); + ATH_KTR(sc, ATH_KTR_ERROR, 0, + "ath_edma_recv_proc_queue(): kickpcu"); device_printf(sc->sc_dev, "%s: handled npkts %d ngood %d\n", __func__, npkts, ngood); Modified: head/sys/dev/ath/if_ath_sysctl.c ============================================================================== --- head/sys/dev/ath/if_ath_sysctl.c Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath_sysctl.c Mon Sep 24 20:35:56 2012 (r240899) @@ -518,6 +518,9 @@ ath_sysctlattach(struct ath_softc *sc) SYSCTL_ADD_QUAD(ctx, SYSCTL_CHILDREN(tree), OID_AUTO, "debug", CTLFLAG_RW, &sc->sc_debug, "control debugging printfs"); + SYSCTL_ADD_QUAD(ctx, SYSCTL_CHILDREN(tree), OID_AUTO, + "ktrdebug", CTLFLAG_RW, &sc->sc_ktrdebug, + "control debugging KTR"); #endif SYSCTL_ADD_PROC(ctx, SYSCTL_CHILDREN(tree), OID_AUTO, "slottime", CTLTYPE_INT | CTLFLAG_RW, sc, 0, Modified: head/sys/dev/ath/if_ath_tx.c ============================================================================== --- head/sys/dev/ath/if_ath_tx.c Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_ath_tx.c Mon Sep 24 20:35:56 2012 (r240899) @@ -722,6 +722,10 @@ ath_tx_handoff_hw(struct ath_softc *sc, ATH_TXQ_INSERT_TAIL(txq, bf, bf_list); qbusy = ath_hal_txqenabled(ah, txq->axq_qnum); + + ATH_KTR(sc, ATH_KTR_TX, 4, + "ath_tx_handoff: txq=%u, add bf=%p, qbusy=%d, depth=%d", + txq->axq_qnum, bf, qbusy, txq->axq_depth); if (txq->axq_link == NULL) { /* * Be careful writing the address to TXDP. If @@ -738,15 +742,24 @@ ath_tx_handoff_hw(struct ath_softc *sc, bf->bf_daddr); txq->axq_flags &= ~ATH_TXQ_PUTPENDING; DPRINTF(sc, ATH_DEBUG_XMIT, - "%s: TXDP[%u] = %p (%p) depth %d\n", + "%s: TXDP[%u] = %p (%p) lastds=%p depth %d\n", __func__, txq->axq_qnum, (caddr_t)bf->bf_daddr, bf->bf_desc, + bf->bf_lastds, + txq->axq_depth); + ATH_KTR(sc, ATH_KTR_TX, 5, + "ath_tx_handoff: TXDP[%u] = %p (%p) " + "lastds=%p depth %d", + txq->axq_qnum, + (caddr_t)bf->bf_daddr, bf->bf_desc, + bf->bf_lastds, txq->axq_depth); } else { txq->axq_flags |= ATH_TXQ_PUTPENDING; DPRINTF(sc, ATH_DEBUG_TDMA | ATH_DEBUG_XMIT, "%s: Q%u busy, defer enable\n", __func__, txq->axq_qnum); + ATH_KTR(sc, ATH_KTR_TX, 0, "defer enable"); } } else { *txq->axq_link = bf->bf_daddr; @@ -755,6 +768,12 @@ ath_tx_handoff_hw(struct ath_softc *sc, txq->axq_qnum, txq->axq_link, (caddr_t)bf->bf_daddr, bf->bf_desc, txq->axq_depth); + ATH_KTR(sc, ATH_KTR_TX, 5, + "ath_tx_handoff: link[%u](%p)=%p (%p) lastds=%p", + txq->axq_qnum, txq->axq_link, + (caddr_t)bf->bf_daddr, bf->bf_desc, + bf->bf_lastds); + if ((txq->axq_flags & ATH_TXQ_PUTPENDING) && !qbusy) { /* * The q was busy when we previously tried @@ -771,10 +790,24 @@ ath_tx_handoff_hw(struct ath_softc *sc, DPRINTF(sc, ATH_DEBUG_TDMA | ATH_DEBUG_XMIT, "%s: Q%u restarted\n", __func__, txq->axq_qnum); + ATH_KTR(sc, ATH_KTR_TX, 4, + "ath_tx_handoff: txq[%d] restarted, bf=%p " + "daddr=%p ds=%p", + txq->axq_qnum, + bf, + (caddr_t)bf->bf_daddr, + bf->bf_desc); } } #else ATH_TXQ_INSERT_TAIL(txq, bf, bf_list); + ATH_KTR(sc, ATH_KTR_TX, 4, + "ath_tx_handoff: non-tdma: txq=%u, add bf=%p, qbusy=%d, " + "depth=%d", + txq->axq_qnum, + bf, + qbusy, + txq->axq_depth); if (txq->axq_link == NULL) { ath_hal_puttxbuf(ah, txq->axq_qnum, bf->bf_daddr); DPRINTF(sc, ATH_DEBUG_XMIT, @@ -782,6 +815,14 @@ ath_tx_handoff_hw(struct ath_softc *sc, __func__, txq->axq_qnum, (caddr_t)bf->bf_daddr, bf->bf_desc, txq->axq_depth); + ATH_KTR(sc, ATH_KTR_TX, 5, + "ath_tx_handoff: non-tdma: TXDP[%u] = %p (%p) " + "lastds=%p depth %d", + txq->axq_qnum, + (caddr_t)bf->bf_daddr, bf->bf_desc, + bf->bf_lastds, + txq->axq_depth); + } else { *txq->axq_link = bf->bf_daddr; DPRINTF(sc, ATH_DEBUG_XMIT, @@ -789,12 +830,21 @@ ath_tx_handoff_hw(struct ath_softc *sc, txq->axq_qnum, txq->axq_link, (caddr_t)bf->bf_daddr, bf->bf_desc, txq->axq_depth); + ATH_KTR(sc, ATH_KTR_TX, 5, + "ath_tx_handoff: non-tdma: link[%u](%p)=%p (%p) " + "lastds=%d", + txq->axq_qnum, txq->axq_link, + (caddr_t)bf->bf_daddr, bf->bf_desc, + bf->bf_lastds); + } #endif /* IEEE80211_SUPPORT_TDMA */ if (bf->bf_state.bfs_aggr) txq->axq_aggr_depth++; ath_hal_gettxdesclinkptr(ah, bf->bf_lastds, &txq->axq_link); ath_hal_txstart(ah, txq->axq_qnum); + ATH_KTR(sc, ATH_KTR_TX, 1, + "ath_tx_handoff: txq=%u, txstart", txq->axq_qnum); } } @@ -1875,6 +1925,9 @@ ath_tx_raw_start(struct ath_softc *sc, s /* XXX honor IEEE80211_BPF_DATAPAD */ pktlen = m0->m_pkthdr.len - (hdrlen & 3) + IEEE80211_CRC_LEN; + ATH_KTR(sc, ATH_KTR_TX, 2, + "ath_tx_raw_start: ni=%p, bf=%p, raw", ni, bf); + DPRINTF(sc, ATH_DEBUG_SW_TX, "%s: ismcast=%d\n", __func__, ismcast); @@ -2132,6 +2185,8 @@ ath_raw_xmit(struct ieee80211_node *ni, error = ENOBUFS; goto bad; } + ATH_KTR(sc, ATH_KTR_TX, 3, "ath_raw_xmit: m=%p, params=%p, bf=%p\n", + m, params, bf); if (params == NULL) { /* @@ -2162,6 +2217,11 @@ ath_raw_xmit(struct ieee80211_node *ni, return 0; bad2: + ATH_KTR(sc, ATH_KTR_TX, 3, "ath_raw_xmit: bad2: m=%p, params=%p, " + "bf=%p", + m, + params, + bf); ATH_TXBUF_LOCK(sc); ath_returnbuf_head(sc, bf); ATH_TXBUF_UNLOCK(sc); @@ -2170,6 +2230,8 @@ bad: sc->sc_txstart_cnt--; ATH_PCU_UNLOCK(sc); bad0: + ATH_KTR(sc, ATH_KTR_TX, 2, "ath_raw_xmit: bad0: m=%p, params=%p", + m, params); ifp->if_oerrors++; sc->sc_stats.ast_tx_raw_fail++; ieee80211_free_node(ni); @@ -2752,6 +2814,7 @@ ath_tx_swq(struct ath_softc *sc, struct DPRINTF(sc, ATH_DEBUG_SW_TX, "%s: ampdu; swq'ing\n", __func__); + ath_tx_tid_sched(sc, atid); } } else if (txq->axq_depth < sc->sc_hwq_limit) { @@ -3240,7 +3303,7 @@ ath_tx_tid_drain_pkt(struct ath_softc *s static void ath_tx_tid_drain_print(struct ath_softc *sc, struct ath_node *an, - struct ath_tid *tid, struct ath_buf *bf) + const char *pfx, struct ath_tid *tid, struct ath_buf *bf) { struct ieee80211_node *ni = &an->an_node; struct ath_txq *txq = sc->sc_ac2q[tid->ac]; @@ -3249,18 +3312,19 @@ ath_tx_tid_drain_print(struct ath_softc tap = ath_tx_get_tx_tid(an, tid->tid); device_printf(sc->sc_dev, - "%s: node %p: bf=%p: addbaw=%d, dobaw=%d, " + "%s: %s: node %p: bf=%p: addbaw=%d, dobaw=%d, " "seqno=%d, retry=%d\n", - __func__, ni, bf, + __func__, pfx, ni, bf, bf->bf_state.bfs_addedbaw, bf->bf_state.bfs_dobaw, SEQNO(bf->bf_state.bfs_seqno), bf->bf_state.bfs_retries); device_printf(sc->sc_dev, - "%s: node %p: bf=%p: txq axq_depth=%d, axq_aggr_depth=%d\n", + "%s: node %p: bf=%p: txq[%d] axq_depth=%d, axq_aggr_depth=%d\n", __func__, ni, bf, - txq->axq_depth, - txq->axq_aggr_depth); + txq->axq_qnum, + txq->axq_depth, + txq->axq_aggr_depth); device_printf(sc->sc_dev, "%s: node %p: bf=%p: tid txq_depth=%d hwq_depth=%d, bar_wait=%d, isfiltered=%d\n", @@ -3323,7 +3387,7 @@ ath_tx_tid_drain(struct ath_softc *sc, s } if (t == 0) { - ath_tx_tid_drain_print(sc, an, tid, bf); + ath_tx_tid_drain_print(sc, an, "norm", tid, bf); t = 1; } @@ -3339,7 +3403,7 @@ ath_tx_tid_drain(struct ath_softc *sc, s break; if (t == 0) { - ath_tx_tid_drain_print(sc, an, tid, bf); + ath_tx_tid_drain_print(sc, an, "filt", tid, bf); t = 1; } @@ -3397,6 +3461,9 @@ ath_tx_node_flush(struct ath_softc *sc, TAILQ_INIT(&bf_cq); + ATH_KTR(sc, ATH_KTR_NODE, 1, "ath_tx_node_flush: flush node; ni=%p", + &an->an_node); + for (tid = 0; tid < IEEE80211_TID_SIZE; tid++) { struct ath_tid *atid = &an->an_tid[tid]; struct ath_txq *txq = sc->sc_ac2q[atid->ac]; Modified: head/sys/dev/ath/if_athvar.h ============================================================================== --- head/sys/dev/ath/if_athvar.h Mon Sep 24 20:05:52 2012 (r240898) +++ head/sys/dev/ath/if_athvar.h Mon Sep 24 20:35:56 2012 (r240899) @@ -445,6 +445,7 @@ struct ath_softc { struct ath_tx_aggr_stats sc_aggr_stats; struct ath_intr_stats sc_intr_stats; uint64_t sc_debug; + uint64_t sc_ktrdebug; int sc_nvaps; /* # vaps */ int sc_nstavaps; /* # station vaps */ int sc_nmeshvaps; /* # mbss vaps */
Want to link to this message? Use this URL: <https://mail-archive.FreeBSD.org/cgi/mid.cgi?201209242035.q8OKZvUM093772>