hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

I'm seeing the ring-full messages below when running 35 stations on
modified 10.4.3 firmware.  I also have serial console logging enabled, so
things are running a bit slow...this seems to exacerbate the issue.

[   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2 credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
[   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128 ret -105)
[   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f  write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
[   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2 credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
[   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret -105)
[   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool: -105
[   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f  write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
[   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2 credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
[   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128 ret -105)
[   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f  write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
[   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2 credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
[   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret -105)
[   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool: -105
[   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f  write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
[   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2 credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1


I am struggling to understand how the pipe can be full since we have tx-credits logic
enabled for the WMI pipe.

Any suggestions on what sort of bugs could cause this?

And, should the ath10k_wmi_cmd_send retry when we get a -105 return
code in hopes it will free up shortly instead of just failing and leaving
the system in invalid state?


Debug message comes from the warning I added below:

static int ath10k_pci_hif_tx_sg(struct ath10k *ar, u8 pipe_id,
				struct ath10k_hif_sg_item *items, int n_items)
{
	struct ath10k_pci *ar_pci = ath10k_pci_priv(ar);
	struct ath10k_pci_pipe *pci_pipe = &ar_pci->pipe_info[pipe_id];
	struct ath10k_ce_pipe *ce_pipe = pci_pipe->ce_hdl;
	struct ath10k_ce_ring *src_ring = ce_pipe->src_ring;
	unsigned int nentries_mask;
	unsigned int sw_index;
	unsigned int write_index;
	int err, i = 0;

	spin_lock_bh(&ar_pci->ce_lock);

	nentries_mask = src_ring->nentries_mask;
	sw_index = src_ring->sw_index;
	write_index = src_ring->write_index;

	if (unlikely(CE_RING_DELTA(nentries_mask,
				   write_index, sw_index - 1) < n_items)) {
		ath10k_warn(ar, "hif-tx-sg, full, nentries_mask: 0x%x  write_idx: %d sw-idx: %d  n_items: %d pipe-id: %d\n",
			    nentries_mask, write_index, sw_index, n_items, pipe_id);
		err = -ENOBUFS;
		goto err;
	}

Thanks,
Ben

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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Michal Kazior]

On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
> I'm seeing the ring-full messages below when running 35 stations on
> modified 10.4.3 firmware.  I also have serial console logging enabled, so
> things are running a bit slow...this seems to exacerbate the issue.
>
> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
> ret -105)
> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
> -105)
> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
> -105
> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
> ret -105)
> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
> -105)
> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
> -105
> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>
>
> I am struggling to understand how the pipe can be full since we have
> tx-credits logic
> enabled for the WMI pipe.
>
> Any suggestions on what sort of bugs could cause this?
>
> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
> code in hopes it will free up shortly instead of just failing and leaving
> the system in invalid state?

It probably shouldn't. As you've pointed out HTC tx credits should
prevent this in the first place. If you see -105 it means something is
really broken and needs to be fixed properly.

A thing that comes to mind is that CE -for whatever reason- would need
to stop completing CE ring items. Are you running with MSI? 1 or
multiple interrupts? Did you try forcing legacy interrupt mode to rule
out MSI problems?

You could add a debug messages to see if the HTC-WMI CE ring gets tx
completions properly.



Michał

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/29/2016 01:05 AM, Michal Kazior wrote:
> On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
>> I'm seeing the ring-full messages below when running 35 stations on
>> modified 10.4.3 firmware.  I also have serial console logging enabled, so
>> things are running a bit slow...this seems to exacerbate the issue.
>>
>> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
>> ret -105)
>> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
>> -105)
>> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
>> -105
>> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
>> ret -105)
>> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
>> -105)
>> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
>> -105
>> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>
>>
>> I am struggling to understand how the pipe can be full since we have
>> tx-credits logic
>> enabled for the WMI pipe.
>>
>> Any suggestions on what sort of bugs could cause this?
>>
>> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>> code in hopes it will free up shortly instead of just failing and leaving
>> the system in invalid state?
>
> It probably shouldn't. As you've pointed out HTC tx credits should
> prevent this in the first place. If you see -105 it means something is
> really broken and needs to be fixed properly.
>
> A thing that comes to mind is that CE -for whatever reason- would need
> to stop completing CE ring items. Are you running with MSI? 1 or
> multiple interrupts? Did you try forcing legacy interrupt mode to rule
> out MSI problems?
>
> You could add a debug messages to see if the HTC-WMI CE ring gets tx
> completions properly.

I don't think I'm using MSI.  Could it be that whatever logic that should
be processing the tx-completions is just running slower than whatever is
handling the WMI messages (and credits)?

Thanks,
Ben


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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/29/2016 10:08 AM, Adrian Chadd wrote:
> Does it eventually catch up?

It seems to.

> IE, put a wait completion in there?

Maybe so, but the current wait-completion waits on tx-credits,
so more like I'd need to put the whole wait-completion in a loop
and add a small sleep, maybe?

Or, maybe try to force a read of the CE entries if the CE logic
ever detects the ring is full?

Thanks,
Ben

>
> On Mar 29, 2016 8:49 AM, "Ben Greear" <greearb@candelatech.com <mailto:greearb@candelatech.com>> wrote:
>
>     On 03/29/2016 01:05 AM, Michal Kazior wrote:
>
>         On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com <mailto:greearb@candelatech.com>> wrote:
>
>             I'm seeing the ring-full messages below when running 35 stations on
>             modified 10.4.3 firmware.  I also have serial console logging enabled, so
>             things are running a bit slow...this seems to exacerbate the issue.
>
>             [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>             credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>             [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
>             ret -105)
>             [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>             write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>             [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>             credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>             [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
>             -105)
>             [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
>             -105
>             [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>             write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>             [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>             credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>             [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
>             ret -105)
>             [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>             write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>             [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>             credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>             [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1 ret
>             -105)
>             [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for ethtool:
>             -105
>             [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask: 0x1f
>             write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>             [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>             credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>
>
>             I am struggling to understand how the pipe can be full since we have
>             tx-credits logic
>             enabled for the WMI pipe.
>
>             Any suggestions on what sort of bugs could cause this?
>
>             And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>             code in hopes it will free up shortly instead of just failing and leaving
>             the system in invalid state?
>
>
>         It probably shouldn't. As you've pointed out HTC tx credits should
>         prevent this in the first place. If you see -105 it means something is
>         really broken and needs to be fixed properly.
>
>         A thing that comes to mind is that CE -for whatever reason- would need
>         to stop completing CE ring items. Are you running with MSI? 1 or
>         multiple interrupts? Did you try forcing legacy interrupt mode to rule
>         out MSI problems?
>
>         You could add a debug messages to see if the HTC-WMI CE ring gets tx
>         completions properly.
>
>
>     I don't think I'm using MSI.  Could it be that whatever logic that should
>     be processing the tx-completions is just running slower than whatever is
>     handling the WMI messages (and credits)?
>
>     Thanks,
>     Ben
>
>
>     --
>     Ben Greear <greearb@candelatech.com <mailto:greearb@candelatech.com>>
>     Candela Technologies Inc http://www.candelatech.com
>
>
>     _______________________________________________
>     ath10k mailing list
>     ath10k@lists.infradead.org <mailto:ath10k@lists.infradead.org>
>     http://lists.infradead.org/mailman/listinfo/ath10k
>


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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Adrian Chadd]

On 29 March 2016 at 10:13, Ben Greear <greearb@candelatech.com> wrote:
> On 03/29/2016 10:08 AM, Adrian Chadd wrote:
>>
>> Does it eventually catch up?
>
>
> It seems to.
>
>> IE, put a wait completion in there?
>
>
> Maybe so, but the current wait-completion waits on tx-credits,
> so more like I'd need to put the whole wait-completion in a loop
> and add a small sleep, maybe?
>
> Or, maybe try to force a read of the CE entries if the CE logic
> ever detects the ring is full?

Right. A little sleep (as long as its in a place where you can do it!)
just to check would be good. I'd also print out the CE ring contents
as well - see where the firmware has gotten to.



-adrian

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/29/2016 10:45 AM, Adrian Chadd wrote:
> On 29 March 2016 at 10:13, Ben Greear <greearb@candelatech.com> wrote:
>> On 03/29/2016 10:08 AM, Adrian Chadd wrote:
>>>
>>> Does it eventually catch up?
>>
>>
>> It seems to.
>>
>>> IE, put a wait completion in there?
>>
>>
>> Maybe so, but the current wait-completion waits on tx-credits,
>> so more like I'd need to put the whole wait-completion in a loop
>> and add a small sleep, maybe?
>>
>> Or, maybe try to force a read of the CE entries if the CE logic
>> ever detects the ring is full?
>
> Right. A little sleep (as long as its in a place where you can do it!)
> just to check would be good. I'd also print out the CE ring contents
> as well - see where the firmware has gotten to.

This seemed to help my system, but I also fixed some other bugs that made
the system work better over-all, so not sure this is a complete fix on its
own.  I'll send a patch in case someone wants to give it a try.

Thanks,
Ben

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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Michal Kazior]

On 29 March 2016 at 17:48, Ben Greear <greearb@candelatech.com> wrote:
> On 03/29/2016 01:05 AM, Michal Kazior wrote:
>>
>> On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
>>>
>>> I'm seeing the ring-full messages below when running 35 stations on
>>> modified 10.4.3 firmware.  I also have serial console logging enabled, so
>>> things are running a bit slow...this seems to exacerbate the issue.
>>>
>>> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>> ret -105)
>>> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>> 0x1f
>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>> ret
>>> -105)
>>> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>> ethtool:
>>> -105
>>> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>> 0x1f
>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>> ret -105)
>>> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>> 0x1f
>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>> ret
>>> -105)
>>> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>> ethtool:
>>> -105
>>> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>> 0x1f
>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>
>>>
>>> I am struggling to understand how the pipe can be full since we have
>>> tx-credits logic
>>> enabled for the WMI pipe.
>>>
>>> Any suggestions on what sort of bugs could cause this?
>>>
>>> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>>> code in hopes it will free up shortly instead of just failing and leaving
>>> the system in invalid state?
>>
>>
>> It probably shouldn't. As you've pointed out HTC tx credits should
>> prevent this in the first place. If you see -105 it means something is
>> really broken and needs to be fixed properly.
>>
>> A thing that comes to mind is that CE -for whatever reason- would need
>> to stop completing CE ring items. Are you running with MSI? 1 or
>> multiple interrupts? Did you try forcing legacy interrupt mode to rule
>> out MSI problems?
>>
>> You could add a debug messages to see if the HTC-WMI CE ring gets tx
>> completions properly.
>
>
> I don't think I'm using MSI.  Could it be that whatever logic that should
> be processing the tx-completions is just running slower than whatever is
> handling the WMI messages (and credits)?

Your WMI command queue is limited to HTC Tx credits (2, right?). This
means you can enqueue, in practice, 2 CE items to WMI's CE Tx pipe.
Once you've done that you have to wait until next interrupt carrying
HTC Rx message with Tx Credit Update. If you get this it implies FW
received your WMI commands which implies WMI's CE Tx pipe was updated
(and at least the 2 CE's associated with your WMI commands have been
consumed/completed). Even if you assume CE processing ordering is
reversed (i.e. HTC Rx gets processed before HTC Tx completions are)
you still should be able to have enqueued no more than 4 CE items at a
time as far as WMI is concerned.

Now, if you assume MSI-range (multiple MSI interrupts; a vector) is
enabled, you can service each CE pipe in a separate interrupt and
tasklet. This could, in theory, result in some weird race as HTC Tx
credits and CE Tx pipe completions are not guaranteed to be
serialized.

Or maybe you're using some forced WMI commands in your fork and
disregard Tx credits in some cases? This could explain the problem
even when running with a single interrupt.


Michał

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/30/2016 11:51 PM, Michal Kazior wrote:
> On 29 March 2016 at 17:48, Ben Greear <greearb@candelatech.com> wrote:
>> On 03/29/2016 01:05 AM, Michal Kazior wrote:
>>>
>>> On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
>>>>
>>>> I'm seeing the ring-full messages below when running 35 stations on
>>>> modified 10.4.3 firmware.  I also have serial console logging enabled, so
>>>> things are running a bit slow...this seems to exacerbate the issue.
>>>>
>>>> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>>> ret -105)
>>>> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>> ret
>>>> -105)
>>>> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>> ethtool:
>>>> -105
>>>> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>>> ret -105)
>>>> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>> ret
>>>> -105)
>>>> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>> ethtool:
>>>> -105
>>>> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>
>>>>
>>>> I am struggling to understand how the pipe can be full since we have
>>>> tx-credits logic
>>>> enabled for the WMI pipe.
>>>>
>>>> Any suggestions on what sort of bugs could cause this?
>>>>
>>>> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>>>> code in hopes it will free up shortly instead of just failing and leaving
>>>> the system in invalid state?
>>>
>>>
>>> It probably shouldn't. As you've pointed out HTC tx credits should
>>> prevent this in the first place. If you see -105 it means something is
>>> really broken and needs to be fixed properly.
>>>
>>> A thing that comes to mind is that CE -for whatever reason- would need
>>> to stop completing CE ring items. Are you running with MSI? 1 or
>>> multiple interrupts? Did you try forcing legacy interrupt mode to rule
>>> out MSI problems?
>>>
>>> You could add a debug messages to see if the HTC-WMI CE ring gets tx
>>> completions properly.
>>
>>
>> I don't think I'm using MSI.  Could it be that whatever logic that should
>> be processing the tx-completions is just running slower than whatever is
>> handling the WMI messages (and credits)?
>
> Your WMI command queue is limited to HTC Tx credits (2, right?). This
> means you can enqueue, in practice, 2 CE items to WMI's CE Tx pipe.
> Once you've done that you have to wait until next interrupt carrying
> HTC Rx message with Tx Credit Update. If you get this it implies FW
> received your WMI commands which implies WMI's CE Tx pipe was updated
> (and at least the 2 CE's associated with your WMI commands have been
> consumed/completed). Even if you assume CE processing ordering is
> reversed (i.e. HTC Rx gets processed before HTC Tx completions are)
> you still should be able to have enqueued no more than 4 CE items at a
> time as far as WMI is concerned.
>
> Now, if you assume MSI-range (multiple MSI interrupts; a vector) is
> enabled, you can service each CE pipe in a separate interrupt and
> tasklet. This could, in theory, result in some weird race as HTC Tx
> credits and CE Tx pipe completions are not guaranteed to be
> serialized.

That could be what happened.

>
> Or maybe you're using some forced WMI commands in your fork and
> disregard Tx credits in some cases? This could explain the problem
> even when running with a single interrupt.

I'm not forcing WMI commands, and if I were really managing to queue up 30
WMI cmds in the firmware, it seems it would have crashed the firmware since
it does not contain many local resources (ie, only 2).

Thanks,
Ben


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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/30/2016 11:51 PM, Michal Kazior wrote:
> On 29 March 2016 at 17:48, Ben Greear <greearb@candelatech.com> wrote:
>> On 03/29/2016 01:05 AM, Michal Kazior wrote:
>>>
>>> On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
>>>>
>>>> I'm seeing the ring-full messages below when running 35 stations on
>>>> modified 10.4.3 firmware.  I also have serial console logging enabled, so
>>>> things are running a bit slow...this seems to exacerbate the issue.
>>>>
>>>> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>>> ret -105)
>>>> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>> ret
>>>> -105)
>>>> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>> ethtool:
>>>> -105
>>>> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type 128
>>>> ret -105)
>>>> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>> ret
>>>> -105)
>>>> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>> ethtool:
>>>> -105
>>>> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>> 0x1f
>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid: 2
>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>
>>>>
>>>> I am struggling to understand how the pipe can be full since we have
>>>> tx-credits logic
>>>> enabled for the WMI pipe.
>>>>
>>>> Any suggestions on what sort of bugs could cause this?
>>>>
>>>> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>>>> code in hopes it will free up shortly instead of just failing and leaving
>>>> the system in invalid state?
>>>
>>>
>>> It probably shouldn't. As you've pointed out HTC tx credits should
>>> prevent this in the first place. If you see -105 it means something is
>>> really broken and needs to be fixed properly.
>>>
>>> A thing that comes to mind is that CE -for whatever reason- would need
>>> to stop completing CE ring items. Are you running with MSI? 1 or
>>> multiple interrupts? Did you try forcing legacy interrupt mode to rule
>>> out MSI problems?
>>>
>>> You could add a debug messages to see if the HTC-WMI CE ring gets tx
>>> completions properly.
>>
>>
>> I don't think I'm using MSI.  Could it be that whatever logic that should
>> be processing the tx-completions is just running slower than whatever is
>> handling the WMI messages (and credits)?
>
> Your WMI command queue is limited to HTC Tx credits (2, right?). This
> means you can enqueue, in practice, 2 CE items to WMI's CE Tx pipe.
> Once you've done that you have to wait until next interrupt carrying
> HTC Rx message with Tx Credit Update. If you get this it implies FW
> received your WMI commands which implies WMI's CE Tx pipe was updated
> (and at least the 2 CE's associated with your WMI commands have been
> consumed/completed). Even if you assume CE processing ordering is
> reversed (i.e. HTC Rx gets processed before HTC Tx completions are)
> you still should be able to have enqueued no more than 4 CE items at a
> time as far as WMI is concerned.
>
> Now, if you assume MSI-range (multiple MSI interrupts; a vector) is
> enabled, you can service each CE pipe in a separate interrupt and
> tasklet. This could, in theory, result in some weird race as HTC Tx
> credits and CE Tx pipe completions are not guaranteed to be
> serialized.
>
> Or maybe you're using some forced WMI commands in your fork and
> disregard Tx credits in some cases? This could explain the problem
> even when running with a single interrupt.

