Received-SPF: pass (google.com: domain of linux-wireless+bounces-6148-linux.lists.archive=gmail.com@vger.kernel.org designates 2604:1380:4601:e00::3 as permitted sender) client-ip=2604:1380:4601:e00::3;
From: Baochen Qiang <quic_bqiang@quicinc.com>
To: <ath11k@lists.infradead.org>
CC: <linux-wireless@vger.kernel.org>, <quic_bqiang@quicinc.com>
Subject: [PATCH RFT] wifi: ath11k: add log to debug CE ring post buf failure
Date: Thu, 11 Apr 2024 15:48:12 +0800
Message-ID: <20240411074812.86700-1-quic_bqiang@quicinc.com>
Precedence: bulk
MIME-Version: 1.0
Content-Transfer-Encoding: 8bit
Content-Type: text/plain

There is a report from community that ath11k fails to enqueue
rx bufs some times. Although running tests for nearly 10 days
I failed to reproduce this issue. Considering that the reporter
seems not that hard to hit this issue I'd like to submit this
patch to public so that the reporter could merge it and get us
more logs.

This patch does not contain any functional changes but only
logs added.

Link: https://lore.kernel.org/ath11k/e458216d-b389-4abd-a9b2-90525ea10a8d@gmail.com/
Signed-off-by: Baochen Qiang <quic_bqiang@quicinc.com>
---
 drivers/net/wireless/ath/ath11k/ce.c  |  6 +++
 drivers/net/wireless/ath/ath11k/hal.c | 73 +++++++++++++++++++++++++--
 2 files changed, 75 insertions(+), 4 deletions(-)

