Re: [PATCH] mailbox: forward the hrtimer if not queued and under a lock

[Bjorn Ardo <bjorn.ardo@axis.com>]

[-- Attachment #1: Type: text/plain, Size: 7533 bytes --]

Hi,


I can confirm that this is an actual issue found on our system, not just 
a theoretical case.


If I add the following trace-code to the original code:


diff --git a/drivers/mailbox/mailbox.c b/drivers/mailbox/mailbox.c
index 3e7d4b20ab34..8e9e82e5f4b1 100644
--- a/drivers/mailbox/mailbox.c
+++ b/drivers/mailbox/mailbox.c
@@ -57,6 +57,7 @@ static void msg_submit(struct mbox_chan *chan)
         void *data;
         int err = -EBUSY;

+       trace_printk("Entering msg_submit\n");
         spin_lock_irqsave(&chan->lock, flags);

         if (!chan->msg_count || chan->active_req)
@@ -85,9 +86,14 @@ static void msg_submit(struct mbox_chan *chan)
         /* kick start the timer immediately to avoid delays */
         if (!err && (chan->txdone_method & TXDONE_BY_POLL)) {
                 /* but only if not already active */
-               if (!hrtimer_active(&chan->mbox->poll_hrt))
+               if (!hrtimer_active(&chan->mbox->poll_hrt)) {
+                       trace_printk("Starting the hr timer from 
submit\n");
hrtimer_start(&chan->mbox->poll_hrt, 0, HRTIMER_MODE_REL);
+               } else {
+                       trace_printk("Not starting the hr timer from 
submit since it is active\n");
+               }
         }
+       trace_printk("Leaving msg_submit\n");
  }

  static void tx_tick(struct mbox_chan *chan, int r)
@@ -121,6 +127,7 @@ static enum hrtimer_restart txdone_hrtimer(struct 
hrtimer *hrtimer)
         bool txdone, resched = false;
         int i;

+       trace_printk("Entering txdone_hrtimer\n");
         for (i = 0; i < mbox->num_chans; i++) {
                 struct mbox_chan *chan = &mbox->chans[i];

@@ -134,8 +141,10 @@ static enum hrtimer_restart txdone_hrtimer(struct 
hrtimer *hrtimer)

         if (resched) {
                 hrtimer_forward_now(hrtimer, 
ms_to_ktime(mbox->txpoll_period));
+               trace_printk("Leaving txdone_hrtimer with restart\n");
                 return HRTIMER_RESTART;
         }
+       trace_printk("Leaving txdone_hrtimer without restart\n");
         return HRTIMER_NORESTART;
  }

Then I get the following trace output (I have cropped a small portion 
around where the error appears):


        vhost-475-480     [000] d..1.   217.440325: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d..1.   217.440332: msg_submit: Starting 
the hr timer from submit
        vhost-475-480     [000] d..1.   217.440336: msg_submit: Leaving 
msg_submit
        vhost-475-480     [000] d.h1.   217.440342: txdone_hrtimer: 
Entering txdone_hrtimer
        vhost-475-480     [000] d.h1.   217.440349: txdone_hrtimer: 
Leaving txdone_hrtimer without restart
        vhost-475-480     [000] d..1.   217.440597: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d..1.   217.440599: msg_submit: Starting 
the hr timer from submit
        vhost-475-480     [000] d..1.   217.440602: msg_submit: Leaving 
msg_submit
           <idle>-0       [001] ..s1.   217.440604: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d.h1.   217.440606: txdone_hrtimer: 
Entering txdone_hrtimer
        vhost-475-480     [000] d.h1.   217.440608: txdone_hrtimer: 
Leaving txdone_hrtimer without restart
           <idle>-0       [001] ..s1.   217.440609: msg_submit: Not 
starting the hr timer from submit since it is active
           <idle>-0       [001] ..s1.   217.440610: msg_submit: Leaving 
msg_submit


If I break down the log above we first have one case that works as 
intended. That is a message being written and a timer started and the 
message have been read when the timer hits:

        vhost-475-480     [000] d..1.   217.440325: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d..1.   217.440332: msg_submit: Starting 
the hr timer from submit
        vhost-475-480     [000] d..1.   217.440336: msg_submit: Leaving 
msg_submit
        vhost-475-480     [000] d.h1.   217.440342: txdone_hrtimer: 
Entering txdone_hrtimer
        vhost-475-480     [000] d.h1.   217.440349: txdone_hrtimer: 
Leaving txdone_hrtimer without restart


After this we write a new message and a new timer is started:

        vhost-475-480     [000] d..1.   217.440597: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d..1.   217.440599: msg_submit: Starting 
the hr timer from submit
        vhost-475-480     [000] d..1.   217.440602: msg_submit: Leaving 
msg_submit


However here comes the race. Now a new message is being written at the 
same time as the hr-timer is handling the first reply (on different CPU's):

           <idle>-0       [001] ..s1.   217.440604: msg_submit: Entering 
msg_submit
        vhost-475-480     [000] d.h1.   217.440606: txdone_hrtimer: 
Entering txdone_hrtimer

And the hr-timer decides not to restart itself:

        vhost-475-480     [000] d.h1.   217.440608: txdone_hrtimer: 
Leaving txdone_hrtimer without restart

And also the new message written decides to not start the timer (even 
thou it requires one), since it has the status of being active during 
the time that the hr-timer callback is running:

           <idle>-0       [001] ..s1.   217.440609: msg_submit: Not 
starting the hr timer from submit since it is active
           <idle>-0       [001] ..s1.   217.440610: msg_submit: Leaving 
msg_submit


So now we end up in a state where we have a message waiting for a reply 
but no timer started that can provide this reply.


Our own mailbox code is attached (it is not upstreamed yet, but it is on 
its way).


Best Regards

Björn

On 4/14/22 16:30, Jassi Brar wrote:
> On Thu, Mar 31, 2022 at 2:01 AM Björn Ardö <bjorn.ardo@axis.com> wrote:
>> This reverts commit c7dacf5b0f32957b24ef29df1207dc2cd8307743,
>> "mailbox: avoid timer start from callback"
>>
>> The previous commit was reverted since it lead to a race that
>> caused the hrtimer to not be started at all. The check for
>> hrtimer_active() in msg_submit() will return true if the
>> callback function txdone_hrtimer() is currently running. This
>> function could return HRTIMER_NORESTART and then the timer
>> will not be restarted, and also msg_submit() will not start
>> the timer. This will lead to a message actually being submitted
>> but no timer will start to check for its compleation.
>>
>> The original fix that added checking hrtimer_active() was added to
>> avoid a warning with hrtimer_forward. Looking in the kernel
>> another solution to avoid this warning is to check hrtimer_is_queued()
>> before calling hrtimer_forward_now() instead. This however requires a
>> lock so the timer is not started by msg_submit() inbetween this check
>> and the hrtimer_forward() call.
>>
> This is a very dense api used by many use-cases, I am not confident
> making any changes without confirming its a real issue with the common
> code. Please share your client code and traces, that will help me get
> a clearer picture.
>
> Thanks.

[-- Attachment #2: mailbox-artpec8.c --]
[-- Type: text/x-csrc, Size: 7507 bytes --]

// SPDX-License-Identifier: GPL-2.0
/* Copyright (C) 2020 Axis Communications AB */

#include <linux/mailbox_controller.h>
#include <linux/platform_device.h>
#include <linux/interrupt.h>
#include <linux/device.h>
#include <linux/iopoll.h>
#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/io.h>
#include <linux/of.h>

#include <linux/soc/axis/artpec-endpoint.h>

#define MAILBOX_MCUCTLR		0x00
#define MAILBOX_INTGR0		0x08
#define MAILBOX_INTCR0		0x0c
#define MAILBOX_INTMR0		0x10
#define MAILBOX_INTSR0		0x14
#define MAILBOX_INTMSR0		0x18
#define MAILBOX_INTGR1		0x1C
#define MAILBOX_INTCR1		0x20
#define MAILBOX_INTMR1		0x24
#define MAILBOX_INTSR1		0x28
#define MAILBOX_INTMSR1		0x2C
#define MAILBOX_IS_VERSION	0x50
#define MAILBOX_ISSR(n)		(0x80 + (n) * 4)

/*
 * We have 32 interrupts and thus 32 channels.  We also have 64 general-purpose
 * ISSR registers, and we use these to send 32-bit values between the hosts for
 * each of the channels.  The first 32 ISSR registers are used for data sent
 * from CPU1 to CPU0 and the remaining are used in the other direction.
 */
#define MAILBOX_NUM_CHANS	32

struct artpec8_mbox {
	void __iomem *base;
	unsigned int cpu;
	struct mutex mutex;
	int irq_low;
	int irq_high;
	struct mbox_controller controller;
	struct mbox_chan chans[MAILBOX_NUM_CHANS];
	const struct artpec_endpoint_info *endpoint;
	u32 msi;
};

static irqreturn_t artpec8_mbox_irq(int irq, void *p)
{
	unsigned int cr, msr, issroffset = 0;
	struct artpec8_mbox *mbox = p;
	u32 clear, ints;

	if (mbox->cpu == 0) {
		msr = MAILBOX_INTMSR0;
		cr = MAILBOX_INTCR0;
	} else {
		msr = MAILBOX_INTMSR1;
		cr = MAILBOX_INTCR1;
		issroffset = 32;
	}

	ints = readl_relaxed(mbox->base + msr);
	if (!ints)
		return IRQ_NONE;

	clear = ints;
	while (ints) {
		unsigned int channum = __ffs(ints);
		struct mbox_chan *chan = &mbox->chans[channum];
		u32 msg;

		ints &= ~BIT(channum);

		msg = readl_relaxed(mbox->base + MAILBOX_ISSR(channum + issroffset));
		mbox_chan_received_data(chan, (void *)(unsigned long)msg);
	}

	writel_relaxed(clear, mbox->base + cr);

	return IRQ_HANDLED;
}

static int artpec8_mbox_send_data(struct mbox_chan *chan, void *data)
{
	struct artpec8_mbox *mbox = chan->con_priv;
	unsigned int channum = chan - mbox->chans;
	unsigned int gr, issroffset = 0;
	u32 arg = (u32)(unsigned long)data;

	if (mbox->cpu == 0) {
		gr = MAILBOX_INTGR1;
		issroffset = 32;
	} else {
		gr = MAILBOX_INTGR0;
	}

	writel(arg, mbox->base + MAILBOX_ISSR(channum + issroffset));

	writel(BIT(channum), mbox->base + gr);

	if (mbox->endpoint)
		writel(mbox->endpoint->msi_data + mbox->msi, mbox->endpoint->msi);

	return 0;
}

static bool artpec8_mbox_last_tx_done(struct mbox_chan *chan)
{
	struct artpec8_mbox *mbox = chan->con_priv;
	unsigned int sr = mbox->cpu == 0 ? MAILBOX_INTSR1 : MAILBOX_INTSR0;
	unsigned int channum = chan - mbox->chans;

	return !(readl_relaxed(mbox->base + sr) & BIT(channum));
}

static int artpec8_mbox_startup(struct mbox_chan *chan)
{
	struct artpec8_mbox *mbox = chan->con_priv;
	unsigned int mr = mbox->cpu == 0 ? MAILBOX_INTMR0 : MAILBOX_INTMR1;
	unsigned int channum = chan - mbox->chans;
	u32 val;

	mutex_lock(&mbox->mutex);

	/*
	 * The hardware manual claims that writing 0 has No Effect, but it also
	 * doesn't provide any way to unmask interrupts, so I'm assuming that
	 * that is a typo.
	 */
	val = readl_relaxed(mbox->base + mr);
	val &= ~BIT(channum);
	writel_relaxed(val, mbox->base + mr);

	mutex_unlock(&mbox->mutex);

	return 0;
}

static void artpec8_mbox_shutdown(struct mbox_chan *chan)
{
	struct artpec8_mbox *mbox = chan->con_priv;
	unsigned int mr = mbox->cpu == 0 ? MAILBOX_INTMR0 : MAILBOX_INTMR1;
	unsigned int channum = chan - mbox->chans;
	u32 val;

	mutex_lock(&mbox->mutex);

	val = readl_relaxed(mbox->base + mr);
	val |= BIT(channum);
	writel_relaxed(val, mbox->base + mr);

	mutex_unlock(&mbox->mutex);
}

static const struct mbox_chan_ops artpec8_mbox_ops = {
	.send_data = artpec8_mbox_send_data,
	.startup = artpec8_mbox_startup,
	.shutdown = artpec8_mbox_shutdown,
	.last_tx_done = artpec8_mbox_last_tx_done,
};

static int artpec8_mbox_reset(struct artpec8_mbox *mbox)
{
	u32 val;
	int ret;

	/* We assume that CPU0 starts up first, so it should do the main reset. */
	if (mbox->cpu != 0) {
		writel_relaxed(~0ul, mbox->base + MAILBOX_INTMR1);
		writel_relaxed(~0ul, mbox->base + MAILBOX_INTCR1);
		return 0;
	}

	/*
	 * It's not entirely clear from the hardware manual, but this reset may
	 * also clear the SEMAPHORE* registers used by the hwspinlock driver.
	 * This will probably not be a problem in practice since both drivers
	 * will presumably be used together by the same clients.
	 */
	writel_relaxed(1, mbox->base + MAILBOX_MCUCTLR);
	ret = readl_relaxed_poll_timeout(mbox->base + MAILBOX_MCUCTLR, val,
					 !val, 0, 100);
	if (ret)
		return ret;

	writel_relaxed(~0ul, mbox->base + MAILBOX_INTMR0);
	writel_relaxed(~0ul, mbox->base + MAILBOX_INTCR0);

	return 0;
}

static int artpec8_mbox_probe(struct platform_device *pdev)
{
	struct device *dev = &pdev->dev;
	struct artpec8_mbox *mbox;
	struct resource	*res;
	const struct artpec_endpoint_info *endpoint;
	int ret;
	int i;

	mbox = devm_kzalloc(dev, sizeof(*mbox), GFP_KERNEL);
	if (!mbox)
		return -ENOMEM;

	of_property_read_u32(dev->of_node, "cpu", &mbox->cpu);
	if (mbox->cpu > 1)
		return -EINVAL;

	res = platform_get_resource(pdev, IORESOURCE_MEM, 0);
	if (!res)
		return -ENXIO;

	mbox->base = devm_ioremap(dev, res->start, resource_size(res));
	if (IS_ERR(mbox->base))
		return PTR_ERR(mbox->base);

	mbox->irq_low = platform_get_irq_optional(pdev, 0);
	if (mbox->irq_low == -EPROBE_DEFER)
		return mbox->irq_low;

	mbox->irq_high = platform_get_irq_optional(pdev, 1);
	if (mbox->irq_high == -EPROBE_DEFER)
		return mbox->irq_high;

	/* Only enable MSI if present */
	mbox->endpoint = NULL;
	endpoint = artpec_endpoint_get_info(&pdev->dev);
	if (endpoint)
		if (!of_property_read_u32(dev->of_node, "msi", &mbox->msi))
			mbox->endpoint = endpoint;

	mutex_init(&mbox->mutex);

	mbox->controller.txdone_irq = false;
	mbox->controller.txdone_poll = true;
	mbox->controller.txpoll_period = 1;

	mbox->controller.dev = dev;
	mbox->controller.num_chans = ARRAY_SIZE(mbox->chans);
	mbox->controller.chans = mbox->chans;
	mbox->controller.ops = &artpec8_mbox_ops;

	for (i = 0; i < ARRAY_SIZE(mbox->chans); i++)
		mbox->chans[i].con_priv = mbox;

	ret = artpec8_mbox_reset(mbox);
	if (ret)
		return ret;

	if (mbox->irq_low > 0) {
		ret = devm_request_irq(dev, mbox->irq_low, artpec8_mbox_irq,
				       0, "mbox-low", mbox);
		if (ret)
			return ret;
	}

	if (mbox->irq_high > 0) {
		ret = devm_request_irq(dev, mbox->irq_high, artpec8_mbox_irq,
				       0, "mbox-high", mbox);
		if (ret)
			return ret;
	}

	platform_set_drvdata(pdev, mbox);

	return mbox_controller_register(&mbox->controller);
}

static int artpec8_mbox_remove(struct platform_device *pdev)
{
	struct artpec8_mbox *mbox = platform_get_drvdata(pdev);

	mbox_controller_unregister(&mbox->controller);

	return 0;
}

static const struct of_device_id artpec8_mbox_match[] = {
	{ .compatible = "samsung,artpec8-mailbox" },
	{ /* Sentinel */ }
};
MODULE_DEVICE_TABLE(of, artpec8_mbox_match);

static struct platform_driver artpec8_mbox_driver = {
	.probe	= artpec8_mbox_probe,
	.remove	= artpec8_mbox_remove,
	.driver	= {
		.name	= "artpec8-mailbox",
		.of_match_table	= artpec8_mbox_match,
	},
};

module_platform_driver(artpec8_mbox_driver);

MODULE_LICENSE("GPL v2");