So, I am using MSI-X, I guess?

# dmesg|grep -i msi
[65284.853372] ath10k_pci 0000:05:00.0: pci irq msi-x interrupts 13 irq_mode 0 reset_mode 0

Thanks,
Ben

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


_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Michal Kazior]

On 31 March 2016 at 18:44, Ben Greear <greearb@candelatech.com> wrote:
> On 03/30/2016 11:51 PM, Michal Kazior wrote:
>>
>> On 29 March 2016 at 17:48, Ben Greear <greearb@candelatech.com> wrote:
>>>
>>> On 03/29/2016 01:05 AM, Michal Kazior wrote:
>>>>
>>>>
>>>> On 28 March 2016 at 21:01, Ben Greear <greearb@candelatech.com> wrote:
>>>>>
>>>>>
>>>>> I'm seeing the ring-full messages below when running 35 stations on
>>>>> modified 10.4.3 firmware.  I also have serial console logging enabled,
>>>>> so
>>>>> things are running a bit slow...this seems to exacerbate the issue.
>>>>>
>>>>> [   91.108923] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid:
>>>>> 2
>>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>> [   91.108932] ath10k_pci 0000:05:00.0: could not request stats (type
>>>>> 128
>>>>> ret -105)
>>>>> [   91.108942] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>>> 0x1f
>>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>>> [   91.108944] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid:
>>>>> 2
>>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>> [   91.108952] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>>> ret
>>>>> -105)
>>>>> [   91.108953] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>>> ethtool:
>>>>> -105
>>>>> [   91.109039] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>>> 0x1f
>>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>>> [   91.109041] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid:
>>>>> 2
>>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>> [   91.109050] ath10k_pci 0000:05:00.0: could not request stats (type
>>>>> 128
>>>>> ret -105)
>>>>> [   91.109060] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>>> 0x1f
>>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>>> [   91.109062] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid:
>>>>> 2
>>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>> [   91.109070] ath10k_pci 0000:05:00.0: could not request stats (type 1
>>>>> ret
>>>>> -105)
>>>>> [   91.109072] ath10k_pci 0000:05:00.0: failed to get fw stats for
>>>>> ethtool:
>>>>> -105
>>>>> [   91.109157] ath10k_pci 0000:05:00.0: hif-tx-sg, full, nentries_mask:
>>>>> 0x1f
>>>>> write_idx: 2 sw-idx: 3  n_items: 1 pipe-id: 3
>>>>> [   91.109160] ath10k_pci 0000:05:00.0: htc failed hif-tx-sq: -105 eid:
>>>>> 2
>>>>> credits: 1 ep->tx_credits: 1  credit-flow-enabled: 1
>>>>>
>>>>>
>>>>> I am struggling to understand how the pipe can be full since we have
>>>>> tx-credits logic
>>>>> enabled for the WMI pipe.
>>>>>
>>>>> Any suggestions on what sort of bugs could cause this?
>>>>>
>>>>> And, should the ath10k_wmi_cmd_send retry when we get a -105 return
>>>>> code in hopes it will free up shortly instead of just failing and
>>>>> leaving
>>>>> the system in invalid state?
>>>>
>>>>
>>>>
>>>> It probably shouldn't. As you've pointed out HTC tx credits should
>>>> prevent this in the first place. If you see -105 it means something is
>>>> really broken and needs to be fixed properly.
>>>>
>>>> A thing that comes to mind is that CE -for whatever reason- would need
>>>> to stop completing CE ring items. Are you running with MSI? 1 or
>>>> multiple interrupts? Did you try forcing legacy interrupt mode to rule
>>>> out MSI problems?
>>>>
>>>> You could add a debug messages to see if the HTC-WMI CE ring gets tx
>>>> completions properly.
>>>
>>>
>>>
>>> I don't think I'm using MSI.  Could it be that whatever logic that should
>>> be processing the tx-completions is just running slower than whatever is
>>> handling the WMI messages (and credits)?
>>
>>
>> Your WMI command queue is limited to HTC Tx credits (2, right?). This
>> means you can enqueue, in practice, 2 CE items to WMI's CE Tx pipe.
>> Once you've done that you have to wait until next interrupt carrying
>> HTC Rx message with Tx Credit Update. If you get this it implies FW
>> received your WMI commands which implies WMI's CE Tx pipe was updated
>> (and at least the 2 CE's associated with your WMI commands have been
>> consumed/completed). Even if you assume CE processing ordering is
>> reversed (i.e. HTC Rx gets processed before HTC Tx completions are)
>> you still should be able to have enqueued no more than 4 CE items at a
>> time as far as WMI is concerned.
>>
>> Now, if you assume MSI-range (multiple MSI interrupts; a vector) is
>> enabled, you can service each CE pipe in a separate interrupt and
>> tasklet. This could, in theory, result in some weird race as HTC Tx
>> credits and CE Tx pipe completions are not guaranteed to be
>> serialized.
>>
>> Or maybe you're using some forced WMI commands in your fork and
>> disregard Tx credits in some cases? This could explain the problem
>> even when running with a single interrupt.
>
>
> So, I am using MSI-X, I guess?
>
> # dmesg|grep -i msi
> [65284.853372] ath10k_pci 0000:05:00.0: pci irq msi-x interrupts 13 irq_mode
> 0 reset_mode 0

