Re: livelock with KASAN_SW_TAGS

[Will Deacon <will.deacon@arm.com>]

On Thu, Feb 14, 2019 at 11:04:25PM -0500, Qian Cai wrote:
> On 2/14/19 1:01 PM, Will Deacon wrote:
> > On Thu, Feb 14, 2019 at 11:50:59AM -0500, Qian Cai wrote:
> >> On 2/14/19 11:35 AM, Will Deacon wrote:
> >>> On Wed, Feb 13, 2019 at 10:32:11PM -0500, Qian Cai wrote:
> >>>> Running LTP msgstress03 [1] triggers endless soft lockups below after a few
> >>>> minutes on a ThunderX2 server. It works fine with KASAN_GENERIC and finish the
> >>>> test in roughly 11 minutes.
> >>>
> >>> I've not been able to reproduce this failure under KVM, however the test
> >>> only takes around 18s to complete on the host and the guest, so it feels
> >>> like something is amiss here. Please could you share more information about
> >>> how you're triggering this problem? For example:
> >>>
> >>>   - Kernel version and .config
> >>
> >> Latest mainline at 1f947a7a01 ("Merge branch 'akpm' (patches from Andrew)") plus
> >> a few KASAN_SW_TAGS patches in order to boot.
> >>
> >> https://marc.info/?l=linux-mm&m=155006632110129&w=2 (all 5)
> >> https://marc.info/?l=linux-mm&m=154968731424637&w=2
> >> https://marc.info/?l=linux-mm&m=155010395725051&w=2
> >>
> >> https://git.sr.ht/~cai/linux-debug/tree/master/config
> > 
> > I struggled to get this config to boot under KVM :(
> > 
> >>>   - Clang version
> >>
> >> clang-7.0.1
> > 
> > It would be helpful to know if the issue persists with the latest nightly
> > build of clang.
> > 
> > Anyway, please could you annotate the goto loop in free_debug_processing()
> > so that the object and tail pointer are printed each time around? It would
> > be useful to know if we're failing to exit that.
> >
> 
> Well, I am not sure I understand what your debugging strategy. Maybe, you can
> send along a debug patch you have in mind for me to run.
> 
> From the trace, it definitely exit the "goto next_object" and reached further in
> this line in free_debug_processing(),
> 
> spin_unlock_irqrestore(&n->list_lock, flags);
> 
> Once the machine is restricted to 16 CPUs (nr_cpus=16), although it still
> trigger soft lockups and msgstress03 would seem running forever, the machine is
> still responsible and is able to login via ssh. Hence, it is possible to capture
> a task dump (echo t >/proc/sysrq-trigger) while this is happening.
> 
> https://git.sr.ht/~cai/linux-debug/tree/master/console
> 
> Some traces looks strange that looks like running free_debug_processing() in a loop,
> 
> [ 1986.002139] Call trace:
> [ 1986.002145]  _raw_spin_unlock_irqrestore+0x44/0xac
> [ 1986.002152]  free_debug_processing+0x2f4/0x3e4
> [ 1986.002157]  kmem_cache_free+0x44c/0x870
> [ 1986.002163]  free_object_rcu+0x200/0x228
> [ 1986.002169]  rcu_process_callbacks+0xb00/0x12c0
> [ 1986.002175]  __do_softirq+0x644/0xfd0
> [ 1986.002181]  irq_exit+0x29c/0x370
> [ 1986.002187]  __handle_domain_irq+0xe0/0x1c4
> [ 1986.002192]  gic_handle_irq+0x1c4/0x3b0
> [ 1986.002197]  el1_irq+0xb0/0x140
> [ 1986.002203]  lock_release+0x660/0x7dc
> [ 1986.002209]  rcu_lock_release+0x20/0x28
> [ 1986.002214]  do_msgrcv+0x708/0xed0
> [ 1986.002219]  ksys_msgrcv+0x4c/0x60
> [ 1986.002224]  __arm64_sys_msgrcv+0xb8/0x194
> [ 1986.002230]  el0_svc_handler+0x230/0x3bc
> [ 1986.002236]  el0_svc+0x8/0xc
> [ 1986.007106]  OUTLINED_FUNCTION_169+0x4/0xc
> [ 1986.011885]  free_debug_processing+0x2f4/0x3e4
> [ 1986.017186]  load_msg+0x4c/0x324
> [ 1986.021617]  kmem_cache_free+0x44c/0x870
> [ 1986.026917]  ksys_msgsnd+0x1e0/0xe5c
> [ 1988.050035]  _raw_spin_unlock_irqrestore+0x44/0xac
> [ 1988.054821]  free_debug_processing+0x2f4/0x3e4
> [ 1988.059260]  kfree+0x3f8/0x7ac
> [ 1988.062313]  free_msg+0x50/0xb0
> [ 1988.065450]  do_msgrcv+0xd80/0xed0
> [ 1988.068846]  ksys_msgrcv+0x4c/0x60
> [ 1988.072243]  __arm64_sys_msgrcv+0xb8/0x194
> [ 1988.076336]  el0_svc_handler+0x230/0x3bc
> [ 1988.080255]  el0_svc+0x

I'm hoping that Andrey can make sense of this, since he recently hacked up
freelist_ptr(), although only if CONFIG_SLAB_FREELIST_HARDENED=y, which
isn't the case in your .config.

One thing I did spot is that KASAN doesn't play nicely with page poisoning,
because the pointer returned by kmap_atomic() which is used to poison and
unpoison a page on free and alloc respectively is tagged. The simplest way
to fix this was to disable KASAN around these operations (diff below).

I think the unfortunate reality is that KASAN_SW_TAGS will always be flaky
because most kernel code isn't (and wasn't) written with it in mind.  The
reason that's acceptable is because it's a debug option, but it also means I
can't justify spending very much time on these sort of reports, sorry.

Will

_______________________________________________
linux-arm-kernel mailing list
linux-arm-kernel@lists.infradead.org
http://lists.infradead.org/mailman/listinfo/linux-arm-kernel