[PATCH] ath9k: Print has_queued in debugfs.

[PATCH] ath9k: Print has_queued in debugfs.

[greearb]

From: Ben Greear <greearb@candelatech.com>

The PAUSED field was never printed per tid.  Replace that
with has_queued, which might help someone track down strange
bugs related to aqm.

And, make tx-queue debug info show peer BSSID as well as vdev
MAC to aid debugging with multiple stations connected to the
same peer.

Signed-off-by: Ben Greear <greearb@candelatech.com>
---
 drivers/net/wireless/ath/ath9k/debug_sta.c | 10 ++++++----
 drivers/net/wireless/ath/ath9k/xmit.c      |  5 +++--
 2 files changed, 9 insertions(+), 6 deletions(-)

diff --git a/drivers/net/wireless/ath/ath9k/debug_sta.c b/drivers/net/wireless/ath/ath9k/debug_sta.c
index efc692e..a45f1f5 100644
--- a/drivers/net/wireless/ath/ath9k/debug_sta.c
+++ b/drivers/net/wireless/ath/ath9k/debug_sta.c
@@ -48,9 +48,10 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
 			 an->mpdudensity);
 
 	len += scnprintf(buf + len, size - len,
-			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%8s\n",
+			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%9s\n",
 			 "TID", "SEQ_START", "SEQ_NEXT", "BAW_SIZE",
-			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED", "PAUSED");
+			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED",
+			 "HAS-QUED");
 
 	for (tidno = 0; tidno < IEEE80211_NUM_TIDS; tidno++) {
 		tid = ath_node_to_tid(an, tidno);
@@ -58,7 +59,7 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
 		ath_txq_lock(sc, txq);
 		if (tid->active) {
 			len += scnprintf(buf + len, size - len,
-					 "%3d%11d%10d%10d%10d%10d%9d%6d\n",
+					 "%3d%11d%10d%10d%10d%10d%9d%6d%9d\n",
 					 tid->tidno,
 					 tid->seq_start,
 					 tid->seq_next,
@@ -66,7 +67,8 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
 					 tid->baw_head,
 					 tid->baw_tail,
 					 tid->bar_index,
-					 !list_empty(&tid->list));
+					 !list_empty(&tid->list),
+					 tid->has_queued);
 		}
 		ath_txq_unlock(sc, txq);
 	}
diff --git a/drivers/net/wireless/ath/ath9k/xmit.c b/drivers/net/wireless/ath/ath9k/xmit.c
index 26bf9d4..c28f62f 100644
--- a/drivers/net/wireless/ath/ath9k/xmit.c
+++ b/drivers/net/wireless/ath/ath9k/xmit.c
@@ -157,8 +157,9 @@ void ath9k_wake_tx_queue(struct ieee80211_hw *hw, struct ieee80211_txq *queue)
 	struct ath_atx_tid *tid = (struct ath_atx_tid *) queue->drv_priv;
 	struct ath_txq *txq = tid->txq;
 
