Re: Linux-next POWER9 NULL pointer NIP since 1st Apr.

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

quoted

cheers

quoted

[  208.681091][T27684] Call Trace:
[  208.681129][T27684] [c000200361def6b0] [c0000000005ac3bc] iomap_apply+0x20c/0x920 (unreliable) iomap_apply at fs/iomap/apply.c:80 (discriminator 4)
[  208.681173][T27684] [c000200361def7f0] [c0000000005b4adc] iomap_bmap+0xfc/0x160 iomap_bmap at fs/iomap/fiemap.c:142
[  208.681228][T27684] [c000200361def850] [c0080000102c2c1c] ext4_bmap+0xa4/0x180 [ext4] ext4_bmap at fs/ext4/inode.c:3213
[  208.681260][T27684] [c000200361def890] [c0000000004f71fc] bmap+0x4c/0x80
[  208.681281][T27684] [c000200361def8c0] [c00800000fdb0acc] jbd2_journal_init_inode+0x44/0x1a0 [jbd2] jbd2_journal_init_inode at fs/jbd2/journal.c:1255
[  208.681326][T27684] [c000200361def960] [c00800001031c808] ext4_load_journal+0x440/0x860 [ext4]
[  208.681371][T27684] [c000200361defa30] [c008000010322a14] ext4_fill_super+0x342c/0x3ab0 [ext4]
[  208.681414][T27684] [c000200361defba0] [c0000000004cb0bc] mount_bdev+0x25c/0x290
[  208.681478][T27684] [c000200361defc40] [c008000010310250] ext4_mount+0x28/0x50 [ext4]
[  208.681520][T27684] [c000200361defc60] [c00000000053242c] legacy_get_tree+0x4c/0xb0
[  208.681556][T27684] [c000200361defc90] [c0000000004c864c] vfs_get_tree+0x4c/0x130
[  208.681593][T27684] [c000200361defd00] [c00000000050a1c8] do_mount+0xa18/0xc50
[  208.681641][T27684] [c000200361defdd0] [c00000000050a9a8] sys_mount+0x158/0x180
[  208.681679][T27684] [c000200361defe20] [c00000000000b3f8] system_call+0x5c/0x68
[  208.681726][T27684] Instruction dump:
[  208.681747][T27684] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX 
[  208.681797][T27684] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX 
[  208.681839][T27684] ---[ end trace 4e9e2bab7f1d4048 ]---
[  208.802259][T27684] 
[  209.802373][T27684] Kernel panic - not syncing: Fatal exception

[  215.281666][T16896] LTP: starting chown04_16
[  215.424203][T18297] BUG: Unable to handle kernel instruction fetch (NULL pointer?)
[  215.424289][T18297] Faulting instruction address: 0x00000000
[  215.424313][T18297] Oops: Kernel access of bad area, sig: 11 [#1]
[  215.424341][T18297] LE PAGE_SIZE=64K MMU=Radix SMP NR_CPUS=256 DEBUG_PAGEALLOC NUMA PowerNV
[  215.424383][T18297] Modules linked in: loop kvm_hv kvm ip_tables x_tables xfs sd_mod bnx2x mdio tg3 ahci libahci libphy libata firmware_class dm_mirror dm_region_hash dm_log dm_mod
[  215.424459][T18297] CPU: 85 PID: 18297 Comm: chown04_16 Tainted: G        W         5.6.0-next-20200405+ #3
[  215.424489][T18297] NIP:  0000000000000000 LR: c00800000fbc0408 CTR: 0000000000000000
[  215.424530][T18297] REGS: c000200b8606f990 TRAP: 0400   Tainted: G        W          (5.6.0-next-20200405+)
[  215.424570][T18297] MSR:  9000000040009033 <SF,HV,EE,ME,IR,DR,RI,LE>  CR: 84000248  XER: 20040000
[  215.424619][T18297] CFAR: c00800000fbc64f4 IRQMASK: 0 
[  215.424619][T18297] GPR00: c0000000006c2238 c000200b8606fc20 c00000000165ce00 0000000000000000 
[  215.424619][T18297] GPR04: c000201a58106400 c000200b8606fcc0 000000005f037e7d ffffffff00013bfb 
[  215.424619][T18297] GPR08: c000201a58106400 0000000000000000 0000000000000000 c000000001652ee0 
[  215.424619][T18297] GPR12: 0000000000000000 c000201fff69a600 0000000000000000 0000000000000000 
[  215.424619][T18297] GPR16: 0000000000000000 0000000000000000 0000000000000000 0000000000000000 
[  215.424619][T18297] GPR20: 0000000000000000 0000000000000000 0000000000000000 0000000000000007 
[  215.424619][T18297] GPR24: 0000000000000000 0000000000000000 c00800000fbc8688 c000200b8606fcc0 
[  215.424619][T18297] GPR28: 0000000000000000 000000007fffffff c00800000fbc0400 c00020068b8c0e70 
[  215.424914][T18297] NIP [0000000000000000] 0x0
[  215.424953][T18297] LR [c00800000fbc0408] find_free_cb+0x8/0x30 [loop]
find_free_cb at drivers/block/loop.c:2129
[  215.424997][T18297] Call Trace:
[  215.425036][T18297] [c000200b8606fc20] [c0000000006c2290] idr_for_each+0xf0/0x170 (unreliable)
[  215.425073][T18297] [c000200b8606fca0] [c00800000fbc2744] loop_lookup.part.2+0x4c/0xb0 [loop]
loop_lookup at drivers/block/loop.c:2144
[  215.425105][T18297] [c000200b8606fce0] [c00800000fbc3558] loop_control_ioctl+0x120/0x1d0 [loop]
[  215.425149][T18297] [c000200b8606fd40] [c0000000004eb688] ksys_ioctl+0xd8/0x130
[  215.425190][T18297] [c000200b8606fd90] [c0000000004eb708] sys_ioctl+0x28/0x40
[  215.425233][T18297] [c000200b8606fdb0] [c00000000003cc30] system_call_exception+0x110/0x1e0
[  215.425274][T18297] [c000200b8606fe20] [c00000000000c9f0] system_call_common+0xf0/0x278
[  215.425314][T18297] Instruction dump:
[  215.425338][T18297] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX 
[  215.425374][T18297] XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX XXXXXXXX 
[  215.425422][T18297] ---[ end trace ebed248fad431966 ]---
[  215.642114][T18297] 
[  216.642220][T18297] Kernel panic - not syncing: Fatal exception