diff --git a/drivers/net/wireless/ath/ath11k/ce.c b/drivers/net/wireless/ath/ath11k/ce.c
index e66e86bdec20..f9405cad73b0 100644
--- a/drivers/net/wireless/ath/ath11k/ce.c
+++ b/drivers/net/wireless/ath/ath11k/ce.c
@@ -290,12 +290,14 @@ static int ath11k_ce_rx_buf_enqueue_pipe(struct ath11k_ce_pipe *pipe,
 	ath11k_hal_srng_access_begin(ab, srng);
 
 	if (unlikely(ath11k_hal_srng_src_num_free(ab, srng, false) < 1)) {
+		ath11k_warn(ab, "srng is full\n");
 		ret = -ENOSPC;
 		goto exit;
 	}
 
 	desc = ath11k_hal_srng_src_get_next_entry(ab, srng);
 	if (!desc) {
+		ath11k_warn(ab, "srng get next entry failed\n");
 		ret = -ENOSPC;
 		goto exit;
 	}
@@ -307,6 +309,7 @@ static int ath11k_ce_rx_buf_enqueue_pipe(struct ath11k_ce_pipe *pipe,
 	ring->write_index = write_index;
 
 	pipe->rx_buf_needed--;
+	ath11k_info(ab, "%s: pipe %u rx_buf_needed %u\n", __func__, pipe->pipe_num,  pipe->rx_buf_needed);
 
 	ret = 0;
 exit:
@@ -389,12 +392,14 @@ static int ath11k_ce_completed_recv_next(struct ath11k_ce_pipe *pipe,
 
 	desc = ath11k_hal_srng_dst_get_next_entry(ab, srng);
 	if (!desc) {
+		ath11k_warn(ab, "dst get next entry failed\n");
 		ret = -EIO;
 		goto err;
 	}
 
 	*nbytes = ath11k_hal_ce_dst_status_get_length(desc);
 	if (*nbytes == 0) {
+		ath11k_warn(ab, "dst status get length failed\n");
 		ret = -EIO;
 		goto err;
 	}
@@ -406,6 +411,7 @@ static int ath11k_ce_completed_recv_next(struct ath11k_ce_pipe *pipe,
 	pipe->dest_ring->sw_index = sw_index;
 
 	pipe->rx_buf_needed++;
+	ath11k_info(ab, "%s: pipe %u rx_buf_needed %u\n", __func__, pipe->pipe_num,  pipe->rx_buf_needed);
 err:
 	ath11k_hal_srng_access_end(ab, srng);
 
diff --git a/drivers/net/wireless/ath/ath11k/hal.c b/drivers/net/wireless/ath/ath11k/hal.c
index f3d04568c221..ad5492c8d1aa 100644
--- a/drivers/net/wireless/ath/ath11k/hal.c
+++ b/drivers/net/wireless/ath/ath11k/hal.c
@@ -9,6 +9,10 @@
 #include "hal_desc.h"
 #include "hif.h"
 
+
+#define DUMP_SRNG_ID_MIN HAL_SRNG_RING_ID_CE0_SRC
+#define DUMP_SRNG_ID_MAX HAL_SRNG_RING_ID_CE11_DST_STATUS
+
 static const struct hal_srng_config hw_srng_config_template[] = {
 	/* TODO: max_rings can populated by querying HW capabilities */
 	{ /* REO_DST */
@@ -663,8 +667,13 @@ u32 *ath11k_hal_srng_dst_get_next_entry(struct ath11k_base *ab,
 
 	lockdep_assert_held(&srng->lock);
 
-	if (srng->u.dst_ring.tp == srng->u.dst_ring.cached_hp)
+	if (srng->u.dst_ring.tp == srng->u.dst_ring.cached_hp) {
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+			ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u is empty, cached hp %u, tp %u\n", __func__, srng->ring_id,
+										srng->u.dst_ring.cached_hp,
+										srng->u.dst_ring.tp);
 		return NULL;
+	}
 
 	desc = srng->ring_base_vaddr + srng->u.dst_ring.tp;
 
@@ -674,6 +683,10 @@ u32 *ath11k_hal_srng_dst_get_next_entry(struct ath11k_base *ab,
 	if (srng->u.dst_ring.tp == srng->ring_size)
 		srng->u.dst_ring.tp = 0;
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+		ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u, cached hp %u, tp %u\n", __func__, srng->ring_id,
+										srng->u.dst_ring.cached_hp,
+										srng->u.dst_ring.tp);
 	/* Try to prefetch the next descriptor in the ring */
 	if (srng->flags & HAL_SRNG_FLAGS_CACHED)
 		ath11k_hal_srng_prefetch_desc(ab, srng);
@@ -697,6 +710,9 @@ int ath11k_hal_srng_dst_num_free(struct ath11k_base *ab, struct hal_srng *srng,
 		hp = srng->u.dst_ring.cached_hp;
 	}
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u, hp %u, tp %u\n", __func__, srng->ring_id, hp, tp);
+
 	if (hp >= tp)
 		return (hp - tp) / srng->entry_size;
 	else
@@ -720,6 +736,9 @@ int ath11k_hal_srng_src_num_free(struct ath11k_base *ab, struct hal_srng *srng,
 		tp = srng->u.src_ring.cached_tp;
 	}
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, hp %u, tp %u\n", __func__, srng->ring_id, hp, tp);
+
 	if (tp > hp)
 		return ((tp - hp) / srng->entry_size) - 1;
 	else
@@ -742,8 +761,11 @@ u32 *ath11k_hal_srng_src_get_next_entry(struct ath11k_base *ab,
 	 */
 	next_hp = (srng->u.src_ring.hp + srng->entry_size) % srng->ring_size;
 
-	if (next_hp == srng->u.src_ring.cached_tp)
+	if (next_hp == srng->u.src_ring.cached_tp) {
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                        ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, hal ring is full, next_hp %u\n", __func__, srng->ring_id, next_hp);
 		return NULL;
+	}
 
 	desc = srng->ring_base_vaddr + srng->u.src_ring.hp;
 	srng->u.src_ring.hp = next_hp;
@@ -756,6 +778,9 @@ u32 *ath11k_hal_srng_src_get_next_entry(struct ath11k_base *ab,
 	 */
 	srng->u.src_ring.reap_hp = next_hp;
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, hp %u, reap_hp %u\n", __func__, srng->ring_id, srng->u.src_ring.hp, srng->u.src_ring.reap_hp);
+
 	return desc;
 }
 
@@ -770,12 +795,18 @@ u32 *ath11k_hal_srng_src_reap_next(struct ath11k_base *ab,
 	next_reap_hp = (srng->u.src_ring.reap_hp + srng->entry_size) %
 		       srng->ring_size;
 
-	if (next_reap_hp == srng->u.src_ring.cached_tp)
+	if (next_reap_hp == srng->u.src_ring.cached_tp) {
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+			ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u is empty, cached_tp %u\n", __func__, srng->ring_id, srng->u.src_ring.cached_tp);
 		return NULL;
+	}
 
 	desc = srng->ring_base_vaddr + next_reap_hp;
 	srng->u.src_ring.reap_hp = next_reap_hp;
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+		ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, reap_hp %u\n", __func__, srng->ring_id, srng->u.src_ring.reap_hp);
+
 	return desc;
 }
 
@@ -786,13 +817,23 @@ u32 *ath11k_hal_srng_src_get_next_reaped(struct ath11k_base *ab,
 
 	lockdep_assert_held(&srng->lock);
 
-	if (srng->u.src_ring.hp == srng->u.src_ring.reap_hp)
+	if (srng->u.src_ring.hp == srng->u.src_ring.reap_hp) {
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+			ath11k_warn(ab, "SRNG-DEBUG: %s: SRC srng id %u is full, hp %u, reap_hp %u\n", __func__, srng->ring_id, srng->u.src_ring.hp, srng->u.src_ring.reap_hp);
+
 		return NULL;
+	}
 
 	desc = srng->ring_base_vaddr + srng->u.src_ring.hp;
 	srng->u.src_ring.hp = (srng->u.src_ring.hp + srng->entry_size) %
 			      srng->ring_size;
 
+	if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+		ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, hp %u, entry_size %u, ring_size %u\n", __func__, srng->ring_id,
+				srng->u.src_ring.hp,
+				srng->entry_size,
+				srng->ring_size);
+
 	return desc;
 }
 
@@ -814,8 +855,12 @@ void ath11k_hal_srng_access_begin(struct ath11k_base *ab, struct hal_srng *srng)
 	if (srng->ring_dir == HAL_SRNG_DIR_SRC) {
 		srng->u.src_ring.cached_tp =
 			*(volatile u32 *)srng->u.src_ring.tp_addr;
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+			ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, cached_tp %u\n", __func__, srng->ring_id, srng->u.src_ring.cached_tp);
 	} else {
 		srng->u.dst_ring.cached_hp = *srng->u.dst_ring.hp_addr;
+		if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+			ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u, cached_hp %u\n", __func__, srng->ring_id, srng->u.dst_ring.cached_hp);
 
 		/* Try to prefetch the next descriptor in the ring */
 		if (srng->flags & HAL_SRNG_FLAGS_CACHED)
@@ -839,9 +884,19 @@ void ath11k_hal_srng_access_end(struct ath11k_base *ab, struct hal_srng *srng)
 			srng->u.src_ring.last_tp =
 				*(volatile u32 *)srng->u.src_ring.tp_addr;
 			*srng->u.src_ring.hp_addr = srng->u.src_ring.hp;
+			if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+				ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, last_tp %u, hp %u, hw hp %u\n", __func__, srng->ring_id,
+						srng->u.src_ring.last_tp,
+						srng->u.src_ring.hp,
+						*srng->u.src_ring.hp_addr);
 		} else {
 			srng->u.dst_ring.last_hp = *srng->u.dst_ring.hp_addr;
 			*srng->u.dst_ring.tp_addr = srng->u.dst_ring.tp;
+			if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+				ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u, last_hp %u, tp %u, hw tp %u\n", __func__, srng->ring_id,
+						srng->u.dst_ring.last_hp,
+						srng->u.dst_ring.tp,
+						*srng->u.dst_ring.tp_addr);
 		}
 	} else {
 		if (srng->ring_dir == HAL_SRNG_DIR_SRC) {
@@ -851,12 +906,22 @@ void ath11k_hal_srng_access_end(struct ath11k_base *ab, struct hal_srng *srng)
 					   (unsigned long)srng->u.src_ring.hp_addr -
 					   (unsigned long)ab->mem,
 					   srng->u.src_ring.hp);
+			if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                                ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: SRC srng id %u, last_tp %u, hp %u, hw hp %u\n", __func__, srng->ring_id,
+						srng->u.src_ring.last_tp,
+						srng->u.src_ring.hp,
+						ath11k_hif_read32(ab, (unsigned long)srng->u.src_ring.hp_addr - (unsigned long)ab->mem));
 		} else {
 			srng->u.dst_ring.last_hp = *srng->u.dst_ring.hp_addr;
 			ath11k_hif_write32(ab,
 					   (unsigned long)srng->u.dst_ring.tp_addr -
 					   (unsigned long)ab->mem,
 					   srng->u.dst_ring.tp);
+			if (DUMP_SRNG_ID_MIN <= srng->ring_id && srng->ring_id <= DUMP_SRNG_ID_MAX)
+                                ath11k_dbg(ab, ATH11K_DBG_HAL, "SRNG-DEBUG: %s: DST srng id %u, last_hp %u, tp %u, hw tp %u\n", __func__, srng->ring_id,
+						srng->u.dst_ring.last_hp,
+						srng->u.dst_ring.tp,
+						ath11k_hif_read32(ab, (unsigned long)srng->u.dst_ring.tp_addr - (unsigned long)ab->mem));
 		}
 	}
 

base-commit: 363e7193eaf258fe7f04e8db560bd8a282a12cd9
-- 
2.25.1