livelock with KASAN_SW_TAGS

livelock with KASAN_SW_TAGS

[Qian Cai]

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.

[1]
https://github.com/linux-test-project/ltp/blob/master/testcases/kernel/syscalls/ipc/msgstress/msgstress03.c

# ./scripts/faddr2line vmlinux _raw_spin_unlock_irqrestore+0x44/0xac
_raw_spin_unlock_irqrestore+0x44/0xac:
arch_local_irq_restore at arch/arm64/include/asm/irqflags.h:88
(inlined by) __raw_spin_unlock_irqrestore at include/linux/spinlock_api_smp.h:160
(inlined by) _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:184

This code:

	asm volatile(
		"msr	daif, %0
	:
	: "r" (flags)
	: "memory");

[  545.622261] watchdog: BUG: soft lockup - CPU#12 stuck for 23s!
[kworker/12:1:1439]
[  545.629847] Modules linked in: thunderx2_pmu ip_tables xfs libcrc32c sd_mod
ahci libahci mlx5_core libata dm_mirror dm_region_hash dm_log dm_mod efivarfs
[  545.643692] CPU: 12 PID: 1439 Comm: kworker/12:1 Tainted: G        W
5.0.0-rc6+ #44
[  545.652082] Hardware name: HPE Apollo 70             /C01_APACHE_MB         ,
BIOS L50_5.13_1.0.6 07/10/2018
[  545.661947] Workqueue: events free_obj_work
[  545.666173] pstate: 60400009 (nZCv daif +PAN -UAO)
[  545.670981] pc : _raw_spin_unlock_irqrestore+0x44/0xac
[  545.676166] lr : _raw_spin_unlock_irqrestore+0x38/0xac
[  545.681389] sp : 30ff80098de3fa70
[  545.684724] x29: 30ff80098de3fa90 x28: 00000000000044c0
[  545.690048] x27: 0000000000000001 x26: 8aff808ba9f844d0
[  545.695380] x25: 0000000000000001 x24: 0000000000000001
[  545.700705] x23: 0000000000000000 x22: 62ff808b7d00df00
[  545.706038] x21: 62ff808b7d00df00 x20: 0000000000000000
[  545.711366] x19: ffff1000105d6ac0 x18: ffff1000148a5538
[  545.716720] x17: 000000000000001b x16: 00000000000000ff
[  545.722040] x15: ffff1000148a5000 x14: 000000000000004c
[  545.727358] x13: 0000000000000001 x12: efff100000000000
[  545.732678] x11: 0000000000000002 x10: 00000000000000ff
[  545.738034] x9 : 00000000ffffffff x8 : 4cff800832347840
[  545.743354] x7 : bbbbbbbbbbbbbbbb x6 : 0000000000000008
[  545.748711] x5 : 000000000000005a x4 : 0000000000000000
[  545.754041] x3 : 30ff80098de3fa04 x2 : 0000000000000003
[  545.759422] x1 : 62ff808b7d00df18 x0 : 4cff800832347850
[  545.764761] Call trace:
[  545.767225]  _raw_spin_unlock_irqrestore+0x44/0xac
[  545.772027]  free_debug_processing+0x308/0x410
[  545.776489]  kmem_cache_free+0x604/0x9f0
[  545.780442]  free_obj_work+0x92c/0xa44
[  545.784241]  process_one_work+0x894/0x1280
[  545.788349]  worker_thread+0x684/0xa1c
[  545.792122]  kthread+0x2cc/0x2e8
[  545.795367]  ret_from_fork+0x10/0x18

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

Re: livelock with KASAN_SW_TAGS

[Will Deacon]

Hi Qian Cai,

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
  - Clang version
  - LTP version and command-line
  - Machine configuration (CPUs, memory, etc)

