| Message ID | 20230524103934.1019096-1-s.hauer@pengutronix.de (mailing list archive) |
|---|---|
| State | Accepted |
| Commit | 1f1784a59caf3eefd127908a1a3cf224017ff9c7 |
| Delegated to: | Kalle Valo |
| Headers | show |
| Series | wifi: rtw88: usb: silence log flooding error message | expand |
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 >
> -----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
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
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
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>
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
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.
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; }
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(-)