[PATCH] wifi: rtw88: usb: silence log flooding error message

[PATCH] wifi: rtw88: usb: silence log flooding error message

[Sascha Hauer]

When receiving more rx packets than the kernel can handle the driver
drops the packets and issues an error message. This is bad for two
reasons. The logs are flooded with myriads of messages, but then time
consumed for printing messages in that critical code path brings down
the device. After some time of excessive rx load the driver responds
with:

rtw_8822cu 1-1:1.2: failed to get tx report from firmware
rtw_8822cu 1-1:1.2: firmware failed to report density after scan
rtw_8822cu 1-1:1.2: firmware failed to report density after scan

The device stops working until being replugged.

Fix this by lowering the priority to debug level and also by
ratelimiting it.

Fixes: a82dfd33d1237 ("wifi: rtw88: Add common USB chip support")
Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
---
 drivers/net/wireless/realtek/rtw88/usb.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/net/wireless/realtek/rtw88/usb.c b/drivers/net/wireless/realtek/rtw88/usb.c
index 44a5fafb99055..976eafa739a2d 100644
--- a/drivers/net/wireless/realtek/rtw88/usb.c
+++ b/drivers/net/wireless/realtek/rtw88/usb.c
@@ -535,7 +535,7 @@ static void rtw_usb_rx_handler(struct work_struct *work)
 		}
 
 		if (skb_queue_len(&rtwusb->rx_queue) >= RTW_USB_MAX_RXQ_LEN) {
-			rtw_err(rtwdev, "failed to get rx_queue, overflow\n");
+			dev_dbg_ratelimited(rtwdev->dev, "failed to get rx_queue, overflow\n");
 			dev_kfree_skb_any(skb);
 			continue;
 		}
-- 
2.39.2

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Simon Horman]

On Wed, May 24, 2023 at 12:39:34PM +0200, Sascha Hauer wrote:
> When receiving more rx packets than the kernel can handle the driver
> drops the packets and issues an error message. This is bad for two
> reasons. The logs are flooded with myriads of messages, but then time
> consumed for printing messages in that critical code path brings down
> the device. After some time of excessive rx load the driver responds
> with:
> 
> rtw_8822cu 1-1:1.2: failed to get tx report from firmware
> rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> 
> The device stops working until being replugged.
> 
> Fix this by lowering the priority to debug level and also by
> ratelimiting it.
> 
> Fixes: a82dfd33d1237 ("wifi: rtw88: Add common USB chip support")
> Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
> ---
>  drivers/net/wireless/realtek/rtw88/usb.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/drivers/net/wireless/realtek/rtw88/usb.c b/drivers/net/wireless/realtek/rtw88/usb.c
> index 44a5fafb99055..976eafa739a2d 100644
> --- a/drivers/net/wireless/realtek/rtw88/usb.c
> +++ b/drivers/net/wireless/realtek/rtw88/usb.c
> @@ -535,7 +535,7 @@ static void rtw_usb_rx_handler(struct work_struct *work)
>  		}
>  
>  		if (skb_queue_len(&rtwusb->rx_queue) >= RTW_USB_MAX_RXQ_LEN) {
> -			rtw_err(rtwdev, "failed to get rx_queue, overflow\n");
> +			dev_dbg_ratelimited(rtwdev->dev, "failed to get rx_queue, overflow\n");

This is certainly an improvement. But as I understand things
it is still somewhat verbose if the condition persists.
Did you consider dev_dbg_once()?

>  			dev_kfree_skb_any(skb);
>  			continue;
>  		}
> -- 
> 2.39.2
> 

RE: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Ping-Ke Shih]