Yep. This at least makes it possible for this weird problem to come
into existance. However I still find it a little hard to believe for
tasklets to be scheduled this badly. Maybe the device doesn't assert
interrupts properly as Adrian suggested? Or maybe they are not mapped
properly? I think you're actually the first one to exercise MSI-range
support on qca99x0.


Michał

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Ben Greear]

On 03/31/2016 10:18 PM, Michal Kazior wrote:
> On 31 March 2016 at 18:44, Ben Greear <greearb@candelatech.com> wrote:
>> On 03/30/2016 11:51 PM, Michal Kazior wrote:

>>
>> So, I am using MSI-X, I guess?
>>
>> # dmesg|grep -i msi
>> [65284.853372] ath10k_pci 0000:05:00.0: pci irq msi-x interrupts 13 irq_mode
>> 0 reset_mode 0
>
> Yep. This at least makes it possible for this weird problem to come
> into existance. However I still find it a little hard to believe for
> tasklets to be scheduled this badly. Maybe the device doesn't assert
> interrupts properly as Adrian suggested? Or maybe they are not mapped
> properly? I think you're actually the first one to exercise MSI-range
> support on qca99x0.

I applied Rajkumar's patch to disable msi-x today, so maybe that will be
the end of those problems.

I think upstream might want a warn-on for that wmi issue, even if you don't
add the work-around code though...just to see if someone else hits it.

