Message-ID: <20220716153424.49327-1-zhengyejian1@huawei.com>
Date:   Sat, 16 Jul 2022 23:34:24 +0800
From:   Zheng Yejian <zhengyejian1@...wei.com>
To:     <gregkh@...uxfoundation.org>
CC:     <jiangshanlai@...il.com>, <josh@...htriplett.org>,
        <linux-kernel@...r.kernel.org>, <mathieu.desnoyers@...icios.com>,
        <paulmck@...ux.vnet.ibm.com>, <peterz@...radead.org>,
        <rostedt@...dmis.org>, <stable@...r.kernel.org>,
        <xukuohai@...wei.com>, <zhengyejian1@...wei.com>
Subject: Re: [PATCH 4.19] rcu/tree: Mark functions as notrace

On Fri, 15 Jul 2022 16:39:12 +0200
Greg KH <gregkh@...uxfoundation.org> wrote:
> On Wed, Jul 13, 2022 at 06:20:09PM +0800, Zheng Yejian wrote:
> > This patch and problem analysis is based on v4.19 LTS, but v5.4 LTS
> > and below seem to be involved.
> >
> > Hulk Robot reports a softlockup problem, see following logs:
> >   [   41.463870] watchdog: BUG: soft lockup - CPU#0 stuck for 22s!  [ksoftirqd/0:9]
> >   [   41.509763] Modules linked in:
> >   [   41.512295] CPU: 0 PID: 9 Comm: ksoftirqd/0 Not tainted 4.19.90 #13
> >   [   41.516134] Hardware name: linux,dummy-virt (DT)
> >   [   41.519182] pstate: 80c00005 (Nzcv daif +PAN +UAO)
> >   [   41.522415] pc : perf_trace_buf_alloc+0x138/0x238
> >   [   41.525583] lr : perf_trace_buf_alloc+0x138/0x238
> >   [   41.528656] sp : ffff8000c137e880
> >   [   41.531050] x29: ffff8000c137e880 x28: ffff20000850ced0
> >   [   41.534759] x27: 0000000000000000 x26: ffff8000c137e9c0
> >   [   41.538456] x25: ffff8000ce5c2ae0 x24: ffff200008358b08
> >   [   41.542151] x23: 0000000000000000 x22: ffff2000084a50ac
> >   [   41.545834] x21: ffff8000c137e880 x20: 000000000000001c
> >   [   41.549516] x19: ffff7dffbfdf88e8 x18: 0000000000000000
> >   [   41.553202] x17: 0000000000000000 x16: 0000000000000000
> >   [   41.556892] x15: 1ffff00036e07805 x14: 0000000000000000
> >   [   41.560592] x13: 0000000000000004 x12: 0000000000000000
> >   [   41.564315] x11: 1fffefbff7fbf120 x10: ffff0fbff7fbf120
> >   [   41.568003] x9 : dfff200000000000 x8 : ffff7dffbfdf8904
> >   [   41.571699] x7 : 0000000000000000 x6 : ffff0fbff7fbf121
> >   [   41.575398] x5 : ffff0fbff7fbf121 x4 : ffff0fbff7fbf121
> >   [   41.579086] x3 : ffff20000850cdc8 x2 : 0000000000000008
> >   [   41.582773] x1 : ffff8000c1376000 x0 : 0000000000000100
> >   [   41.586495] Call trace:
> >   [   41.588922]  perf_trace_buf_alloc+0x138/0x238
> >   [   41.591912]  perf_ftrace_function_call+0x1ac/0x248
> >   [   41.595123]  ftrace_ops_no_ops+0x3a4/0x488
> >   [   41.597998]  ftrace_graph_call+0x0/0xc
> >   [   41.600715]  rcu_dynticks_curr_cpu_in_eqs+0x14/0x70
> >   [   41.603962]  rcu_is_watching+0xc/0x20
> >   [   41.606635]  ftrace_ops_no_ops+0x240/0x488
> >   [   41.609530]  ftrace_graph_call+0x0/0xc
> >   [   41.612249]  __read_once_size_nocheck.constprop.0+0x1c/0x38
> >   [   41.615905]  unwind_frame+0x140/0x358
> >   [   41.618597]  walk_stackframe+0x34/0x60
> >   [   41.621359]  __save_stack_trace+0x204/0x3b8
> >   [   41.624328]  save_stack_trace+0x2c/0x38
> >   [   41.627112]  __kasan_slab_free+0x120/0x228
> >   [   41.630018]  kasan_slab_free+0x10/0x18
> >   [   41.632752]  kfree+0x84/0x250
> >   [   41.635107]  skb_free_head+0x70/0xb0
> >   [   41.637772]  skb_release_data+0x3f8/0x730
> >   [   41.640626]  skb_release_all+0x50/0x68
> >   [   41.643350]  kfree_skb+0x84/0x278
> >   [   41.645890]  kfree_skb_list+0x4c/0x78
> >   [   41.648595]  __dev_queue_xmit+0x1a4c/0x23a0
> >   [   41.651541]  dev_queue_xmit+0x28/0x38
> >   [   41.654254]  ip6_finish_output2+0xeb0/0x1630
> >   [   41.657261]  ip6_finish_output+0x2d8/0x7f8
> >   [   41.660174]  ip6_output+0x19c/0x348
> >   [   41.663850]  mld_sendpack+0x560/0x9e0
> >   [   41.666564]  mld_ifc_timer_expire+0x484/0x8a8
> >   [   41.669624]  call_timer_fn+0x68/0x4b0
> >   [   41.672355]  expire_timers+0x168/0x498
> >   [   41.675126]  run_timer_softirq+0x230/0x7a8
> >   [   41.678052]  __do_softirq+0x2d0/0xba0
> >   [   41.680763]  run_ksoftirqd+0x110/0x1a0
> >   [   41.683512]  smpboot_thread_fn+0x31c/0x620
> >   [   41.686429]  kthread+0x2c8/0x348
> >   [   41.688927]  ret_from_fork+0x10/0x18
> >
> > Look into above call stack, there is a recursive call in
> > 'ftrace_graph_call', and the direct cause of above recursion is that
> > 'rcu_dynticks_curr_cpu_in_eqs' is traced, see following snippet:
> >     __read_once_size_nocheck.constprop.0
> >       ftrace_graph_call    <-- 1. first call
> >         ......
> >           rcu_dynticks_curr_cpu_in_eqs
> >             ftrace_graph_call    <-- 2. recursive call here!!!
> >
> > Comparing with mainline kernel, commit ff5c4f5cad33 ("rcu/tree:
> > Mark the idle relevant functions noinstr") mark related functions as
> > 'noinstr' which implies notrace, noinline and sticks things in the
> > .noinstr.text section.
> > Link: https://lore.kernel.org/all/20200416114706.625340212@infradead.org/
> >
> > But we cannot directly backport that commit, because there seems to be
> > many prepatches. Instead, marking the functions as 'notrace' where it is
> > 'noinstr' in that commit and mark 'rcu_dynticks_curr_cpu_in_eqs' as
> > inline look like it resolves the problem.
> >
> > Reported-by: Hulk Robot <hulkci@...wei.com>
> > Signed-off-by: Zheng Yejian <zhengyejian1@...wei.com>
> > ---
> >  kernel/rcu/tree.c        | 22 +++++++++++-----------
> >  kernel/rcu/tree_plugin.h |  4 ++--
> >  2 files changed, 13 insertions(+), 13 deletions(-)
>
> Given that no one has noticed this on 4.19 yet, this change is very odd.
>
> What changed to cause this to suddenly happen?  How did you test this
> change, and as you did change the function to be __alaways_inline, what
> did that cause to have happen?

Hi greg, Steve had similar questions, so answer them together in:
https://lore.kernel.org/lkml/20220716152313.46350-1-zhengyejian1@huawei.com/

There are something need to be discussed.

>
> I would need an ack from the maintainer of this code before I can take
> an out-of-tree patch.
>
> thanks,
>
> greg k-h

Powered by blists - more mailing lists