> -----Original Message-----
> From: Sascha Hauer <s.hauer@pengutronix.de>
> Sent: Wednesday, May 24, 2023 6:40 PM
> To: linux-wireless <linux-wireless@vger.kernel.org>
> Cc: Hans Ulli Kroll <linux@ulli-kroll.de>; Larry Finger <Larry.Finger@lwfinger.net>; Ping-Ke Shih
> <pkshih@realtek.com>; Tim K <tpkuester@gmail.com>; Alex G . <mr.nuke.me@gmail.com>; Nick Morrow
> <morrownr@gmail.com>; Viktor Petrenko <g0000ga@gmail.com>; Andreas Henriksson <andreas@fatal.se>;
> ValdikSS <iam@valdikss.org.ru>; kernel@pengutronix.de; petter@technux.se; Sascha Hauer
> <s.hauer@pengutronix.de>
> Subject: [PATCH] wifi: rtw88: usb: silence log flooding error message
> 
> When receiving more rx packets than the kernel can handle the driver
> drops the packets and issues an error message.

The workqueue rtw88_usb is using is:

	rtwusb->rxwq = create_singlethread_workqueue("rtw88_usb: rx wq");

Have you tried workqueue with flags WQ_UNBOUND and WQ_HIGHPRI? Like,

	rtwusb->rxwq = alloc_workqueue("rtw88_usb: rx wq", WQ_UNBOUND | WQ_HIGHPRI, 0);
or
	rtwusb->rxwq = alloc_ordered_workqueue("rtw88_usb: rx wq", WQ_HIGHPRI);

Then, driver get more time to process RX, so it could ease flooding messages. 

Ping-Ke

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Sascha Hauer]

On Thu, May 25, 2023 at 12:45:23AM +0000, Ping-Ke Shih wrote:
> 
> 
> > -----Original Message-----
> > From: Sascha Hauer <s.hauer@pengutronix.de>
> > Sent: Wednesday, May 24, 2023 6:40 PM
> > To: linux-wireless <linux-wireless@vger.kernel.org>
> > Cc: Hans Ulli Kroll <linux@ulli-kroll.de>; Larry Finger <Larry.Finger@lwfinger.net>; Ping-Ke Shih
> > <pkshih@realtek.com>; Tim K <tpkuester@gmail.com>; Alex G . <mr.nuke.me@gmail.com>; Nick Morrow
> > <morrownr@gmail.com>; Viktor Petrenko <g0000ga@gmail.com>; Andreas Henriksson <andreas@fatal.se>;
> > ValdikSS <iam@valdikss.org.ru>; kernel@pengutronix.de; petter@technux.se; Sascha Hauer
> > <s.hauer@pengutronix.de>
> > Subject: [PATCH] wifi: rtw88: usb: silence log flooding error message
> > 
> > When receiving more rx packets than the kernel can handle the driver
> > drops the packets and issues an error message.
> 
> The workqueue rtw88_usb is using is:
> 
> 	rtwusb->rxwq = create_singlethread_workqueue("rtw88_usb: rx wq");
> 
> Have you tried workqueue with flags WQ_UNBOUND and WQ_HIGHPRI? Like,
> 
> 	rtwusb->rxwq = alloc_workqueue("rtw88_usb: rx wq", WQ_UNBOUND | WQ_HIGHPRI, 0);
> or
> 	rtwusb->rxwq = alloc_ordered_workqueue("rtw88_usb: rx wq", WQ_HIGHPRI);
> 
> Then, driver get more time to process RX, so it could ease flooding messages. 

No, I haven't tried this. Regardless of that, I think it still makes
sense to rate limit the messages. There will always be a slower system
that can't cope with the number of packets even with a higher priority
workqueue.

Sascha


-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Sascha Hauer]