If you drop the wrong WMI message, often your best hope is that firmware crashes
right away, so we should really be quite loud about not sending a WMI message.

Thanks,
Ben

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

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k

Re: hacked 4.4.6+, 10.4.3 firmware, Running out of ring-index for pipe-id 3 (WMI).

[Michal Kazior]

On 1 April 2016 at 07:23, Ben Greear <greearb@candelatech.com> wrote:
>
>
> On 03/31/2016 10:18 PM, Michal Kazior wrote:
>>
>> On 31 March 2016 at 18:44, Ben Greear <greearb@candelatech.com> wrote:
>>>
>>> On 03/30/2016 11:51 PM, Michal Kazior wrote:
>
>
>>>
>>> So, I am using MSI-X, I guess?
>>>
>>> # dmesg|grep -i msi
>>> [65284.853372] ath10k_pci 0000:05:00.0: pci irq msi-x interrupts 13
>>> irq_mode
>>> 0 reset_mode 0
>>
>>
>> Yep. This at least makes it possible for this weird problem to come
>> into existance. However I still find it a little hard to believe for
>> tasklets to be scheduled this badly. Maybe the device doesn't assert
>> interrupts properly as Adrian suggested? Or maybe they are not mapped
>> properly? I think you're actually the first one to exercise MSI-range
>> support on qca99x0.
>
>
> I applied Rajkumar's patch to disable msi-x today, so maybe that will be
> the end of those problems.
>
> I think upstream might want a warn-on for that wmi issue, even if you don't
> add the work-around code though...just to see if someone else hits it.

Hm.. not really sure. If FW crashes you'll see a ton o warnings..


Michał

_______________________________________________
ath10k mailing list
ath10k@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/ath10k