[PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[Alexandru Ardelean]

From: Alexandru Ardelean <ardeleanalex@gmail.com>

Even though it may be user-space's fault for this error (some application
terminated or crashed without cleaning up it's endpoint), the rpmsg
communication should not overflow the syslog with too many messages.

A dev_warn_ratelimited() seems like a good alternative in case this can
occur.

Signed-off-by: Alexandru Ardelean <ardeleanalex@gmail.com>
---
 drivers/rpmsg/virtio_rpmsg_bus.c | 2 +-
 1 file changed, 1 insertion(+), 1 deletion(-)

diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
index 8e49a3bacfc7..546f0fb66f1d 100644
--- a/drivers/rpmsg/virtio_rpmsg_bus.c
+++ b/drivers/rpmsg/virtio_rpmsg_bus.c
@@ -749,7 +749,7 @@ static int rpmsg_recv_single(struct virtproc_info *vrp, struct device *dev,
 		/* farewell, ept, we don't need you anymore */
 		kref_put(&ept->refcount, __ept_release);
 	} else
-		dev_warn(dev, "msg received with no recipient\n");
+		dev_warn_ratelimited(dev, "msg received with no recipient\n");
 
 	/* publish the real size of the buffer */
 	rpmsg_sg_init(&sg, msg, vrp->buf_size);
-- 
2.31.1

Re: [PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[Bjorn Andersson]

On Tue 28 Sep 08:29 CDT 2021, Alexandru Ardelean wrote:

> From: Alexandru Ardelean <ardeleanalex@gmail.com>
> 
> Even though it may be user-space's fault for this error (some application
> terminated or crashed without cleaning up it's endpoint), the rpmsg
> communication should not overflow the syslog with too many messages.
> 
> A dev_warn_ratelimited() seems like a good alternative in case this can
> occur.
> 

Is there anything a user could/should do when they see this entry in
their log?

It doesn't look very actionable to me, should we perhaps degrade it
further to just a dev_dbg()?

Regards,
Bjorn

> Signed-off-by: Alexandru Ardelean <ardeleanalex@gmail.com>
> ---
>  drivers/rpmsg/virtio_rpmsg_bus.c | 2 +-
>  1 file changed, 1 insertion(+), 1 deletion(-)
> 
> diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> index 8e49a3bacfc7..546f0fb66f1d 100644
> --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> @@ -749,7 +749,7 @@ static int rpmsg_recv_single(struct virtproc_info *vrp, struct device *dev,
>  		/* farewell, ept, we don't need you anymore */
>  		kref_put(&ept->refcount, __ept_release);
>  	} else
> -		dev_warn(dev, "msg received with no recipient\n");
> +		dev_warn_ratelimited(dev, "msg received with no recipient\n");
>  
>  	/* publish the real size of the buffer */
>  	rpmsg_sg_init(&sg, msg, vrp->buf_size);
> -- 
> 2.31.1
> 

Re: [PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[Alexandru Ardelean]

On Wed, Sep 29, 2021 at 12:33 AM Bjorn Andersson
<bjorn.andersson@linaro.org> wrote:
>
> On Tue 28 Sep 08:29 CDT 2021, Alexandru Ardelean wrote:
>
> > From: Alexandru Ardelean <ardeleanalex@gmail.com>
> >
> > Even though it may be user-space's fault for this error (some application
> > terminated or crashed without cleaning up it's endpoint), the rpmsg
> > communication should not overflow the syslog with too many messages.
> >
> > A dev_warn_ratelimited() seems like a good alternative in case this can
> > occur.
> >
>
> Is there anything a user could/should do when they see this entry in
> their log?

Not really, no.
The userspace application would need to respawn, or some systemd (or
similar process manager) would need to respawn the application it
should recover the state, and communication should resume normally.
I think this message is good mostly as informative.

>
> It doesn't look very actionable to me, should we perhaps degrade it
> further to just a dev_dbg()?

It's not actionable unfortunately.
But I feel it is useful to have this message, until the application recovers.
Mostly to be informative.
A more robust mechanism would be to setup some counters, where we
count the number of missed messages.
And then access this counter via sysfs or something.

The problem is that a high-rate of dev_warn() (during failure),
temporarily increases system CPU usage & load-average, making the
recovery a bit slower, because systemd-journald is processing these
messages from the kernel.
So, dev_dbg() would definitely help, but would also require us to bump
the system log-level to see the messages.
And if they occur and we don't see them, it causes more questions and
debugging, because people won't know for sure what the issue is.

Ultimately, dev_dbg() or dev_warn_rate_limited() are both fine.
The goal is to avoid the temporary increase in CPU load.
I just wanted to state my arguments for dev_warn_ratelimite() :)

Thank you
Alex

>
> Regards,
> Bjorn
>
> > Signed-off-by: Alexandru Ardelean <ardeleanalex@gmail.com>
> > ---
> >  drivers/rpmsg/virtio_rpmsg_bus.c | 2 +-
> >  1 file changed, 1 insertion(+), 1 deletion(-)
> >
> > diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> > index 8e49a3bacfc7..546f0fb66f1d 100644
> > --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> > +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> > @@ -749,7 +749,7 @@ static int rpmsg_recv_single(struct virtproc_info *vrp, struct device *dev,
> >               /* farewell, ept, we don't need you anymore */
> >               kref_put(&ept->refcount, __ept_release);
> >       } else
> > -             dev_warn(dev, "msg received with no recipient\n");
> > +             dev_warn_ratelimited(dev, "msg received with no recipient\n");
> >
> >       /* publish the real size of the buffer */
> >       rpmsg_sg_init(&sg, msg, vrp->buf_size);
> > --
> > 2.31.1
> >

Re: [PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[Alexandru Ardelean]

On Wed, Sep 29, 2021 at 12:40 PM Alexandru Ardelean
<ardeleanalex@gmail.com> wrote:
>
> On Wed, Sep 29, 2021 at 12:33 AM Bjorn Andersson
> <bjorn.andersson@linaro.org> wrote:
> >
> > On Tue 28 Sep 08:29 CDT 2021, Alexandru Ardelean wrote:
> >
> > > From: Alexandru Ardelean <ardeleanalex@gmail.com>
> > >
> > > Even though it may be user-space's fault for this error (some application
> > > terminated or crashed without cleaning up it's endpoint), the rpmsg
> > > communication should not overflow the syslog with too many messages.
> > >
> > > A dev_warn_ratelimited() seems like a good alternative in case this can
> > > occur.
> > >
> >
> > Is there anything a user could/should do when they see this entry in
> > their log?
>
> Not really, no.
> The userspace application would need to respawn, or some systemd (or
> similar process manager) would need to respawn the application it
> should recover the state, and communication should resume normally.
> I think this message is good mostly as informative.
>
> >
> > It doesn't look very actionable to me, should we perhaps degrade it
> > further to just a dev_dbg()?
>
> It's not actionable unfortunately.
> But I feel it is useful to have this message, until the application recovers.
> Mostly to be informative.
> A more robust mechanism would be to setup some counters, where we
> count the number of missed messages.
> And then access this counter via sysfs or something.
>
> The problem is that a high-rate of dev_warn() (during failure),
> temporarily increases system CPU usage & load-average, making the
> recovery a bit slower, because systemd-journald is processing these
> messages from the kernel.
> So, dev_dbg() would definitely help, but would also require us to bump
> the system log-level to see the messages.
> And if they occur and we don't see them, it causes more questions and
> debugging, because people won't know for sure what the issue is.
>
> Ultimately, dev_dbg() or dev_warn_rate_limited() are both fine.
> The goal is to avoid the temporary increase in CPU load.
> I just wanted to state my arguments for dev_warn_ratelimite() :)
>

Ping on this :)

> Thank you
> Alex
>
> >
> > Regards,
> > Bjorn
> >
> > > Signed-off-by: Alexandru Ardelean <ardeleanalex@gmail.com>
> > > ---
> > >  drivers/rpmsg/virtio_rpmsg_bus.c | 2 +-
> > >  1 file changed, 1 insertion(+), 1 deletion(-)
> > >
> > > diff --git a/drivers/rpmsg/virtio_rpmsg_bus.c b/drivers/rpmsg/virtio_rpmsg_bus.c
> > > index 8e49a3bacfc7..546f0fb66f1d 100644
> > > --- a/drivers/rpmsg/virtio_rpmsg_bus.c
> > > +++ b/drivers/rpmsg/virtio_rpmsg_bus.c
> > > @@ -749,7 +749,7 @@ static int rpmsg_recv_single(struct virtproc_info *vrp, struct device *dev,
> > >               /* farewell, ept, we don't need you anymore */
> > >               kref_put(&ept->refcount, __ept_release);
> > >       } else
> > > -             dev_warn(dev, "msg received with no recipient\n");
> > > +             dev_warn_ratelimited(dev, "msg received with no recipient\n");
> > >
> > >       /* publish the real size of the buffer */
> > >       rpmsg_sg_init(&sg, msg, vrp->buf_size);
> > > --
> > > 2.31.1
> > >

Re: (subset) [PATCH] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient

[Bjorn Andersson]

On Tue, 28 Sep 2021 16:29:02 +0300, Alexandru Ardelean wrote:
> From: Alexandru Ardelean <ardeleanalex@gmail.com>
> 
> Even though it may be user-space's fault for this error (some application
> terminated or crashed without cleaning up it's endpoint), the rpmsg
> communication should not overflow the syslog with too many messages.
> 
> A dev_warn_ratelimited() seems like a good alternative in case this can
> occur.
> 
> [...]

Applied, thanks!

[1/1] rpmsg: virtio_rpmsg_bus: use dev_warn_ratelimited for msg with no recipient
      commit: 63b8d79916672d35069962d87d1540c534cb2438

Best regards,
-- 
Bjorn Andersson <bjorn.andersson@linaro.org>