From: Michael Ellerman <mpe@ellerman.id.au> Date: 2020-04-07 12:41:59
Qian Cai [off-list ref] writes:
Ever since 1st Apr, linux-next starts to trigger a NULL pointer NIP on POWER9 below using
this config,
https://raw.githubusercontent.com/cailca/linux-mm/master/powerpc.config
It takes a while to reproduce, so before I bury myself into bisecting and just send a head-up
to see if anyone spots anything obvious.
[ 206.744625][T13224] LTP: starting fallocate04
[ 207.601583][T27684] /dev/zero: Can't open blockdev
[ 208.674301][T27684] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
[ 208.680347][T27684] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[ 208.680383][T27684] Faulting instruction address: 0x00000000
[ 208.680406][T27684] Oops: Kernel access of bad area, sig: 11 [#1]
[ 208.680439][T27684] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 208.680474][T27684] Modules linked in: ext4 crc16 mbcache jbd2 loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci libahci mdio tg3 libata libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 208.680576][T27684] CPU: 117 PID: 27684 Comm: fallocate04 Tainted: G W 5.6.0-next-20200401+ #288
[ 208.680614][T27684] NIP: 0000000000000000 LR: c0080000102c0048 CTR: 0000000000000000
[ 208.680657][T27684] REGS: c000200361def420 TRAP: 0400 Tainted: G W (5.6.0-next-20200401+)
[ 208.680700][T27684] MSR: 900000004280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 42022228 XER: 20040000
[ 208.680760][T27684] CFAR: c00800001032c494 IRQMASK: 0
[ 208.680760][T27684] GPR00: c0000000005ac3f8 c000200361def6b0 c00000000165c200 c00020107dae0bd0
[ 208.680760][T27684] GPR04: 0000000000000000 0000000000000400 0000000000000000 0000000000000000
[ 208.680760][T27684] GPR08: c000200361def6e8 c0080000102c0040 000000007fffffff c000000001614e80
[ 208.680760][T27684] GPR12: 0000000000000000 c000201fff671280 0000000000000000 0000000000000002
[ 208.680760][T27684] GPR16: 0000000000000002 0000000000040001 c00020030f5a1000 c00020030f5a1548
[ 208.680760][T27684] GPR20: c0000000015fbad8 c00000000168c654 c000200361def818 c0000000005b4c10
[ 208.680760][T27684] GPR24: 0000000000000000 c0080000103365b8 c00020107dae0bd0 0000000000000400
[ 208.680760][T27684] GPR28: c00000000168c3a8 0000000000000000 0000000000000000 0000000000000000
[ 208.681014][T27684] NIP [0000000000000000] 0x0
[ 208.681065][T27684] LR [c0080000102c0048] ext4_iomap_end+0x8/0x30 [ext4]
That LR looks like it's pointing to the return from _mcount in
ext4_iomap_end(), which means we have probably crashed in ftrace
somewhere.
Did you have tracing enabled when you ran the test? Or does it do
tracing itself?
cheers
On Apr 7, 2020, at 8:42 AM, Michael Ellerman [off-list ref] wrote:
Qian Cai [off-list ref] writes:
quoted
Ever since 1st Apr, linux-next starts to trigger a NULL pointer NIP on POWER9 below using
this config,
https://raw.githubusercontent.com/cailca/linux-mm/master/powerpc.config
It takes a while to reproduce, so before I bury myself into bisecting and just send a head-up
to see if anyone spots anything obvious.
[ 206.744625][T13224] LTP: starting fallocate04
[ 207.601583][T27684] /dev/zero: Can't open blockdev
[ 208.674301][T27684] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
[ 208.680347][T27684] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[ 208.680383][T27684] Faulting instruction address: 0x00000000
[ 208.680406][T27684] Oops: Kernel access of bad area, sig: 11 [#1]
[ 208.680439][T27684] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 208.680474][T27684] Modules linked in: ext4 crc16 mbcache jbd2 loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci libahci mdio tg3 libata libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 208.680576][T27684] CPU: 117 PID: 27684 Comm: fallocate04 Tainted: G W 5.6.0-next-20200401+ #288
[ 208.680614][T27684] NIP: 0000000000000000 LR: c0080000102c0048 CTR: 0000000000000000
[ 208.680657][T27684] REGS: c000200361def420 TRAP: 0400 Tainted: G W (5.6.0-next-20200401+)
[ 208.680700][T27684] MSR: 900000004280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 42022228 XER: 20040000
[ 208.680760][T27684] CFAR: c00800001032c494 IRQMASK: 0
[ 208.680760][T27684] GPR00: c0000000005ac3f8 c000200361def6b0 c00000000165c200 c00020107dae0bd0
[ 208.680760][T27684] GPR04: 0000000000000000 0000000000000400 0000000000000000 0000000000000000
[ 208.680760][T27684] GPR08: c000200361def6e8 c0080000102c0040 000000007fffffff c000000001614e80
[ 208.680760][T27684] GPR12: 0000000000000000 c000201fff671280 0000000000000000 0000000000000002
[ 208.680760][T27684] GPR16: 0000000000000002 0000000000040001 c00020030f5a1000 c00020030f5a1548
[ 208.680760][T27684] GPR20: c0000000015fbad8 c00000000168c654 c000200361def818 c0000000005b4c10
[ 208.680760][T27684] GPR24: 0000000000000000 c0080000103365b8 c00020107dae0bd0 0000000000000400
[ 208.680760][T27684] GPR28: c00000000168c3a8 0000000000000000 0000000000000000 0000000000000000
[ 208.681014][T27684] NIP [0000000000000000] 0x0
[ 208.681065][T27684] LR [c0080000102c0048] ext4_iomap_end+0x8/0x30 [ext4]
That LR looks like it's pointing to the return from _mcount in
ext4_iomap_end(), which means we have probably crashed in ftrace
somewhere.
Did you have tracing enabled when you ran the test? Or does it do
tracing itself?
Yes, it run ftrace at first before running LTP to trigger it,
https://github.com/cailca/linux-mm/blob/master/test.sh
echo function > /sys/kernel/debug/tracing/current_tracer
echo nop > /sys/kernel/debug/tracing/current_tracer
There is another crash with even non-NULL NIP, but then symbol behaves weird.
# ./scripts/faddr2line vmlinux sysctl_net_busy_read+0x0/0x4
skipping sysctl_net_busy_read address at 0xc0000000016804ac due to non-function symbol of type 'D'
[ 148.110969][T13115] LTP: starting chown04_16
[ 148.255048][T13380] kernel tried to execute exec-protected page (c0000000016804ac) - exploit attempt? (uid: 0)
[ 148.255099][T13380] BUG: Unable to handle kernel instruction fetch
[ 148.255122][T13380] Faulting instruction address: 0xc0000000016804ac
[ 148.255136][T13380] Oops: Kernel access of bad area, sig: 11 [#1]
[ 148.255157][T13380] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 148.255171][T13380] Modules linked in: loop kvm_hv kvm xfs sd_mod bnx2x mdio ahci tg3 libahci libphy libata firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 148.255213][T13380] CPU: 45 PID: 13380 Comm: chown04_16 Tainted: G W 5.6.0+ #7
[ 148.255236][T13380] NIP: c0000000016804ac LR: c00800000fa60408 CTR: c0000000016804ac
[ 148.255250][T13380] REGS: c0000010a6fafa00 TRAP: 0400 Tainted: G W (5.6.0+)
[ 148.255281][T13380] MSR: 9000000010009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 84000248 XER: 20040000
[ 148.255310][T13380] CFAR: c00800000fa66534 IRQMASK: 0
[ 148.255310][T13380] GPR00: c000000000973268 c0000010a6fafc90 c000000001648200 0000000000000000
[ 148.255310][T13380] GPR04: c000000d8a22dc00 c0000010a6fafd30 00000000b5e98331 ffffffff00012c9f
[ 148.255310][T13380] GPR08: c000000d8a22dc00 0000000000000000 0000000000000000 c00000000163c520
[ 148.255310][T13380] GPR12: c0000000016804ac c000001ffffdad80 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR24: 00007fff8f5e2e48 0000000000000000 c00800000fa6a488 c0000010a6fafd30
[ 148.255310][T13380] GPR28: 0000000000000000 000000007fffffff c00800000fa60400 c000000efd0c6780
[ 148.255494][T13380] NIP [c0000000016804ac] sysctl_net_busy_read+0x0/0x4
[ 148.255516][T13380] LR [c00800000fa60408] find_free_cb+0x8/0x30 [loop]
[ 148.255528][T13380] Call Trace:
[ 148.255538][T13380] [c0000010a6fafc90] [c0000000009732c0] idr_for_each+0xf0/0x170 (unreliable)
[ 148.255572][T13380] [c0000010a6fafd10] [c00800000fa626c4] loop_lookup.part.1+0x4c/0xb0 [loop]
[ 148.255597][T13380] [c0000010a6fafd50] [c00800000fa634d8] loop_control_ioctl+0x120/0x1d0 [loop]
[ 148.255623][T13380] [c0000010a6fafdb0] [c0000000004ddc08] ksys_ioctl+0xd8/0x130
[ 148.255636][T13380] [c0000010a6fafe00] [c0000000004ddc88] sys_ioctl+0x28/0x40
[ 148.255669][T13380] [c0000010a6fafe20] [c00000000000b378] system_call+0x5c/0x68
[ 148.255699][T13380] Instruction dump:
[ 148.255718][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255744][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255772][T13380] ---[ end trace a5894a74208c22ec ]---
[ 148.576663][T13380]
[ 149.576765][T13380] Kernel panic - not syncing: Fatal exception
The bisect so far indicated the bad ones always have this,
aa1a8ce53332 Merge tag 'trace-v5.7' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
8a815e6b8b88 tracing: Have the document reflect that the trace file keeps tracing enabled
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
153368ce1bd0 ring-buffer: Optimize rb_iter_head_event()
ff84c50cfb4b ring-buffer: Do not die if rb_iter_peek() fails more than thrice
785888c544e0 ring-buffer: Have rb_iter_head_event() handle concurrent writer
28e3fc56a471 ring-buffer: Add page_stamp to iterator for synchronization
bc1a72afdc4a ring-buffer: Rename ring_buffer_read() to read_buffer_iter_advance()
ead6ecfddea5 ring-buffer: Have ring_buffer_empty() not depend on tracing stopped
ff895103a84a tracing: Save off entry when peeking at next entry
8c77f0ba4156 selftest/ftrace: Fix function trigger test to handle trace not disabling the tracer
bf2cbe044da2 tracing: Use address-of operator on section symbols
bbd9d05618a6 gpu/trace: add a gpu total memory usage tracepoint
89b74cac7834 tools/bootconfig: Show line and column in parse error
306b69dce926 bootconfig: Support O=<builddir> option
5412e0b763e0 tracing: Remove unused TRACE_BUFFER bits
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
From: Steven Rostedt <rostedt@goodmis.org> Date: 2020-04-07 13:30:59
On Tue, 7 Apr 2020 09:01:10 -0400
Qian Cai [off-list ref] wrote:
+ Steven
quoted
On Apr 7, 2020, at 8:42 AM, Michael Ellerman [off-list ref] wrote:
Qian Cai [off-list ref] writes:
quoted
Ever since 1st Apr, linux-next starts to trigger a NULL pointer NIP on POWER9 below using
this config,
https://raw.githubusercontent.com/cailca/linux-mm/master/powerpc.config
It takes a while to reproduce, so before I bury myself into bisecting and just send a head-up
to see if anyone spots anything obvious.
[ 206.744625][T13224] LTP: starting fallocate04
[ 207.601583][T27684] /dev/zero: Can't open blockdev
[ 208.674301][T27684] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
[ 208.680347][T27684] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[ 208.680383][T27684] Faulting instruction address: 0x00000000
[ 208.680406][T27684] Oops: Kernel access of bad area, sig: 11 [#1]
[ 208.680439][T27684] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 208.680474][T27684] Modules linked in: ext4 crc16 mbcache jbd2 loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci libahci mdio tg3 libata libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 208.680576][T27684] CPU: 117 PID: 27684 Comm: fallocate04 Tainted: G W 5.6.0-next-20200401+ #288
[ 208.680614][T27684] NIP: 0000000000000000 LR: c0080000102c0048 CTR: 0000000000000000
[ 208.680657][T27684] REGS: c000200361def420 TRAP: 0400 Tainted: G W (5.6.0-next-20200401+)
[ 208.680700][T27684] MSR: 900000004280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 42022228 XER: 20040000
[ 208.680760][T27684] CFAR: c00800001032c494 IRQMASK: 0
[ 208.680760][T27684] GPR00: c0000000005ac3f8 c000200361def6b0 c00000000165c200 c00020107dae0bd0
[ 208.680760][T27684] GPR04: 0000000000000000 0000000000000400 0000000000000000 0000000000000000
[ 208.680760][T27684] GPR08: c000200361def6e8 c0080000102c0040 000000007fffffff c000000001614e80
[ 208.680760][T27684] GPR12: 0000000000000000 c000201fff671280 0000000000000000 0000000000000002
[ 208.680760][T27684] GPR16: 0000000000000002 0000000000040001 c00020030f5a1000 c00020030f5a1548
[ 208.680760][T27684] GPR20: c0000000015fbad8 c00000000168c654 c000200361def818 c0000000005b4c10
[ 208.680760][T27684] GPR24: 0000000000000000 c0080000103365b8 c00020107dae0bd0 0000000000000400
[ 208.680760][T27684] GPR28: c00000000168c3a8 0000000000000000 0000000000000000 0000000000000000
[ 208.681014][T27684] NIP [0000000000000000] 0x0
[ 208.681065][T27684] LR [c0080000102c0048] ext4_iomap_end+0x8/0x30 [ext4]
That LR looks like it's pointing to the return from _mcount in
ext4_iomap_end(), which means we have probably crashed in ftrace
somewhere.
Did you have tracing enabled when you ran the test? Or does it do
tracing itself?
Yes, it run ftrace at first before running LTP to trigger it,
https://github.com/cailca/linux-mm/blob/master/test.sh
echo function > /sys/kernel/debug/tracing/current_tracer
echo nop > /sys/kernel/debug/tracing/current_tracer
There is another crash with even non-NULL NIP, but then symbol behaves weird.
# ./scripts/faddr2line vmlinux sysctl_net_busy_read+0x0/0x4
skipping sysctl_net_busy_read address at 0xc0000000016804ac due to non-function symbol of type 'D'
[ 148.110969][T13115] LTP: starting chown04_16
[ 148.255048][T13380] kernel tried to execute exec-protected page (c0000000016804ac) - exploit attempt? (uid: 0)
[ 148.255099][T13380] BUG: Unable to handle kernel instruction fetch
[ 148.255122][T13380] Faulting instruction address: 0xc0000000016804ac
[ 148.255136][T13380] Oops: Kernel access of bad area, sig: 11 [#1]
[ 148.255157][T13380] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 148.255171][T13380] Modules linked in: loop kvm_hv kvm xfs sd_mod bnx2x mdio ahci tg3 libahci libphy libata firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 148.255213][T13380] CPU: 45 PID: 13380 Comm: chown04_16 Tainted: G W 5.6.0+ #7
[ 148.255236][T13380] NIP: c0000000016804ac LR: c00800000fa60408 CTR: c0000000016804ac
[ 148.255250][T13380] REGS: c0000010a6fafa00 TRAP: 0400 Tainted: G W (5.6.0+)
[ 148.255281][T13380] MSR: 9000000010009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 84000248 XER: 20040000
[ 148.255310][T13380] CFAR: c00800000fa66534 IRQMASK: 0
[ 148.255310][T13380] GPR00: c000000000973268 c0000010a6fafc90 c000000001648200 0000000000000000
[ 148.255310][T13380] GPR04: c000000d8a22dc00 c0000010a6fafd30 00000000b5e98331 ffffffff00012c9f
[ 148.255310][T13380] GPR08: c000000d8a22dc00 0000000000000000 0000000000000000 c00000000163c520
[ 148.255310][T13380] GPR12: c0000000016804ac c000001ffffdad80 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR24: 00007fff8f5e2e48 0000000000000000 c00800000fa6a488 c0000010a6fafd30
[ 148.255310][T13380] GPR28: 0000000000000000 000000007fffffff c00800000fa60400 c000000efd0c6780
[ 148.255494][T13380] NIP [c0000000016804ac] sysctl_net_busy_read+0x0/0x4
[ 148.255516][T13380] LR [c00800000fa60408] find_free_cb+0x8/0x30 [loop]
[ 148.255528][T13380] Call Trace:
[ 148.255538][T13380] [c0000010a6fafc90] [c0000000009732c0] idr_for_each+0xf0/0x170 (unreliable)
[ 148.255572][T13380] [c0000010a6fafd10] [c00800000fa626c4] loop_lookup.part.1+0x4c/0xb0 [loop]
[ 148.255597][T13380] [c0000010a6fafd50] [c00800000fa634d8] loop_control_ioctl+0x120/0x1d0 [loop]
[ 148.255623][T13380] [c0000010a6fafdb0] [c0000000004ddc08] ksys_ioctl+0xd8/0x130
[ 148.255636][T13380] [c0000010a6fafe00] [c0000000004ddc88] sys_ioctl+0x28/0x40
[ 148.255669][T13380] [c0000010a6fafe20] [c00000000000b378] system_call+0x5c/0x68
[ 148.255699][T13380] Instruction dump:
[ 148.255718][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255744][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255772][T13380] ---[ end trace a5894a74208c22ec ]---
[ 148.576663][T13380]
[ 149.576765][T13380] Kernel panic - not syncing: Fatal exception
The bisect so far indicated the bad ones always have this,
aa1a8ce53332 Merge tag 'trace-v5.7' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
-- Steve
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
8a815e6b8b88 tracing: Have the document reflect that the trace file keeps tracing enabled
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
153368ce1bd0 ring-buffer: Optimize rb_iter_head_event()
ff84c50cfb4b ring-buffer: Do not die if rb_iter_peek() fails more than thrice
785888c544e0 ring-buffer: Have rb_iter_head_event() handle concurrent writer
28e3fc56a471 ring-buffer: Add page_stamp to iterator for synchronization
bc1a72afdc4a ring-buffer: Rename ring_buffer_read() to read_buffer_iter_advance()
ead6ecfddea5 ring-buffer: Have ring_buffer_empty() not depend on tracing stopped
ff895103a84a tracing: Save off entry when peeking at next entry
8c77f0ba4156 selftest/ftrace: Fix function trigger test to handle trace not disabling the tracer
bf2cbe044da2 tracing: Use address-of operator on section symbols
bbd9d05618a6 gpu/trace: add a gpu total memory usage tracepoint
89b74cac7834 tools/bootconfig: Show line and column in parse error
306b69dce926 bootconfig: Support O=<builddir> option
5412e0b763e0 tracing: Remove unused TRACE_BUFFER bits
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
On Apr 7, 2020, at 9:30 AM, Steven Rostedt [off-list ref] wrote:
On Tue, 7 Apr 2020 09:01:10 -0400
Qian Cai [off-list ref] wrote:
quoted
+ Steven
quoted
On Apr 7, 2020, at 8:42 AM, Michael Ellerman [off-list ref] wrote:
Qian Cai [off-list ref] writes:
quoted
Ever since 1st Apr, linux-next starts to trigger a NULL pointer NIP on POWER9 below using
this config,
https://raw.githubusercontent.com/cailca/linux-mm/master/powerpc.config
It takes a while to reproduce, so before I bury myself into bisecting and just send a head-up
to see if anyone spots anything obvious.
[ 206.744625][T13224] LTP: starting fallocate04
[ 207.601583][T27684] /dev/zero: Can't open blockdev
[ 208.674301][T27684] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
[ 208.680347][T27684] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[ 208.680383][T27684] Faulting instruction address: 0x00000000
[ 208.680406][T27684] Oops: Kernel access of bad area, sig: 11 [#1]
[ 208.680439][T27684] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 208.680474][T27684] Modules linked in: ext4 crc16 mbcache jbd2 loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci libahci mdio tg3 libata libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 208.680576][T27684] CPU: 117 PID: 27684 Comm: fallocate04 Tainted: G W 5.6.0-next-20200401+ #288
[ 208.680614][T27684] NIP: 0000000000000000 LR: c0080000102c0048 CTR: 0000000000000000
[ 208.680657][T27684] REGS: c000200361def420 TRAP: 0400 Tainted: G W (5.6.0-next-20200401+)
[ 208.680700][T27684] MSR: 900000004280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 42022228 XER: 20040000
[ 208.680760][T27684] CFAR: c00800001032c494 IRQMASK: 0
[ 208.680760][T27684] GPR00: c0000000005ac3f8 c000200361def6b0 c00000000165c200 c00020107dae0bd0
[ 208.680760][T27684] GPR04: 0000000000000000 0000000000000400 0000000000000000 0000000000000000
[ 208.680760][T27684] GPR08: c000200361def6e8 c0080000102c0040 000000007fffffff c000000001614e80
[ 208.680760][T27684] GPR12: 0000000000000000 c000201fff671280 0000000000000000 0000000000000002
[ 208.680760][T27684] GPR16: 0000000000000002 0000000000040001 c00020030f5a1000 c00020030f5a1548
[ 208.680760][T27684] GPR20: c0000000015fbad8 c00000000168c654 c000200361def818 c0000000005b4c10
[ 208.680760][T27684] GPR24: 0000000000000000 c0080000103365b8 c00020107dae0bd0 0000000000000400
[ 208.680760][T27684] GPR28: c00000000168c3a8 0000000000000000 0000000000000000 0000000000000000
[ 208.681014][T27684] NIP [0000000000000000] 0x0
[ 208.681065][T27684] LR [c0080000102c0048] ext4_iomap_end+0x8/0x30 [ext4]
That LR looks like it's pointing to the return from _mcount in
ext4_iomap_end(), which means we have probably crashed in ftrace
somewhere.
Did you have tracing enabled when you ran the test? Or does it do
tracing itself?
Yes, it run ftrace at first before running LTP to trigger it,
https://github.com/cailca/linux-mm/blob/master/test.sh
echo function > /sys/kernel/debug/tracing/current_tracer
echo nop > /sys/kernel/debug/tracing/current_tracer
There is another crash with even non-NULL NIP, but then symbol behaves weird.
# ./scripts/faddr2line vmlinux sysctl_net_busy_read+0x0/0x4
skipping sysctl_net_busy_read address at 0xc0000000016804ac due to non-function symbol of type 'D'
[ 148.110969][T13115] LTP: starting chown04_16
[ 148.255048][T13380] kernel tried to execute exec-protected page (c0000000016804ac) - exploit attempt? (uid: 0)
[ 148.255099][T13380] BUG: Unable to handle kernel instruction fetch
[ 148.255122][T13380] Faulting instruction address: 0xc0000000016804ac
[ 148.255136][T13380] Oops: Kernel access of bad area, sig: 11 [#1]
[ 148.255157][T13380] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 148.255171][T13380] Modules linked in: loop kvm_hv kvm xfs sd_mod bnx2x mdio ahci tg3 libahci libphy libata firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 148.255213][T13380] CPU: 45 PID: 13380 Comm: chown04_16 Tainted: G W 5.6.0+ #7
[ 148.255236][T13380] NIP: c0000000016804ac LR: c00800000fa60408 CTR: c0000000016804ac
[ 148.255250][T13380] REGS: c0000010a6fafa00 TRAP: 0400 Tainted: G W (5.6.0+)
[ 148.255281][T13380] MSR: 9000000010009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 84000248 XER: 20040000
[ 148.255310][T13380] CFAR: c00800000fa66534 IRQMASK: 0
[ 148.255310][T13380] GPR00: c000000000973268 c0000010a6fafc90 c000000001648200 0000000000000000
[ 148.255310][T13380] GPR04: c000000d8a22dc00 c0000010a6fafd30 00000000b5e98331 ffffffff00012c9f
[ 148.255310][T13380] GPR08: c000000d8a22dc00 0000000000000000 0000000000000000 c00000000163c520
[ 148.255310][T13380] GPR12: c0000000016804ac c000001ffffdad80 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR24: 00007fff8f5e2e48 0000000000000000 c00800000fa6a488 c0000010a6fafd30
[ 148.255310][T13380] GPR28: 0000000000000000 000000007fffffff c00800000fa60400 c000000efd0c6780
[ 148.255494][T13380] NIP [c0000000016804ac] sysctl_net_busy_read+0x0/0x4
[ 148.255516][T13380] LR [c00800000fa60408] find_free_cb+0x8/0x30 [loop]
[ 148.255528][T13380] Call Trace:
[ 148.255538][T13380] [c0000010a6fafc90] [c0000000009732c0] idr_for_each+0xf0/0x170 (unreliable)
[ 148.255572][T13380] [c0000010a6fafd10] [c00800000fa626c4] loop_lookup.part.1+0x4c/0xb0 [loop]
[ 148.255597][T13380] [c0000010a6fafd50] [c00800000fa634d8] loop_control_ioctl+0x120/0x1d0 [loop]
[ 148.255623][T13380] [c0000010a6fafdb0] [c0000000004ddc08] ksys_ioctl+0xd8/0x130
[ 148.255636][T13380] [c0000010a6fafe00] [c0000000004ddc88] sys_ioctl+0x28/0x40
[ 148.255669][T13380] [c0000010a6fafe20] [c00000000000b378] system_call+0x5c/0x68
[ 148.255699][T13380] Instruction dump:
[ 148.255718][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255744][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255772][T13380] ---[ end trace a5894a74208c22ec ]---
[ 148.576663][T13380]
[ 149.576765][T13380] Kernel panic - not syncing: Fatal exception
The bisect so far indicated the bad ones always have this,
aa1a8ce53332 Merge tag 'trace-v5.7' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
quoted
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
I tested reverting those 3 commits but it does NOT help.
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
So, it is either one of those is bad.
9c94b39560c3 Merge tag 'ext4_for_linus' of git://git.kernel.org/pub/scm/linux/kernel/git/tytso/ext4
aa1a8ce53332 Merge tag 'trace-v5.7' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
At this point, I suspect this one in ext4_for_linus,
ac58e4fb03f9 ext4: move ext4 bmap to use iomap infrastructure
given the first a few days, it was crashed due to this new ext4_bmap -> iomap_bmap
callsite from the above commit,
LR: ext4_iomap_end
The next few days, even though it starts to crash at,
LR: find_free_cb
by the LTP chown04_16 which is still somewhat ext4 related.
# /opt/ltp/testcases/bin/chown04_16
chown04_16 0 TINFO : Found free device 0 '/dev/loop0'
chown04_16 0 TINFO : Formatting /dev/loop0 with ext2 opts='' extra opts=''
mke2fs 1.45.4 (23-Sep-2019)
chown04_16 1 TBROK : safe_macros.c:764: chown04.c:175: mount(/dev/loop0, mntpoint, ext2, 1, (nil)) failed: errno=ENODEV(19): No such device
chown04_16 2 TBROK : safe_macros.c:764: Remaining cases broken
Is it possible that iomap somewhat corrupt the NIP?
In the next a few hours, I should be able to tell if the trace merge commit is clear.
-- Steve
quoted
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
8a815e6b8b88 tracing: Have the document reflect that the trace file keeps tracing enabled
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
153368ce1bd0 ring-buffer: Optimize rb_iter_head_event()
ff84c50cfb4b ring-buffer: Do not die if rb_iter_peek() fails more than thrice
785888c544e0 ring-buffer: Have rb_iter_head_event() handle concurrent writer
28e3fc56a471 ring-buffer: Add page_stamp to iterator for synchronization
bc1a72afdc4a ring-buffer: Rename ring_buffer_read() to read_buffer_iter_advance()
ead6ecfddea5 ring-buffer: Have ring_buffer_empty() not depend on tracing stopped
ff895103a84a tracing: Save off entry when peeking at next entry
8c77f0ba4156 selftest/ftrace: Fix function trigger test to handle trace not disabling the tracer
bf2cbe044da2 tracing: Use address-of operator on section symbols
bbd9d05618a6 gpu/trace: add a gpu total memory usage tracepoint
89b74cac7834 tools/bootconfig: Show line and column in parse error
306b69dce926 bootconfig: Support O=<builddir> option
5412e0b763e0 tracing: Remove unused TRACE_BUFFER bits
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
On Apr 7, 2020, at 9:30 AM, Steven Rostedt [off-list ref] wrote:
On Tue, 7 Apr 2020 09:01:10 -0400
Qian Cai [off-list ref] wrote:
quoted
+ Steven
quoted
On Apr 7, 2020, at 8:42 AM, Michael Ellerman [off-list ref] wrote:
Qian Cai [off-list ref] writes:
quoted
Ever since 1st Apr, linux-next starts to trigger a NULL pointer NIP on POWER9 below using
this config,
https://raw.githubusercontent.com/cailca/linux-mm/master/powerpc.config
It takes a while to reproduce, so before I bury myself into bisecting and just send a head-up
to see if anyone spots anything obvious.
[ 206.744625][T13224] LTP: starting fallocate04
[ 207.601583][T27684] /dev/zero: Can't open blockdev
[ 208.674301][T27684] EXT4-fs (loop0): mounting ext3 file system using the ext4 subsystem
[ 208.680347][T27684] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[ 208.680383][T27684] Faulting instruction address: 0x00000000
[ 208.680406][T27684] Oops: Kernel access of bad area, sig: 11 [#1]
[ 208.680439][T27684] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 208.680474][T27684] Modules linked in: ext4 crc16 mbcache jbd2 loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci libahci mdio tg3 libata libphy firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 208.680576][T27684] CPU: 117 PID: 27684 Comm: fallocate04 Tainted: G W 5.6.0-next-20200401+ #288
[ 208.680614][T27684] NIP: 0000000000000000 LR: c0080000102c0048 CTR: 0000000000000000
[ 208.680657][T27684] REGS: c000200361def420 TRAP: 0400 Tainted: G W (5.6.0-next-20200401+)
[ 208.680700][T27684] MSR: 900000004280b033 <SF,HV,VEC,VSX,EE,FP,ME,IR,DR,RI,LE> CR: 42022228 XER: 20040000
[ 208.680760][T27684] CFAR: c00800001032c494 IRQMASK: 0
[ 208.680760][T27684] GPR00: c0000000005ac3f8 c000200361def6b0 c00000000165c200 c00020107dae0bd0
[ 208.680760][T27684] GPR04: 0000000000000000 0000000000000400 0000000000000000 0000000000000000
[ 208.680760][T27684] GPR08: c000200361def6e8 c0080000102c0040 000000007fffffff c000000001614e80
[ 208.680760][T27684] GPR12: 0000000000000000 c000201fff671280 0000000000000000 0000000000000002
[ 208.680760][T27684] GPR16: 0000000000000002 0000000000040001 c00020030f5a1000 c00020030f5a1548
[ 208.680760][T27684] GPR20: c0000000015fbad8 c00000000168c654 c000200361def818 c0000000005b4c10
[ 208.680760][T27684] GPR24: 0000000000000000 c0080000103365b8 c00020107dae0bd0 0000000000000400
[ 208.680760][T27684] GPR28: c00000000168c3a8 0000000000000000 0000000000000000 0000000000000000
[ 208.681014][T27684] NIP [0000000000000000] 0x0
[ 208.681065][T27684] LR [c0080000102c0048] ext4_iomap_end+0x8/0x30 [ext4]
That LR looks like it's pointing to the return from _mcount in
ext4_iomap_end(), which means we have probably crashed in ftrace
somewhere.
Did you have tracing enabled when you ran the test? Or does it do
tracing itself?
Yes, it run ftrace at first before running LTP to trigger it,
https://github.com/cailca/linux-mm/blob/master/test.sh
echo function > /sys/kernel/debug/tracing/current_tracer
echo nop > /sys/kernel/debug/tracing/current_tracer
There is another crash with even non-NULL NIP, but then symbol behaves weird.
# ./scripts/faddr2line vmlinux sysctl_net_busy_read+0x0/0x4
skipping sysctl_net_busy_read address at 0xc0000000016804ac due to non-function symbol of type 'D'
[ 148.110969][T13115] LTP: starting chown04_16
[ 148.255048][T13380] kernel tried to execute exec-protected page (c0000000016804ac) - exploit attempt? (uid: 0)
[ 148.255099][T13380] BUG: Unable to handle kernel instruction fetch
[ 148.255122][T13380] Faulting instruction address: 0xc0000000016804ac
[ 148.255136][T13380] Oops: Kernel access of bad area, sig: 11 [#1]
[ 148.255157][T13380] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 148.255171][T13380] Modules linked in: loop kvm_hv kvm xfs sd_mod bnx2x mdio ahci tg3 libahci libphy libata firmware_class dm_mirror dm_region_hash dm_log dm_mod
[ 148.255213][T13380] CPU: 45 PID: 13380 Comm: chown04_16 Tainted: G W 5.6.0+ #7
[ 148.255236][T13380] NIP: c0000000016804ac LR: c00800000fa60408 CTR: c0000000016804ac
[ 148.255250][T13380] REGS: c0000010a6fafa00 TRAP: 0400 Tainted: G W (5.6.0+)
[ 148.255281][T13380] MSR: 9000000010009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 84000248 XER: 20040000
[ 148.255310][T13380] CFAR: c00800000fa66534 IRQMASK: 0
[ 148.255310][T13380] GPR00: c000000000973268 c0000010a6fafc90 c000000001648200 0000000000000000
[ 148.255310][T13380] GPR04: c000000d8a22dc00 c0000010a6fafd30 00000000b5e98331 ffffffff00012c9f
[ 148.255310][T13380] GPR08: c000000d8a22dc00 0000000000000000 0000000000000000 c00000000163c520
[ 148.255310][T13380] GPR12: c0000000016804ac c000001ffffdad80 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 148.255310][T13380] GPR24: 00007fff8f5e2e48 0000000000000000 c00800000fa6a488 c0000010a6fafd30
[ 148.255310][T13380] GPR28: 0000000000000000 000000007fffffff c00800000fa60400 c000000efd0c6780
[ 148.255494][T13380] NIP [c0000000016804ac] sysctl_net_busy_read+0x0/0x4
[ 148.255516][T13380] LR [c00800000fa60408] find_free_cb+0x8/0x30 [loop]
[ 148.255528][T13380] Call Trace:
[ 148.255538][T13380] [c0000010a6fafc90] [c0000000009732c0] idr_for_each+0xf0/0x170 (unreliable)
[ 148.255572][T13380] [c0000010a6fafd10] [c00800000fa626c4] loop_lookup.part.1+0x4c/0xb0 [loop]
[ 148.255597][T13380] [c0000010a6fafd50] [c00800000fa634d8] loop_control_ioctl+0x120/0x1d0 [loop]
[ 148.255623][T13380] [c0000010a6fafdb0] [c0000000004ddc08] ksys_ioctl+0xd8/0x130
[ 148.255636][T13380] [c0000010a6fafe00] [c0000000004ddc88] sys_ioctl+0x28/0x40
[ 148.255669][T13380] [c0000010a6fafe20] [c00000000000b378] system_call+0x5c/0x68
[ 148.255699][T13380] Instruction dump:
[ 148.255718][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255744][T13380] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 148.255772][T13380] ---[ end trace a5894a74208c22ec ]---
[ 148.576663][T13380]
[ 149.576765][T13380] Kernel panic - not syncing: Fatal exception
The bisect so far indicated the bad ones always have this,
aa1a8ce53332 Merge tag 'trace-v5.7' of git://git.kernel.org/pub/scm/linux/kernel/git/rostedt/linux-trace
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
quoted
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
OK, it was narrowed down to one of those messed with mcount here,
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
153368ce1bd0 ring-buffer: Optimize rb_iter_head_event()
ff84c50cfb4b ring-buffer: Do not die if rb_iter_peek() fails more than thrice
785888c544e0 ring-buffer: Have rb_iter_head_event() handle concurrent writer
28e3fc56a471 ring-buffer: Add page_stamp to iterator for synchronization
bc1a72afdc4a ring-buffer: Rename ring_buffer_read() to read_buffer_iter_advance()
ead6ecfddea5 ring-buffer: Have ring_buffer_empty() not depend on tracing stopped
ff895103a84a tracing: Save off entry when peeking at next entry
bf2cbe044da2 tracing: Use address-of operator on section symbols
bbd9d05618a6 gpu/trace: add a gpu total memory usage tracepoint
89b74cac7834 tools/bootconfig: Show line and column in parse error
306b69dce926 bootconfig: Support O=<builddir> option
5412e0b763e0 tracing: Remove unused TRACE_BUFFER bits
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
This time happens with another random NIP.
[ 130.866777][ T8601] LTP: starting chown04_16
[ 131.004754][ T8868] kernel tried to execute exec-protected page (c000000005add4d4) - exploit attempt? (uid: 0)
[ 131.004804][ T8868] BUG: Unable to handle kernel instruction fetch
[ 131.004827][ T8868] Faulting instruction address: 0xc000000005add4d4
[ 131.004850][ T8868] Oops: Kernel access of bad area, sig: 11 [#1]
[ 131.004862][ T8868] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[ 131.004885][ T8868] Modules linked in: loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x ahci tg3 mdio libahci libphy firmware_class libata dm_mirror dm_region_hash dm_log dm_mod
[ 131.004925][ T8868] CPU: 58 PID: 8868 Comm: chown04_16 Tainted: G W 5.6.0+ #6
[ 131.004939][ T8868] NIP: c000000005add4d4 LR: c00800000fb20408 CTR: c000000005add4d4
[ 131.004962][ T8868] REGS: c000001b3c32fa00 TRAP: 0400 Tainted: G W (5.6.0+)
[ 131.004993][ T8868] MSR: 9000000010009033 <SF,HV,EE,ME,IR,DR,RI,LE> CR: 84000248 XER: 20040000
[ 131.005031][ T8868] CFAR: c00800000fb26534 IRQMASK: 0
[ 131.005031][ T8868] GPR00: c00000000097c638 c000001b3c32fc90 c000000001659400 0000000000000000
[ 131.005031][ T8868] GPR04: c00000004a96b800 c000001b3c32fd30 000000000b83d6b8 ffffffff000129f4
[ 131.005031][ T8868] GPR08: c00000004a96b800 0000000000000000 0000000000000000 c00000000164d720
[ 131.005031][ T8868] GPR12: c000000005add4d4 c000001ffffd0b00 0000000000000000 0000000000000000
[ 131.005031][ T8868] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 131.005031][ T8868] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000000
[ 131.005031][ T8868] GPR24: 00007fffa4982d80 0000000000000000 c00800000fb2a488 c000001b3c32fd30
[ 131.005031][ T8868] GPR28: 0000000000000000 000000007fffffff c00800000fb20400 c000000335c88790
[ 131.005202][ T8868] NIP [c000000005add4d4] net_msg_warn+0x0/0x4
[ 131.005224][ T8868] LR [c00800000fb20408] find_free_cb+0x8/0x30 [loop]
[ 131.005243][ T8868] Call Trace:
[ 131.005253][ T8868] [c000001b3c32fc90] [c00000000097c690] idr_for_each+0xf0/0x170 (unreliable)
[ 131.005278][ T8868] [c000001b3c32fd10] [c00800000fb226c4] loop_lookup.part.1+0x4c/0xb0 [loop]
[ 131.005311][ T8868] [c000001b3c32fd50] [c00800000fb234d8] loop_control_ioctl+0x120/0x1d0 [loop]
[ 131.005344][ T8868] [c000001b3c32fdb0] [c0000000004dd778] ksys_ioctl+0xd8/0x130
[ 131.005376][ T8868] [c000001b3c32fe00] [c0000000004dd7f8] sys_ioctl+0x28/0x40
[ 131.005399][ T8868] [c000001b3c32fe20] [c00000000000b378] system_call+0x5c/0x68
[ 131.005438][ T8868] Instruction dump:
[ 131.005465][ T8868] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 131.005500][ T8868] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX
[ 131.005527][ T8868] ---[ end trace cfaf36049cb72805 ]---
[ 131.117039][ T8868]
[ 132.117139][ T8868] Kernel panic - not syncing: Fatal exception
From: Steven Rostedt <rostedt@goodmis.org> Date: 2020-04-09 14:14:22
On Thu, 9 Apr 2020 06:06:35 -0400
Qian Cai [off-list ref] wrote:
quoted
quoted
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
quoted
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
OK, it was narrowed down to one of those messed with mcount here,
Thing is, nothing here touches mcount.
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
Touches reading the trace buffer.
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
Documentation.
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
kprobe output.
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
Reading the buffer.
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
Reading the buffer.
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
Reading the buffer.
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
Affects only the hard ware latency detector (most likely not even
configured in the kernel).
So I don't understand how any of the above commits can cause a problem.
-- Steve
On Apr 9, 2020, at 10:14 AM, Steven Rostedt [off-list ref] wrote:
On Thu, 9 Apr 2020 06:06:35 -0400
Qian Cai [off-list ref] wrote:
quoted
quoted
quoted
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
quoted
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
OK, it was narrowed down to one of those messed with mcount here,
Thing is, nothing here touches mcount.
Yes, you are right. I went back to test the commit just before the 5.7-trace merge request,
I did reproduce there. The thing is that this bastard could take more 6-hour to happen,
so my previous attempt did not wait long enough. Back to the square one...
quoted
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
Touches reading the trace buffer.
quoted
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
Documentation.
quoted
6a13a0d7b4d1 ftrace/kprobe: Show the maxactive number on kprobe_events
kprobe output.
quoted
c9b7a4a72ff6 ring-buffer/tracing: Have iterator acknowledge dropped events
Reading the buffer.
quoted
06e0a548bad0 tracing: Do not disable tracing when reading the trace file
Reading the buffer.
quoted
1039221cc278 ring-buffer: Do not disable recording when there is an iterator
Reading the buffer.
quoted
07b8b10ec94f ring-buffer: Make resize disable per cpu buffer instead of total buffer
b396bfdebffc tracing: Have hwlat ts be first instance and record count of instances
Affects only the hard ware latency detector (most likely not even
configured in the kernel).
So I don't understand how any of the above commits can cause a problem.
-- Steve
On Apr 10, 2020, at 3:20 PM, Qian Cai [off-list ref] wrote:
quoted
On Apr 9, 2020, at 10:14 AM, Steven Rostedt [off-list ref] wrote:
On Thu, 9 Apr 2020 06:06:35 -0400
Qian Cai [off-list ref] wrote:
quoted
quoted
quoted
I’ll go to bisect some more but it is going to take a while.
$ git log --oneline 4c205c84e249..8e99cf91b99b
8e99cf91b99b tracing: Do not allocate buffer in trace_find_next_entry() in atomic
2ab2a0924b99 tracing: Add documentation on set_ftrace_notrace_pid and set_event_notrace_pid
ebed9628f5c2 selftests/ftrace: Add test to test new set_event_notrace_pid file
ed8839e072b8 selftests/ftrace: Add test to test new set_ftrace_notrace_pid file
276836260301 tracing: Create set_event_notrace_pid to not trace tasks
quoted
b3b1e6ededa4 ftrace: Create set_ftrace_notrace_pid to not trace tasks
717e3f5ebc82 ftrace: Make function trace pid filtering a bit more exact
If it is affecting function tracing, it is probably one of the above two
commits.
OK, it was narrowed down to one of those messed with mcount here,
Thing is, nothing here touches mcount.
Yes, you are right. I went back to test the commit just before the 5.7-trace merge request,
I did reproduce there. The thing is that this bastard could take more 6-hour to happen,
so my previous attempt did not wait long enough. Back to the square one…
OK, I starts to test all commits up to 12 hours. The progess on far is,
BAD: v5.6-rc1
GOOD: v5.5
GOOD: 153b5c566d30 Merge tag 'microblaze-v5.6-rc1' of git://git.monstr.eu/linux-2.6-microblaze
The next step I’ll be testing,
71c3a888cbca Merge tag 'powerpc-5.6-1' of git://git.kernel.org/pub/scm/linux/kernel/git/powerpc/linux
IF that is BAD, the merge request is the culprit. I can see a few commits are more related that others.
5290ae2b8e5f powerpc/64: Use {SAVE,REST}_NVGPRS macros
ed0bc98f8cbe powerpc/64s: Reimplement power4_idle code in C
Does it ring any bell yet?
From: Steven Rostedt <rostedt@goodmis.org> Date: 2020-04-17 02:17:58
On Thu, 16 Apr 2020 21:19:10 -0400
Qian Cai [off-list ref] wrote:
OK, reverted the commit,
c55d7b5e6426 (“powerpc: Remove STRICT_KERNEL_RWX incompatibility with RELOCATABLE”)
or set STRICT_KERNEL_RWX=n fixed the crash below and also mentioned in this thread,
The instruction pointer is on sysctl_net_busy_read? Isn't that data and
not code?
In net/socket.c:
#ifdef CONFIG_NET_RX_BUSY_POLL
unsigned int sysctl_net_busy_read __read_mostly;
unsigned int sysctl_net_busy_poll __read_mostly;
#endif
-- Steve
From: Russell Currey <hidden> Date: 2020-04-17 02:27:49
On Thu, 2020-04-16 at 22:17 -0400, Steven Rostedt wrote:
On Thu, 16 Apr 2020 21:19:10 -0400
Qian Cai [off-list ref] wrote:
quoted
OK, reverted the commit,
c55d7b5e6426 (“powerpc: Remove STRICT_KERNEL_RWX incompatibility
with RELOCATABLE”)
or set STRICT_KERNEL_RWX=n fixed the crash below and also mentioned
in this thread,
This may be a symptom and not a cure.
Reverting the patch with the given config will have the same effect as
STRICT_KERNEL_RWX=n. Not discounting that it could be a bug on the
powerpc side (i.e. relocatable kernels with strict RWX on haven't been
exhaustively tested yet), but we should definitely figure out what's
going on with this bad access first.
The instruction pointer is on sysctl_net_busy_read? Isn't that data
and
not code?
In net/socket.c:
#ifdef CONFIG_NET_RX_BUSY_POLL
unsigned int sysctl_net_busy_read __read_mostly;
unsigned int sysctl_net_busy_poll __read_mostly;
#endif
-- Steve
From: Michael Ellerman <mpe@ellerman.id.au> Date: 2020-04-17 11:45:30
Steven Rostedt [off-list ref] writes:
On Thu, 16 Apr 2020 21:19:10 -0400
Qian Cai [off-list ref] wrote:
quoted
OK, reverted the commit,
c55d7b5e6426 (“powerpc: Remove STRICT_KERNEL_RWX incompatibility with RELOCATABLE”)
or set STRICT_KERNEL_RWX=n fixed the crash below and also mentioned in this thread,
This may be a symptom and not a cure.
I think it is a cure.
But we still have a bug, which is that when STRICT_KERNEL_RWX is enabled
we have some sort of corruption going on.
Enabling STRICT_KERNEL_RWX changes our implementation of
patch_instruction() which is used by ftrace, so I suspect this is a
powerpc bug.
The instruction pointer is on sysctl_net_busy_read? Isn't that data and
not code?
Yes.
But we're corrupting the text, or data, somewhere, so we can jump
anywhere.
I have another trace where vhost_init() appears to call into
proc_dointvec() before crashing. vhost_init() is an empty function.
cheers
Do you see any errors logged in dmesg when you see the crash?
STRICT_KERNEL_RWX changes how patch_instruction() works, so it would be
interesting to see if there are any ftrace-related errors thrown before
the crash.
- Naveen
Do you see any errors logged in dmesg when you see the crash?
STRICT_KERNEL_RWX changes how patch_instruction() works, so it would be
interesting to see if there are any ftrace-related errors thrown before
the crash.
I've been able to reproduce with STRICT_KERNEL_RWX=y and concurrently
running:
# while true; do echo function > /sys/kernel/debug/tracing/current_tracer ; echo nop > /sys/kernel/debug/tracing/current_tracer ; done
and:
# while true; do find /lib/modules/$(uname -r) -name '*.ko' -printf "%f\n" | sed -e "s/\.ko//" | xargs -i modprobe -va {}; lsmod | awk '{print $1}' | xargs -i modprobe -vr {}; done
ie. stressing module loading/unloading and ftrace at the same time.
It's not 100% but it usually reproduces within 10-20 minutes.
It looks like sometimes our __patch_instruction() fails, and then that
somehow leads to things getting further messed up. Presumably we have
some bad error handling somewhere.
cheers
Do you see any errors logged in dmesg when you see the crash? STRICT_KERNEL_RWX changes how patch_instruction() works, so it would be interesting to see if there are any ftrace-related errors thrown before the crash.
Do you see any errors logged in dmesg when you see the crash? STRICT_KERNEL_RWX changes how patch_instruction() works, so it would be interesting to see if there are any ftrace-related errors thrown before the crash.
Thanks. That confirms the problem.
In this particular case, we are unable to convert a module function to
call into ftrace_caller() since the _mcount() entry has not been nop-ed
out during module load. I suspect there might be another error/warning
earlier on indicating that failure. There are a few scenarios where we
are not propagating errors from patch_instruction() properly, so it is
possible that no errors were thrown previously. I will send a separate
set of patches to address that.
The reason for the original crash is a bit more subtle. On module load,
we patch _mcount() call sites of all the module functions with a nop.
However, with STRICT_KERNEL_RWX, one of these is failing. When that
happens, we end up continuing to call into _mcount(), which uses the
default module relocation stub, and not the special ftrace stub. The
default stub uses r2, which won't always be loaded with the module TOC
pointer with -mprofile-kernel. Instead, r2 likely points to the kernel
TOC, so we end up loading incorrect entries from the kernel TOC to
branch to. In all the traces we've seen so far, a kernel function has
called into a module function, wherein the module function does not set
up its own TOC (ext4_iomap_end(), find_free_cb()).
The core of the problem though is that patch_instruction() is failing in
certain scenarios. We need to find out why that is, and address that.
Russell,
You mentioned in the past that you identified an issue with
patch_instruction() during early boot:
http://lkml.kernel.org/r/c336400d5b7765eb72b3090cd9f8a3c57761d0b6.camel@russell.cc
Does that failure happen without STRICT_MODULE_RWX, with just
STRICT_KERNEL_RWX? That might be relevant here.
- Naveen