> # ./scripts/faddr2line vmlinux _raw_spin_unlock_irqrestore+0x44/0xac
> _raw_spin_unlock_irqrestore+0x44/0xac:
> arch_local_irq_restore at arch/arm64/include/asm/irqflags.h:88
> (inlined by) __raw_spin_unlock_irqrestore at include/linux/spinlock_api_smp.h:160
> (inlined by) _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:184
> 
> This code:
> 
> 	asm volatile(
> 		"msr	daif, %0
> 	:
> 	: "r" (flags)
> 	: "memory");

This is just the instruction when we unmask interrupts, so that's when the
soft watchdog fires. I suspect the real issue is that we're spending lots
of time in:

> [  545.772027]  free_debug_processing+0x308/0x410

with irqs disabled. Does the machine eventually come back to life?

Will

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

Re: livelock with KASAN_SW_TAGS

[Qian Cai]

On 2/14/19 11:35 AM, Will Deacon wrote:
> Hi Qian Cai,
> 
> 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

>   - Clang version

clang-7.0.1

>   - LTP version and command-line

latest git at db57ddc1497e

/opt/ltp/testcases/bin/msgstress03

>   - Machine configuration (CPUs, memory, etc)

https://git.sr.ht/~cai/linux-debug/tree/master/dmesg

# lscpu
Architecture:        aarch64
Byte Order:          Little Endian
CPU(s):              256
On-line CPU(s) list: 0-255
Thread(s) per core:  4
Core(s) per socket:  32
Socket(s):           2
NUMA node(s):        2
Vendor ID:           Cavium
Model:               1
Model name:          ThunderX2 99xx
Stepping:            0x1
BogoMIPS:            400.00
L1d cache:           32K
L1i cache:           32K
L2 cache:            256K
L3 cache:            32768K
NUMA node0 CPU(s):   0-127
NUMA node1 CPU(s):   128-255
Flags:               fp asimd evtstrm aes pmull sha1 sha2 crc32 atomics cpuid
asimdrdm

# free -m
              total        used        free      shared  buff/cache   available
Mem:          84871        8347       75942          55         581       69699
Swap:          4095           0        4095

> 
>> # ./scripts/faddr2line vmlinux _raw_spin_unlock_irqrestore+0x44/0xac
>> _raw_spin_unlock_irqrestore+0x44/0xac:
>> arch_local_irq_restore at arch/arm64/include/asm/irqflags.h:88
>> (inlined by) __raw_spin_unlock_irqrestore at include/linux/spinlock_api_smp.h:160
>> (inlined by) _raw_spin_unlock_irqrestore at kernel/locking/spinlock.c:184
>>
>> This code:
>>
>> 	asm volatile(
>> 		"msr	daif, %0
>> 	:
>> 	: "r" (flags)
>> 	: "memory");
> 
> This is just the instruction when we unmask interrupts, so that's when the
> soft watchdog fires. I suspect the real issue is that we're spending lots
> of time in:
> 
>> [  545.772027]  free_debug_processing+0x308/0x410
> 
> with irqs disabled. Does the machine eventually come back to life?
>

Never.

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

Re: livelock with KASAN_SW_TAGS

[Will Deacon]

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.

Thanks,

Will

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

Re: livelock with KASAN_SW_TAGS

[Qian Cai]

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

Occasionally, msgstress03 would trigger a panic.