On Wed, May 24, 2023 at 01:34:52PM +0200, Simon Horman wrote:
> On Wed, May 24, 2023 at 12:39:34PM +0200, Sascha Hauer wrote:
> > When receiving more rx packets than the kernel can handle the driver
> > drops the packets and issues an error message. This is bad for two
> > reasons. The logs are flooded with myriads of messages, but then time
> > consumed for printing messages in that critical code path brings down
> > the device. After some time of excessive rx load the driver responds
> > with:
> > 
> > rtw_8822cu 1-1:1.2: failed to get tx report from firmware
> > rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> > rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> > 
> > The device stops working until being replugged.
> > 
> > Fix this by lowering the priority to debug level and also by
> > ratelimiting it.
> > 
> > Fixes: a82dfd33d1237 ("wifi: rtw88: Add common USB chip support")
> > Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
> > ---
> >  drivers/net/wireless/realtek/rtw88/usb.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> > 
> > diff --git a/drivers/net/wireless/realtek/rtw88/usb.c b/drivers/net/wireless/realtek/rtw88/usb.c
> > index 44a5fafb99055..976eafa739a2d 100644
> > --- a/drivers/net/wireless/realtek/rtw88/usb.c
> > +++ b/drivers/net/wireless/realtek/rtw88/usb.c
> > @@ -535,7 +535,7 @@ static void rtw_usb_rx_handler(struct work_struct *work)
> >  		}
> >  
> >  		if (skb_queue_len(&rtwusb->rx_queue) >= RTW_USB_MAX_RXQ_LEN) {
> > -			rtw_err(rtwdev, "failed to get rx_queue, overflow\n");
> > +			dev_dbg_ratelimited(rtwdev->dev, "failed to get rx_queue, overflow\n");
> 
> This is certainly an improvement. But as I understand things
> it is still somewhat verbose if the condition persists.
> Did you consider dev_dbg_once()?

My rationale was that dev_dbg() is normally disabled anyway. With
CONFIG_DYNAMIC_PRINTK you would still have fine grained control if you
want to see this message or not.

Personally I don't care that much, I would switch to dev_dbg_once() if
that's preferred.

Sascha

-- 
Pengutronix e.K.                           |                             |
Steuerwalder Str. 21                       | http://www.pengutronix.de/  |
31137 Hildesheim, Germany                  | Phone: +49-5121-206917-0    |
Amtsgericht Hildesheim, HRA 2686           | Fax:   +49-5121-206917-5555 |

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Ping-Ke Shih]

On Fri, 2023-05-26 at 11:33 +0200, Sascha Hauer wrote:
> 
> On Thu, May 25, 2023 at 12:45:23AM +0000, Ping-Ke Shih wrote:
> > 
> > > -----Original Message-----
> > > From: Sascha Hauer <s.hauer@pengutronix.de>
> > > Sent: Wednesday, May 24, 2023 6:40 PM
> > > To: linux-wireless <linux-wireless@vger.kernel.org>
> > > Cc: Hans Ulli Kroll <linux@ulli-kroll.de>; Larry Finger <Larry.Finger@lwfinger.net>; Ping-Ke
> > > Shih
> > > <pkshih@realtek.com>; Tim K <tpkuester@gmail.com>; Alex G . <mr.nuke.me@gmail.com>; Nick
> > > Morrow
> > > <morrownr@gmail.com>; Viktor Petrenko <g0000ga@gmail.com>; Andreas Henriksson <
> > > andreas@fatal.se>;
> > > ValdikSS <iam@valdikss.org.ru>; kernel@pengutronix.de; petter@technux.se; Sascha Hauer
> > > <s.hauer@pengutronix.de>
> > > Subject: [PATCH] wifi: rtw88: usb: silence log flooding error message
> > > 
> > > When receiving more rx packets than the kernel can handle the driver
> > > drops the packets and issues an error message.
> > 
> > The workqueue rtw88_usb is using is:
> > 
> >       rtwusb->rxwq = create_singlethread_workqueue("rtw88_usb: rx wq");
> > 
> > Have you tried workqueue with flags WQ_UNBOUND and WQ_HIGHPRI? Like,
> > 
> >       rtwusb->rxwq = alloc_workqueue("rtw88_usb: rx wq", WQ_UNBOUND | WQ_HIGHPRI, 0);
> > or
> >       rtwusb->rxwq = alloc_ordered_workqueue("rtw88_usb: rx wq", WQ_HIGHPRI);
> > 
> > Then, driver get more time to process RX, so it could ease flooding messages.
> 
> No, I haven't tried this. Regardless of that, I think it still makes
> sense to rate limit the messages. There will always be a slower system
> that can't cope with the number of packets even with a higher priority
> workqueue.
> 

