Received-SPF: pass (google.com: domain of linux-kernel-owner@vger.kernel.org designates 2620:137:e000::1:20 as permitted sender) client-ip=2620:137:e000::1:20;
MIME-Version: 1.0
References: <20200923123916.1115962-1-jbrunet@baylibre.com>
 <20201015134628.GA11989@arm.com> <1jlfg7k2ux.fsf@starbuckisacylon.baylibre.com>
 <CABb+yY1-MBac0e6xQwWkHRo3bqJNMWb4xQzdaGdrYT=n5zRvtw@mail.gmail.com>
 <20201016085217.GA12323@arm.com> <1jk0vqk0ju.fsf@starbuckisacylon.baylibre.com>
 <CABb+yY0pDxQ7B+NPsEz325-_X2nSJngnfER7uOLVyoBLoH37cA@mail.gmail.com>
 <1jft6ej91c.fsf@starbuckisacylon.baylibre.com> <CABb+yY0Ktj9O9YxGDM0q_6MnKPBCopm+RzQa6SM64Pn_60a2pA@mail.gmail.com>
In-Reply-To: <CABb+yY0Ktj9O9YxGDM0q_6MnKPBCopm+RzQa6SM64Pn_60a2pA@mail.gmail.com>
From:   Da Xue <da@lessconfused.com>
Date:   Tue, 19 Jul 2022 03:08:14 -0400
Message-ID: <CACdvmAi=4qneshSgZ8ApD-uwH-JSe5xcO-qOyvFOvoYQ9Nk=mQ@mail.gmail.com>
Subject: Re: [PATCH] mailbox: cancel timer before starting it
To:     Jassi Brar <jassisinghbrar@gmail.com>
Cc:     Jerome Brunet <jbrunet@baylibre.com>,
        Ionela Voinescu <ionela.voinescu@arm.com>,
        Kevin Hilman <khilman@baylibre.com>,
        "open list:ARM/Amlogic Meson..." <linux-amlogic@lists.infradead.org>,
        Da Xue <da@libre.computer>,
        Linux Kernel Mailing List <linux-kernel@vger.kernel.org>,
        Qi Duan <qi.duan@amlogic.com>
Content-Type: text/plain; charset="UTF-8"
Precedence: bulk

On Fri, Oct 16, 2020 at 3:27 PM Jassi Brar <jassisinghbrar@gmail.com> wrote:
>
> On Fri, Oct 16, 2020 at 1:54 PM Jerome Brunet <jbrunet@baylibre.com> wrote:
> >
> >
> > On Fri 16 Oct 2020 at 19:33, Jassi Brar <jassisinghbrar@gmail.com> wrote:
> >
> > > On Fri, Oct 16, 2020 at 4:00 AM Jerome Brunet <jbrunet@baylibre.com> wrote:
> > >>
> > >>
> > >> On Fri 16 Oct 2020 at 10:52, Ionela Voinescu <ionela.voinescu@arm.com> wrote:
> > >>
> > >> > On Thursday 15 Oct 2020 at 13:45:54 (-0500), Jassi Brar wrote:
> > >> > [..]
> > >> >> > >> --- a/drivers/mailbox/mailbox.c
> > >> >> > >> +++ b/drivers/mailbox/mailbox.c
> > >> >> > >> @@ -82,9 +82,13 @@ static void msg_submit(struct mbox_chan *chan)
> > >> >> > >>  exit:
> > >> >> > >>      spin_unlock_irqrestore(&chan->lock, flags);
> > >> >> > >>
> > >> >> > >> -    if (!err && (chan->txdone_method & TXDONE_BY_POLL))
> > >> >> > >> -            /* kick start the timer immediately to avoid delays */
> > >> >> > >> +    if (!err && (chan->txdone_method & TXDONE_BY_POLL)) {
> > >> >> > >> +            /* Disable the timer if already active ... */
> > >> >> > >> +            hrtimer_cancel(&chan->mbox->poll_hrt);
> > >> >> > >> +
> > >> >> > >> +            /* ... and kick start it immediately to avoid delays */
> > >> >> > >>              hrtimer_start(&chan->mbox->poll_hrt, 0, HRTIMER_MODE_REL);
> > >> >> > >> +    }
> > >> >> > >>  }
> > >> >> > >>
> > >> >> > >>  static void tx_tick(struct mbox_chan *chan, int r)
> > >> >> > >
> > >> >> > > I've tracked a regression back to this commit. Details to reproduce:
> > >> >> >
> > >> >> > Hi Ionela,
> > >> >> >
> > >> >> > I don't have access to your platform and I don't get what is going on
> > >> >> > from the log below.
> > >> >> >
> > >> >> > Could you please give us a bit more details about what is going on ?
> > >> >> >
> > >> >> > All this patch does is add hrtimer_cancel().
> > >> >> > * It is needed if the timer had already been started, which is
> > >> >> >   appropriate AFAIU
> > >> >> > * It is a NO-OP is the timer is not active.
> > >> >> >
> > >> >> Can you please try using hrtimer_try_to_cancel() instead ?
> > >> >>
> > >> >
> > >> > Yes, using hrtimer_try_to_cancel() instead works for me. But doesn't
> > >> > this limit how effective this change is? AFAIU, this will possibly only
> > >> > reduce the chances for the race condition, but not solve it.
> > >> >
> > >>
> > >> It is also my understanding, hrtimer_try_to_cancel() would remove a
> > >> timer which as not already started but would return withtout doing
> > >> anything if the callback is already running ... which is the original
> > >> problem
> > >>
> > > If we are running in the callback path, hrtimer_try_to_cancel will
> > > return -1, in which case we could skip hrtimer_start.
> > > Anyways, I think simply checking for hrtimer_active should effect the same.
> > > I have submitted a patch, of course not tested.
> >
> > Yes it sloves this race but ...
> >
> Thanks for confirmation.
>
> > If a race is possible between a timer callback rescheduling itself (which
> > is not that uncommon) and another thread trying to cancel it
> >
> In our case, we should not be cancelling+restarting the timer in the
> first place, because txdone_hrtimer will take care of it via
> hrtimer_forward_now.
>
> >, maybe
> > there is something worth fixing in hrtimer ? Also, mailbox calls
> > hrtimer_cancel() in unregister ... are we confident this would work ?
> >
> Yes. After unregister() every channel is supposed to die and so must
> its resources.
>
> -jassi