[  997.982080] Internal error: synchronous external abort: 96000610 [#1] SMP
[  997.988886] Modules linked in: thunderx2_pmu efivarfs ip_tables xfs libcrc32c
sd_mod ahci libahci mlx5_core libata dm_mirror dm_region_hash dm_log dm_mod
[  998.002665] CPU: 229 PID: 1323 Comm: kworker/229:1 Kdump: loaded Tainted: G
     W         5.0.0-rc6+ #57
[  998.012402] Hardware name: HPE Apollo 70             /C01_APACHE_MB         ,
BIOS L50_5.13_1.0.6 07/10/2018
[  998.022243] Workqueue: events free_obj_work
[  998.026434] pstate: 00400009 (nzcv daif +PAN -UAO)
[  998.031229] pc : kmem_cache_free+0x410/0x870
[  998.035500] lr : free_obj_work+0x92c/0xa44
[  998.039592] sp : 29ff808baebefb50
[  998.042908] x29: 29ff808baebefca0 x28: 73ff808a939eb6e0
[  998.048223] x27: 33ff800820013488 x26: 73ff808a939eb710
[  998.053537] x25: 0000000000a3008e x24: ffff100014b73000
[  998.058850] x23: 00000000000000ff x22: dead000000000100
[  998.064164] x21: efff100000000000 x20: efff100000000000
[  998.069480] x19: ffff100014b73d70 x18: ffff1000148a5538
[  998.074795] x17: 000000000000001b x16: 0000000000a3008d
[  998.080108] x15: b1ff808a939ee2a0 x14: 0000000000000000
[  998.085421] x13: 9dff808ba9713850 x12: 0000000000000000
[  998.090737] x11: 007ffffffc000201 x10: ffff1000138d4000
[  998.096055] x9 : 0000000000000000 x8 : 9dff808ba9713840
[  998.101371] x7 : bbbbbbbbbbbbbbbb x6 : 0000000000000008
[  998.106686] x5 : 000000000000005a x4 : 0000000000000000
[  998.111999] x3 : 29ff808baebef9f4 x2 : 0000000000000003
[  998.117312] x1 : cbff80082000df18 x0 : ffff808a939eb710
[  998.122632] Process kworker/229:1 (pid: 1323, stack limit = 0x00000000d1a3376a)
[  998.129937] Call trace:
[  998.132388]  kmem_cache_free+0x410/0x870
[  998.136320]  process_one_work+0x894/0x1280
[  998.140418]  worker_thread+0x684/0xa1c
[  998.144174]  kthread+0x2cc/0x2e8
[  998.147409]  ret_from_fork+0x10/0x18
[  998.150989] Code: a94b7bfd a94a4ff4 a94957f6 a9485ff8 (a94767fa)

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

Re: livelock with KASAN_SW_TAGS

[Will Deacon]

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

Re: livelock with KASAN_SW_TAGS

[Will Deacon]

[this time, with the diff]

On Fri, Feb 15, 2019 at 02:23:56PM +0000, Will Deacon wrote:
> 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).

Will

--->8

diff --git a/mm/page_poison.c b/mm/page_poison.c
index f0c15e9017c0..24aa8789971d 100644
--- a/mm/page_poison.c
+++ b/mm/page_poison.c
@@ -3,6 +3,7 @@
 #include <linux/string.h>
 #include <linux/mm.h>
 #include <linux/highmem.h>
+#include <linux/kasan.h>
 #include <linux/page_ext.h>
 #include <linux/poison.h>
 #include <linux/ratelimit.h>
@@ -116,10 +117,12 @@ void kernel_poison_pages(struct page *page, int numpages, int enable)
 	if (!page_poisoning_enabled())
 		return;
 
+	kasan_disable_current();
 	if (enable)
 		unpoison_pages(page, numpages);
 	else
 		poison_pages(page, numpages);
+	kasan_enable_current();
 }
 
 #ifndef CONFIG_ARCH_SUPPORTS_DEBUG_PAGEALLOC

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

Re: livelock with KASAN_SW_TAGS

[Andrey Konovalov]

On Fri, Feb 15, 2019 at 3:23 PM Will Deacon <will.deacon@arm.com> wrote:
>
> 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.

So far, I've been unable to trigger this in QEMU as well.

Qian, could you check if this still happens after adding that -pg flag
in KASAN Makefile?

>
> 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).

There's a patch in the mm tree that addresses this already.


>
> 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

Re: soft lockups with SLAB_CONSISTENCY_CHECKS + KASAN_SW_TAGS (was: livelock with KASAN_SW_TAGS)

[Andrey Konovalov]