My opinion is just related thing that is an idea to get a little bit
improvement. But, you are right. This may be useless for slower system.
Also, your patch totally make sense to me. 

Reviewed-by: Ping-Ke Shih <pkshih@realtek.com>

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Kalle Valo]

Sascha Hauer <s.hauer@pengutronix.de> wrote:

> When receiving more rx packets than the kernel can handle the driver
> drops the packets and issues an error message. This is bad for two
> reasons. The logs are flooded with myriads of messages, but then time
> consumed for printing messages in that critical code path brings down
> the device. After some time of excessive rx load the driver responds
> with:
> 
> rtw_8822cu 1-1:1.2: failed to get tx report from firmware
> rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> 
> The device stops working until being replugged.
> 
> Fix this by lowering the priority to debug level and also by
> ratelimiting it.
> 
> Fixes: a82dfd33d1237 ("wifi: rtw88: Add common USB chip support")
> Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
> Reviewed-by: Ping-Ke Shih <pkshih@realtek.com>

Patch applied to wireless-next.git, thanks.

1f1784a59caf wifi: rtw88: usb: silence log flooding error message

-- 
https://patchwork.kernel.org/project/linux-wireless/patch/20230524103934.1019096-1-s.hauer@pengutronix.de/

https://wireless.wiki.kernel.org/en/developers/documentation/submittingpatches

Re: [PATCH] wifi: rtw88: usb: silence log flooding error message

[Simon Horman]

On Fri, May 26, 2023 at 12:17:36PM +0200, Sascha Hauer wrote:
> On Wed, May 24, 2023 at 01:34:52PM +0200, Simon Horman wrote:
> > On Wed, May 24, 2023 at 12:39:34PM +0200, Sascha Hauer wrote:
> > > When receiving more rx packets than the kernel can handle the driver
> > > drops the packets and issues an error message. This is bad for two
> > > reasons. The logs are flooded with myriads of messages, but then time
> > > consumed for printing messages in that critical code path brings down
> > > the device. After some time of excessive rx load the driver responds
> > > with:
> > > 
> > > rtw_8822cu 1-1:1.2: failed to get tx report from firmware
> > > rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> > > rtw_8822cu 1-1:1.2: firmware failed to report density after scan
> > > 
> > > The device stops working until being replugged.
> > > 
> > > Fix this by lowering the priority to debug level and also by
> > > ratelimiting it.
> > > 
> > > Fixes: a82dfd33d1237 ("wifi: rtw88: Add common USB chip support")
> > > Signed-off-by: Sascha Hauer <s.hauer@pengutronix.de>
> > > ---
> > >  drivers/net/wireless/realtek/rtw88/usb.c | 2 +-
> > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > > 
> > > diff --git a/drivers/net/wireless/realtek/rtw88/usb.c b/drivers/net/wireless/realtek/rtw88/usb.c
> > > index 44a5fafb99055..976eafa739a2d 100644
> > > --- a/drivers/net/wireless/realtek/rtw88/usb.c
> > > +++ b/drivers/net/wireless/realtek/rtw88/usb.c
> > > @@ -535,7 +535,7 @@ static void rtw_usb_rx_handler(struct work_struct *work)
> > >  		}
> > >  
> > >  		if (skb_queue_len(&rtwusb->rx_queue) >= RTW_USB_MAX_RXQ_LEN) {
> > > -			rtw_err(rtwdev, "failed to get rx_queue, overflow\n");
> > > +			dev_dbg_ratelimited(rtwdev->dev, "failed to get rx_queue, overflow\n");
> > 
> > This is certainly an improvement. But as I understand things
> > it is still somewhat verbose if the condition persists.
> > Did you consider dev_dbg_once()?
> 
> My rationale was that dev_dbg() is normally disabled anyway. With
> CONFIG_DYNAMIC_PRINTK you would still have fine grained control if you
> want to see this message or not.
> 
> Personally I don't care that much, I would switch to dev_dbg_once() if
> that's preferred.

No strong preference from my side.