Hi,

I'm running into an issue where I get "rcu: INFO: rcu_preempt detected
stalls on CPUs/tasks" when booting Linux distributions once every 5 or
so reboots. The system sticks on systemd starting for ~20 seconds
before rcu_preempt prints a message. This only happens on Amlogic (I
tested S805X/S905X/S905D) and I do not get this problem on my
Allwinner or Rockchip boards with the same kernel and image. I have
tried 5.15, 5.18, and 5.19. I dumped a bunch of logs here from the
three kernel versions but the content is the same.
https://github.com/libre-computer-project/libretech-linux/issues/5

+ mount -n -o move /sys /root/sys
+ mount -n -o move /proc /root/proc
+ exec run-init /root /sbin/init
[   26.485689] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[   26.486217] rcu:     Tasks blocked on level-0 rcu_node (CPUs 0-3): P1
[   26.492332]  (detected by 3, t=5252 jiffies, g=-315, q=546)
[   26.497846] task:run-init        state:R  running task     stack:
 0 pid:    1 ppid:     0 flags:0x00000004
[   26.507719] Call trace:
[   26.510063]  dump_backtrace.part.6+0xdc/0xe8
[   26.514306]  show_stack+0x18/0x68
[   26.517574]  sched_show_task+0x154/0x198
[   26.521461]  rcu_sched_clock_irq+0xd10/0xdd8
[   26.525690]  update_process_times+0x9c/0xd0
[   26.529829]  tick_sched_handle.isra.19+0x34/0x58
[   26.534405]  tick_sched_timer+0x4c/0xa8
[   26.538192]  __hrtimer_run_queues+0x120/0x1b8
[   26.542510]  hrtimer_interrupt+0xd8/0x238
[   26.546474]  arch_timer_handler_phys+0x2c/0x50
[   26.550877]  handle_percpu_devid_irq+0x84/0x138
[   26.555363]  generic_handle_domain_irq+0x2c/0x48
[   26.559935]  gic_handle_irq+0xa4/0xc0
[   26.563549]  call_on_irq_stack+0x2c/0x58
[   26.567432]  do_interrupt_handler+0x80/0x88
[   26.571574]  el1_interrupt+0x38/0x70
[   26.575105]  el1h_64_irq_handler+0x18/0x28
[   26.582437]  el1h_64_irq+0x64/0x68
[   26.585712]  xas_descend+0x0/0x88
[   26.588947]  xas_find+0x190/0x1d8
[   26.592182]  find_lock_entries+0x7c/0x280
[   26.596121]  truncate_inode_pages_range+0xa8/0x490
[   26.600843]  truncate_inode_pages_final+0x58/0x78
[   26.605453]  evict+0x144/0x150
[   26.608471]  iput+0x128/0x190
[   26.611442]  do_unlinkat+0x17c/0x2a8
[   26.614817]  __arm64_sys_unlinkat+0x40/0x88
[   26.618928]  invoke_syscall+0x44/0x100
[   26.622599]  el0_svc_common.constprop.3+0x6c/0xf0
[   26.627237]  do_el0_svc+0x24/0x88
[   26.630473]  el0_svc+0x20/0x60
[   26.633447]  el0t_64_sync_handler+0x90/0xb8
[   26.637562]  el0t_64_sync+0x170/0x174
[   33.757714] VCC_CARD: disabling

I have turned on systemd debug and it does not print anything. The
message is the same every time and I rebuilt the filesystem multiple
times with both ext4 and btrfs roots across the devices.

I'm not sure if this is an extension or corner case of the origin
hr_timer problem. Any ideas?

Best,
Da