On Tue, Feb 19, 2019 at 7:42 PM Qian Cai <cai@lca.pw> wrote:
>
> On Tue, 2019-02-19 at 18:56 +0100, Andrey Konovalov wrote:
> > > > 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.
> >
> > So far, I've been unable to trigger this in QEMU as well.
> >
> > Qian, could you check if this still happens after adding that -pg flag
> > in KASAN Makefile?
>
> Yes, it still happen. Although the reproducer (LTP msgstress0[3-4]) is making
> slow progress, so not strict a live lock now. The situation gets worse if the
> system has more CPUs probably because more CPUs are trying to acquire the
> spinlock in free_debug_processing() and then flush the console with soft
> lockups.
>
> One workaround is to add "KASAN_SANITIZE_string.o := n" to lib/Makefile which
> will stop inserting KASAN instruments for check_bytes8(), and then the
> reproducers are running smoothly without triggering any soft lockups.
>
> It looks like check_bytes8() is a big CPU consumer especially with KASAN
> instruments added.
>
> 0000000000001a2c <check_bytes8>:
>     1a2c:       d2c20008        mov     x8, #0x100000000000
>     1a30:       f2fdffe8        movk    x8, #0xefff, lsl #48
>     1a34:       34000202        cbz     w2, 1a74 <check_bytes8+0x48>
>     1a38:       aa1e03e3        mov     x3, x30
>     1a3c:       94000047        bl      1b58 <OUTLINED_FUNCTION_2>
>     1a40:       aa0303fe        mov     x30, x3
>     1a44:       54000060        b.eq    1a50 <check_bytes8+0x24>  // b.none
>     1a48:       7103fd3f        cmp     w9, #0xff
>     1a4c:       54000101        b.ne    1a6c <check_bytes8+0x40>  // b.any
>     1a50:       39400009        ldrb    w9, [x0]
>     1a54:       6b21013f        cmp     w9, w1, uxtb
>     1a58:       54000101        b.ne    1a78 <check_bytes8+0x4c>  // b.any
>     1a5c:       91000400        add     x0, x0, #0x1
>     1a60:       51000442        sub     w2, w2, #0x1
>     1a64:       35fffea2        cbnz    w2, 1a38 <check_bytes8+0xc>
>     1a68:       14000003        b       1a74 <check_bytes8+0x48>
>     1a6c:       d4212400        brk     #0x920
>     1a70:       17fffff8        b       1a50 <check_bytes8+0x24>
>     1a74:       aa1f03e0        mov     x0, xzr
>     1a78:       d65f03c0        ret
>
> This function is called by over and over again (with interrupts disabled),
>
> free_debug_processing [1]
>   free_consistency_checks
>     check_object
>       memchr_inv [2]
>         check_bytes8
>
> [1] iterate all objects in the slab.
> [2] while (words) { words--;

Ah, so it doesn't lock, it's just very slow? memchr_inv() is the only
caller of check_bytes8(), so we could remove instrumentation from the
latter, and add one KASAN range check into the former. But I'd say
this is the expected behavior, KASAN slows down stuff and I don't
think it makes much sense to enable it together with other memory
debugging options.


>
> I also noticed that even the single "top" command is now consuming 30% - 40%
> CPUs all the time. Sometimes, it could jump to 80% or so.
>
> 5969 root      20   0   24512  10560   4736 R  83.8   0.0   3:25.79 top

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

Re: soft lockups with SLAB_CONSISTENCY_CHECKS + KASAN_SW_TAGS (was: livelock with KASAN_SW_TAGS)

[Qian Cai]

On Tue, 2019-02-19 at 19:56 +0100, Andrey Konovalov wrote:
> Ah, so it doesn't lock, it's just very slow? memchr_inv() is the only
> caller of check_bytes8(), so we could remove instrumentation from the
> latter, and add one KASAN range check into the former. But I'd say
> this is the expected behavior, KASAN slows down stuff and I don't
> think it makes much sense to enable it together with other memory
> debugging options.
> 

Yes, just very slow.

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