2018-01-27 01:10:07

by Ben Greear

[permalink] [raw]
Subject: [PATCH] ath9k: Print has_queued in debugfs.

From: Ben Greear <[email protected]>

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 <[email protected]>
---
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


2018-01-27 16:24:35

by Ben Greear

[permalink] [raw]
Subject: Re: [PATCH] ath9k: Print has_queued in debugfs.



On 01/27/2018 05:29 AM, Toke H?iland-J?rgensen wrote:
> [email protected] writes:
>
>> From: Ben Greear <[email protected]>
>>
>> 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 <[email protected]>
>> ---
>> 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 <[email protected]>
Candela Technologies Inc http://www.candelatech.com

2018-01-27 16:29:50

by Toke Høiland-Jørgensen

[permalink] [raw]
Subject: Re: [PATCH] ath9k: Print has_queued in debugfs.

Ben Greear <[email protected]> writes:

> On 01/27/2018 05:29 AM, Toke H=C3=B8iland-J=C3=B8rgensen wrote:
>> [email protected] writes:
>>
>>> From: Ben Greear <[email protected]>
>>>
>>> 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 <[email protected]>
>>> ---
>>> 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

2018-01-27 13:29:51

by Toke Høiland-Jørgensen

[permalink] [raw]
Subject: Re: [PATCH] ath9k: Print has_queued in debugfs.

[email protected] writes:

> From: Ben Greear <[email protected]>
>
> 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 <[email protected]>
> ---
> 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