-	ath_dbg(common, QUEUE, "Waking TX queue: %pM (%d)\n",
-		queue->sta ? queue->sta->addr : queue->vif->addr,
+	ath_dbg(common, QUEUE,
+		"Waking TX queue: sta-addr %pM vif: %pM (tid %d)\n",
+		queue->sta ? queue->sta->addr : NULL, queue->vif->addr,
 		tid->tidno);
 
 	ath_txq_lock(sc, txq);
-- 
2.4.11

Re: [PATCH] ath9k: Print has_queued in debugfs.

[Toke Høiland-Jørgensen]

greearb@candelatech.com writes:

> From: Ben Greear <greearb@candelatech.com>
>
> The PAUSED field was never printed per tid.  Replace that
> with has_queued, which might help someone track down strange
> bugs related to aqm.
>
> And, make tx-queue debug info show peer BSSID as well as vdev
> MAC to aid debugging with multiple stations connected to the
> same peer.
>
> Signed-off-by: Ben Greear <greearb@candelatech.com>
> ---
>  drivers/net/wireless/ath/ath9k/debug_sta.c | 10 ++++++----
>  drivers/net/wireless/ath/ath9k/xmit.c      |  5 +++--
>  2 files changed, 9 insertions(+), 6 deletions(-)
>
> diff --git a/drivers/net/wireless/ath/ath9k/debug_sta.c b/drivers/net/wireless/ath/ath9k/debug_sta.c
> index efc692e..a45f1f5 100644
> --- a/drivers/net/wireless/ath/ath9k/debug_sta.c
> +++ b/drivers/net/wireless/ath/ath9k/debug_sta.c
> @@ -48,9 +48,10 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>  			 an->mpdudensity);
>  
>  	len += scnprintf(buf + len, size - len,
> -			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%8s\n",
> +			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%9s\n",
>  			 "TID", "SEQ_START", "SEQ_NEXT", "BAW_SIZE",
> -			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED", "PAUSED");
> +			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED",
> +			 "HAS-QUED");
>  
>  	for (tidno = 0; tidno < IEEE80211_NUM_TIDS; tidno++) {
>  		tid = ath_node_to_tid(an, tidno);
> @@ -58,7 +59,7 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>  		ath_txq_lock(sc, txq);
>  		if (tid->active) {
>  			len += scnprintf(buf + len, size - len,
> -					 "%3d%11d%10d%10d%10d%10d%9d%6d\n",
> +					 "%3d%11d%10d%10d%10d%10d%9d%6d%9d\n",
>  					 tid->tidno,
>  					 tid->seq_start,
>  					 tid->seq_next,
> @@ -66,7 +67,8 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>  					 tid->baw_head,
>  					 tid->baw_tail,
>  					 tid->bar_index,
> -					 !list_empty(&tid->list));
> +					 !list_empty(&tid->list),
> +					 tid->has_queued);

Would it perhaps be useful to print the length of tid->retry_q instead
of / in addition to has_queued? Planning to get rid of the has_queued
variable entirely...

-Toke

Re: [PATCH] ath9k: Print has_queued in debugfs.

[Ben Greear]

On 01/27/2018 05:29 AM, Toke Høiland-Jørgensen wrote:
> greearb@candelatech.com writes:
>
>> From: Ben Greear <greearb@candelatech.com>
>>
>> The PAUSED field was never printed per tid.  Replace that
>> with has_queued, which might help someone track down strange
>> bugs related to aqm.
>>
>> And, make tx-queue debug info show peer BSSID as well as vdev
>> MAC to aid debugging with multiple stations connected to the
>> same peer.
>>
>> Signed-off-by: Ben Greear <greearb@candelatech.com>
>> ---
>>  drivers/net/wireless/ath/ath9k/debug_sta.c | 10 ++++++----
>>  drivers/net/wireless/ath/ath9k/xmit.c      |  5 +++--
>>  2 files changed, 9 insertions(+), 6 deletions(-)
>>
>> diff --git a/drivers/net/wireless/ath/ath9k/debug_sta.c b/drivers/net/wireless/ath/ath9k/debug_sta.c
>> index efc692e..a45f1f5 100644
>> --- a/drivers/net/wireless/ath/ath9k/debug_sta.c
>> +++ b/drivers/net/wireless/ath/ath9k/debug_sta.c
>> @@ -48,9 +48,10 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>>  			 an->mpdudensity);
>>
>>  	len += scnprintf(buf + len, size - len,
>> -			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%8s\n",
>> +			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%9s\n",
>>  			 "TID", "SEQ_START", "SEQ_NEXT", "BAW_SIZE",
>> -			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED", "PAUSED");
>> +			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED",
>> +			 "HAS-QUED");
>>
>>  	for (tidno = 0; tidno < IEEE80211_NUM_TIDS; tidno++) {
>>  		tid = ath_node_to_tid(an, tidno);
>> @@ -58,7 +59,7 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>>  		ath_txq_lock(sc, txq);
>>  		if (tid->active) {
>>  			len += scnprintf(buf + len, size - len,
>> -					 "%3d%11d%10d%10d%10d%10d%9d%6d\n",
>> +					 "%3d%11d%10d%10d%10d%10d%9d%6d%9d\n",
>>  					 tid->tidno,
>>  					 tid->seq_start,
>>  					 tid->seq_next,
>> @@ -66,7 +67,8 @@ static ssize_t read_file_node_aggr(struct file *file, char __user *user_buf,
>>  					 tid->baw_head,
>>  					 tid->baw_tail,
>>  					 tid->bar_index,
>> -					 !list_empty(&tid->list));
>> +					 !list_empty(&tid->list),
>> +					 tid->has_queued);
>
> Would it perhaps be useful to print the length of tid->retry_q instead
> of / in addition to has_queued? Planning to get rid of the has_queued
> variable entirely...

I'm just getting started looking at this.  4.9 kernel works fine, so it seems
to be a regression in the aqm stuff since that is the big change between 4.9
and 4.13.

 From a brief look yesterday, it seems that has_queued is not adequately protected
by locks, but also, it was '1', which indicates it wants to send pkts (?), so I guess
it was not hitting a locking race.

Can you point me at the scheduler code (method name?).  I'll be looking at that
as soon as I get time.

Thanks,
Ben

>
> -Toke
>

-- 
Ben Greear <greearb@candelatech.com>
Candela Technologies Inc  http://www.candelatech.com

Re: [PATCH] ath9k: Print has_queued in debugfs.

[Toke Høiland-Jørgensen]

Ben Greear <greearb@candelatech.com> writes:

> On 01/27/2018 05:29 AM, Toke H=C3=B8iland-J=C3=B8rgensen wrote:
>> greearb@candelatech.com writes:
>>
>>> From: Ben Greear <greearb@candelatech.com>
>>>
>>> The PAUSED field was never printed per tid.  Replace that
>>> with has_queued, which might help someone track down strange
>>> bugs related to aqm.
>>>
>>> And, make tx-queue debug info show peer BSSID as well as vdev
>>> MAC to aid debugging with multiple stations connected to the
>>> same peer.
>>>
>>> Signed-off-by: Ben Greear <greearb@candelatech.com>
>>> ---
>>>  drivers/net/wireless/ath/ath9k/debug_sta.c | 10 ++++++----
>>>  drivers/net/wireless/ath/ath9k/xmit.c      |  5 +++--
>>>  2 files changed, 9 insertions(+), 6 deletions(-)
>>>
>>> diff --git a/drivers/net/wireless/ath/ath9k/debug_sta.c b/drivers/net/w=
ireless/ath/ath9k/debug_sta.c
>>> index efc692e..a45f1f5 100644
>>> --- a/drivers/net/wireless/ath/ath9k/debug_sta.c
>>> +++ b/drivers/net/wireless/ath/ath9k/debug_sta.c
>>> @@ -48,9 +48,10 @@ static ssize_t read_file_node_aggr(struct file *file=
, char __user *user_buf,
>>>  			 an->mpdudensity);
>>>
>>>  	len +=3D scnprintf(buf + len, size - len,
>>> -			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%8s\n",
>>> +			 "\n%3s%11s%10s%10s%10s%10s%9s%6s%9s\n",
>>>  			 "TID", "SEQ_START", "SEQ_NEXT", "BAW_SIZE",
>>> -			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED", "PAUSED");
>>> +			 "BAW_HEAD", "BAW_TAIL", "BAR_IDX", "SCHED",
>>> +			 "HAS-QUED");
>>>
>>>  	for (tidno =3D 0; tidno < IEEE80211_NUM_TIDS; tidno++) {
>>>  		tid =3D ath_node_to_tid(an, tidno);
>>> @@ -58,7 +59,7 @@ static ssize_t read_file_node_aggr(struct file *file,=
 char __user *user_buf,
>>>  		ath_txq_lock(sc, txq);
>>>  		if (tid->active) {
>>>  			len +=3D scnprintf(buf + len, size - len,
>>> -					 "%3d%11d%10d%10d%10d%10d%9d%6d\n",
>>> +					 "%3d%11d%10d%10d%10d%10d%9d%6d%9d\n",
>>>  					 tid->tidno,
>>>  					 tid->seq_start,
>>>  					 tid->seq_next,
>>> @@ -66,7 +67,8 @@ static ssize_t read_file_node_aggr(struct file *file,=
 char __user *user_buf,
>>>  					 tid->baw_head,
>>>  					 tid->baw_tail,
>>>  					 tid->bar_index,
>>> -					 !list_empty(&tid->list));
>>> +					 !list_empty(&tid->list),
>>> +					 tid->has_queued);
>>
>> Would it perhaps be useful to print the length of tid->retry_q instead
>> of / in addition to has_queued? Planning to get rid of the has_queued
>> variable entirely...
>
> I'm just getting started looking at this. 4.9 kernel works fine, so it
> seems to be a regression in the aqm stuff since that is the big change
> between 4.9 and 4.13.
>
> From a brief look yesterday, it seems that has_queued is not
> adequately protected by locks, but also, it was '1', which indicates
> it wants to send pkts (?), so I guess it was not hitting a locking
> race.

It's only ever accessed under ath_txq_lock(), so I don't think it's a
locking issue.

> Can you point me at the scheduler code (method name?). I'll be looking
> at that as soon as I get time.

ath_txq_schedule() is the main scheduler (in xmit.c). As I said it may
be the airtime fairness scheduler that's throttling stations; did you
look at the airtime debugfs file?

-Toke