On Tue, 10 Aug 2021 18:37:31 +0200
Sebastian Andrzej Siewior [off-list ref] wrote:
Sebastian, et al,
Got the following panic running v5.14-rc5-rt8:
Aug 13 06:35:05 oberon kernel: page:000000009ac5dd73 refcount:0 mapcount:0 mapping:0000000000000000 index:0x0 pfn:0x1ab3db
Aug 13 06:35:05 oberon kernel: flags: 0x17ffffc0000000(node=0|zone=2|lastcpupid=0x1fffff)
Aug 13 06:35:05 oberon kernel: raw: 0017ffffc0000000 ffffee1286aceb88 ffffee1287b66288 0000000000000000
Aug 13 06:35:05 oberon kernel: raw: 0000000000000000 0000000000100000 00000000ffffffff 0000000000000000
Aug 13 06:35:05 oberon kernel: page dumped because: VM_BUG_ON_PAGE(!PageSlab(page))
Aug 13 06:35:05 oberon kernel: ------------[ cut here ]------------
Aug 13 06:35:05 oberon kernel: kernel BUG at include/linux/page-flags.h:814!
Aug 13 06:35:05 oberon kernel: invalid opcode: 0000 [#1] PREEMPT_RT SMP PTI
Aug 13 06:35:05 oberon kernel: CPU: 3 PID: 12345 Comm: hackbench Not tainted 5.14.0-rc5-rt8+ #12
Aug 13 06:35:05 oberon kernel: Hardware name: /NUC5i7RYB, BIOS RYBDWi35.86A.0359.2016.0906.1028 09/06/2016
Aug 13 06:35:05 oberon kernel: RIP: 0010:___slab_alloc+0x340/0x940
Are you able to translate this RIP via addr2line?
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c04bdaf8 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Call Trace:
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: alloc_skb_with_frags+0x64/0x250
Aug 13 06:35:05 oberon kernel: sock_alloc_send_pskb+0x260/0x2b0
Aug 13 06:35:05 oberon kernel: ? bpf_lsm_socket_getpeersec_dgram+0xa/0x10
Aug 13 06:35:05 oberon kernel: unix_stream_sendmsg+0x27c/0x550
Aug 13 06:35:05 oberon kernel: ? unix_seqpacket_recvmsg+0x60/0x60
Aug 13 06:35:05 oberon kernel: sock_sendmsg+0xbd/0xd0
Aug 13 06:35:05 oberon kernel: sock_write_iter+0xb9/0x120
Aug 13 06:35:05 oberon kernel: new_sync_write+0x175/0x200
Aug 13 06:35:05 oberon kernel: vfs_write+0x3c4/0x510
Aug 13 06:35:05 oberon kernel: ksys_write+0xc9/0x110
Aug 13 06:35:05 oberon kernel: do_syscall_64+0x3b/0x90
Aug 13 06:35:05 oberon kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
While SLUB RT rewrite is obvious suspect, could be also a boring slab
misuse (use-after-free etc), wouldn't be the first related to skb's...
If this reproduces well, could you try booting with slub_debug boot
param. Could catch the culprit sooner (but also hide the bug,
unfortunately).
Aug 13 06:35:05 oberon kernel: RIP: 0033:0x7f474b3a2877
Aug 13 06:35:05 oberon kernel: Code: 75 05 48 83 c4 58 c3 e8 37 4e ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 0>
Aug 13 06:35:05 oberon kernel: RSP: 002b:00007ffe5e71e7a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Aug 13 06:35:05 oberon kernel: RAX: ffffffffffffffda RBX: 00000000000003e8 RCX: 00007f474b3a2877
Aug 13 06:35:05 oberon kernel: RDX: 00000000000003e8 RSI: 00007ffe5e71e7b0 RDI: 0000000000000010
Aug 13 06:35:05 oberon kernel: RBP: 00007ffe5e71ebf0 R08: 00007ffe5e71e700 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000008 R11: 0000000000000246 R12: 00007ffe5e71e7b0
Aug 13 06:35:05 oberon kernel: R13: 0000000000000008 R14: 0000560b46008210 R15: 0000000000000000
Aug 13 06:35:05 oberon kernel: Modules linked in: uinput rfcomm snd_seq_dummy snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tf>
Aug 13 06:35:05 oberon kernel: snd_intel_dspcfg snd_hda_codec mei_hdcp snd_hda_core snd_hwdep cfg80211 snd_seq iTCO_wdt snd_seq_device intel_pmc_bxt>
Aug 13 06:35:05 oberon kernel: ---[ end trace 0000000000000002 ]---
Aug 13 06:35:05 oberon kernel: RIP: 0010:___slab_alloc+0x340/0x940
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c1d901a0 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Kernel panic - not syncing:
Config is attached.
I was running the rteval script that kicks off parallel kernel builds and hackbench runs as loads and runs cyclictest with a thread on each core:
$ sudo rteval --duration=10m
Clark
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c04bdaf8 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Call Trace:
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: alloc_skb_with_frags+0x64/0x250
Aug 13 06:35:05 oberon kernel: sock_alloc_send_pskb+0x260/0x2b0
Aug 13 06:35:05 oberon kernel: ? bpf_lsm_socket_getpeersec_dgram+0xa/0x10
Aug 13 06:35:05 oberon kernel: unix_stream_sendmsg+0x27c/0x550
Aug 13 06:35:05 oberon kernel: ? unix_seqpacket_recvmsg+0x60/0x60
Aug 13 06:35:05 oberon kernel: sock_sendmsg+0xbd/0xd0
Aug 13 06:35:05 oberon kernel: sock_write_iter+0xb9/0x120
Aug 13 06:35:05 oberon kernel: new_sync_write+0x175/0x200
Aug 13 06:35:05 oberon kernel: vfs_write+0x3c4/0x510
Aug 13 06:35:05 oberon kernel: ksys_write+0xc9/0x110
Aug 13 06:35:05 oberon kernel: do_syscall_64+0x3b/0x90
Aug 13 06:35:05 oberon kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
While SLUB RT rewrite is obvious suspect, could be also a boring slab
misuse (use-after-free etc), wouldn't be the first related to skb's...
If this reproduces well, could you try booting with slub_debug boot
param. Could catch the culprit sooner (but also hide the bug,
unfortunately).
Without 'slub_debug' it panic's consistently.
Adding 'slub_debug' to the boot command line causes odd behavior where load and measurement tasks
run by 'rteval' crash, but (so far) no kernel panic.
quoted
Aug 13 06:35:05 oberon kernel: RIP: 0033:0x7f474b3a2877
Aug 13 06:35:05 oberon kernel: Code: 75 05 48 83 c4 58 c3 e8 37 4e ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 0>
Aug 13 06:35:05 oberon kernel: RSP: 002b:00007ffe5e71e7a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Aug 13 06:35:05 oberon kernel: RAX: ffffffffffffffda RBX: 00000000000003e8 RCX: 00007f474b3a2877
Aug 13 06:35:05 oberon kernel: RDX: 00000000000003e8 RSI: 00007ffe5e71e7b0 RDI: 0000000000000010
Aug 13 06:35:05 oberon kernel: RBP: 00007ffe5e71ebf0 R08: 00007ffe5e71e700 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000008 R11: 0000000000000246 R12: 00007ffe5e71e7b0
Aug 13 06:35:05 oberon kernel: R13: 0000000000000008 R14: 0000560b46008210 R15: 0000000000000000
Aug 13 06:35:05 oberon kernel: Modules linked in: uinput rfcomm snd_seq_dummy snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tf>
Aug 13 06:35:05 oberon kernel: snd_intel_dspcfg snd_hda_codec mei_hdcp snd_hda_core snd_hwdep cfg80211 snd_seq iTCO_wdt snd_seq_device intel_pmc_bxt>
Aug 13 06:35:05 oberon kernel: ---[ end trace 0000000000000002 ]---
Aug 13 06:35:05 oberon kernel: RIP: 0010:___slab_alloc+0x340/0x940
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c1d901a0 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Kernel panic - not syncing:
Config is attached.
I was running the rteval script that kicks off parallel kernel builds and hackbench runs as loads and runs cyclictest with a thread on each core:
$ sudo rteval --duration=10m
Clark
--
The United States Coast Guard
Ruining Natural Selection since 1790
Hm that's not much useful, I'd need the line in mm/slub.c
does ./scripts/faddr2line give better output?
quoted
quoted
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c04bdaf8 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Call Trace:
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: alloc_skb_with_frags+0x64/0x250
Aug 13 06:35:05 oberon kernel: sock_alloc_send_pskb+0x260/0x2b0
Aug 13 06:35:05 oberon kernel: ? bpf_lsm_socket_getpeersec_dgram+0xa/0x10
Aug 13 06:35:05 oberon kernel: unix_stream_sendmsg+0x27c/0x550
Aug 13 06:35:05 oberon kernel: ? unix_seqpacket_recvmsg+0x60/0x60
Aug 13 06:35:05 oberon kernel: sock_sendmsg+0xbd/0xd0
Aug 13 06:35:05 oberon kernel: sock_write_iter+0xb9/0x120
Aug 13 06:35:05 oberon kernel: new_sync_write+0x175/0x200
Aug 13 06:35:05 oberon kernel: vfs_write+0x3c4/0x510
Aug 13 06:35:05 oberon kernel: ksys_write+0xc9/0x110
Aug 13 06:35:05 oberon kernel: do_syscall_64+0x3b/0x90
Aug 13 06:35:05 oberon kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
While SLUB RT rewrite is obvious suspect, could be also a boring slab
misuse (use-after-free etc), wouldn't be the first related to skb's...
If this reproduces well, could you try booting with slub_debug boot
param. Could catch the culprit sooner (but also hide the bug,
unfortunately).
Without 'slub_debug' it panic's consistently.
Adding 'slub_debug' to the boot command line causes odd behavior where load and measurement tasks
run by 'rteval' crash, but (so far) no kernel panic.
Huh. And nothing in dmesg about corrupted slabs with slub_debug?
quoted
quoted
Aug 13 06:35:05 oberon kernel: RIP: 0033:0x7f474b3a2877
Aug 13 06:35:05 oberon kernel: Code: 75 05 48 83 c4 58 c3 e8 37 4e ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 0>
Aug 13 06:35:05 oberon kernel: RSP: 002b:00007ffe5e71e7a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Aug 13 06:35:05 oberon kernel: RAX: ffffffffffffffda RBX: 00000000000003e8 RCX: 00007f474b3a2877
Aug 13 06:35:05 oberon kernel: RDX: 00000000000003e8 RSI: 00007ffe5e71e7b0 RDI: 0000000000000010
Aug 13 06:35:05 oberon kernel: RBP: 00007ffe5e71ebf0 R08: 00007ffe5e71e700 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000008 R11: 0000000000000246 R12: 00007ffe5e71e7b0
Aug 13 06:35:05 oberon kernel: R13: 0000000000000008 R14: 0000560b46008210 R15: 0000000000000000
Aug 13 06:35:05 oberon kernel: Modules linked in: uinput rfcomm snd_seq_dummy snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tf>
Aug 13 06:35:05 oberon kernel: snd_intel_dspcfg snd_hda_codec mei_hdcp snd_hda_core snd_hwdep cfg80211 snd_seq iTCO_wdt snd_seq_device intel_pmc_bxt>
Aug 13 06:35:05 oberon kernel: ---[ end trace 0000000000000002 ]---
Aug 13 06:35:05 oberon kernel: RIP: 0010:___slab_alloc+0x340/0x940
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c1d901a0 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Kernel panic - not syncing:
Config is attached.
I was running the rteval script that kicks off parallel kernel builds and hackbench runs as loads and runs cyclictest with a thread on each core:
$ sudo rteval --duration=10m
Clark
Hm that's not much useful, I'd need the line in mm/slub.c
does ./scripts/faddr2line give better output?
Why, yes it does! :)
$ ./scripts/faddr2line /data/o/linux-5.14.y-rt/vmlinux ___slab_alloc+0x340/0x940
___slab_alloc+0x340/0x940:
PageSlabPfmemalloc at include/linux/page-flags.h:814
(inlined by) pfmemalloc_match at mm/slub.c:2772
(inlined by) ___slab_alloc at mm/slub.c:2874
quoted
quoted
quoted
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c04bdaf8 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Call Trace:
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: ? kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: kmem_cache_alloc_node+0xa4/0x2b0
Aug 13 06:35:05 oberon kernel: __alloc_skb+0x1db/0x270
Aug 13 06:35:05 oberon kernel: alloc_skb_with_frags+0x64/0x250
Aug 13 06:35:05 oberon kernel: sock_alloc_send_pskb+0x260/0x2b0
Aug 13 06:35:05 oberon kernel: ? bpf_lsm_socket_getpeersec_dgram+0xa/0x10
Aug 13 06:35:05 oberon kernel: unix_stream_sendmsg+0x27c/0x550
Aug 13 06:35:05 oberon kernel: ? unix_seqpacket_recvmsg+0x60/0x60
Aug 13 06:35:05 oberon kernel: sock_sendmsg+0xbd/0xd0
Aug 13 06:35:05 oberon kernel: sock_write_iter+0xb9/0x120
Aug 13 06:35:05 oberon kernel: new_sync_write+0x175/0x200
Aug 13 06:35:05 oberon kernel: vfs_write+0x3c4/0x510
Aug 13 06:35:05 oberon kernel: ksys_write+0xc9/0x110
Aug 13 06:35:05 oberon kernel: do_syscall_64+0x3b/0x90
Aug 13 06:35:05 oberon kernel: entry_SYSCALL_64_after_hwframe+0x44/0xae
While SLUB RT rewrite is obvious suspect, could be also a boring slab
misuse (use-after-free etc), wouldn't be the first related to skb's...
If this reproduces well, could you try booting with slub_debug boot
param. Could catch the culprit sooner (but also hide the bug,
unfortunately).
Without 'slub_debug' it panic's consistently.
Adding 'slub_debug' to the boot command line causes odd behavior where load and measurement tasks
run by 'rteval' crash, but (so far) no kernel panic.
Huh. And nothing in dmesg about corrupted slabs with slub_debug?
No, nothing slab related in the log. Typical gnome-shell complaints and a lockdep complaint
about MAX_LOCKDEP_ENTRIES too low, but nothing really wierd.
quoted
quoted
quoted
Aug 13 06:35:05 oberon kernel: RIP: 0033:0x7f474b3a2877
Aug 13 06:35:05 oberon kernel: Code: 75 05 48 83 c4 58 c3 e8 37 4e ff ff 0f 1f 80 00 00 00 00 f3 0f 1e fa 64 8b 04 25 18 00 00 00 85 c0 75 10 b8 01 0>
Aug 13 06:35:05 oberon kernel: RSP: 002b:00007ffe5e71e7a8 EFLAGS: 00000246 ORIG_RAX: 0000000000000001
Aug 13 06:35:05 oberon kernel: RAX: ffffffffffffffda RBX: 00000000000003e8 RCX: 00007f474b3a2877
Aug 13 06:35:05 oberon kernel: RDX: 00000000000003e8 RSI: 00007ffe5e71e7b0 RDI: 0000000000000010
Aug 13 06:35:05 oberon kernel: RBP: 00007ffe5e71ebf0 R08: 00007ffe5e71e700 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000008 R11: 0000000000000246 R12: 00007ffe5e71e7b0
Aug 13 06:35:05 oberon kernel: R13: 0000000000000008 R14: 0000560b46008210 R15: 0000000000000000
Aug 13 06:35:05 oberon kernel: Modules linked in: uinput rfcomm snd_seq_dummy snd_hrtimer xt_CHECKSUM xt_MASQUERADE xt_conntrack ipt_REJECT nf_nat_tf>
Aug 13 06:35:05 oberon kernel: snd_intel_dspcfg snd_hda_codec mei_hdcp snd_hda_core snd_hwdep cfg80211 snd_seq iTCO_wdt snd_seq_device intel_pmc_bxt>
Aug 13 06:35:05 oberon kernel: ---[ end trace 0000000000000002 ]---
Aug 13 06:35:05 oberon kernel: RIP: 0010:___slab_alloc+0x340/0x940
Aug 13 06:35:05 oberon kernel: Code: c6 48 0f a3 05 b1 7b 57 03 72 99 c7 85 78 ff ff ff ff ff ff ff 48 8b 7d 88 e9 8d fd ff ff 48 c7 c6 50 5a 7c b0 e>
Aug 13 06:35:05 oberon kernel: RSP: 0018:ffffba1c4a8b7ab0 EFLAGS: 00010293
Aug 13 06:35:05 oberon kernel: RAX: 0000000000000000 RBX: 0000000000000002 RCX: ffff9bb765118000
Aug 13 06:35:05 oberon kernel: RDX: 0000000000000000 RSI: ffffffffaf426050 RDI: 00000000ffffffff
Aug 13 06:35:05 oberon kernel: RBP: ffffba1c4a8b7b70 R08: 0000000000000000 R09: 0000000000000000
Aug 13 06:35:05 oberon kernel: R10: 0000000000000000 R11: 0000000000000000 R12: ffff9bb7410d3600
Aug 13 06:35:05 oberon kernel: R13: 0000000000400cc0 R14: 00000000001f7770 R15: ffff9bbe76df7770
Aug 13 06:35:05 oberon kernel: FS: 00007f474b1be740(0000) GS:ffff9bbe76c00000(0000) knlGS:0000000000000000
Aug 13 06:35:05 oberon kernel: CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
Aug 13 06:35:05 oberon kernel: CR2: 00007f60c1d901a0 CR3: 0000000124f3a003 CR4: 00000000003706e0
Aug 13 06:35:05 oberon kernel: Kernel panic - not syncing:
Config is attached.
I was running the rteval script that kicks off parallel kernel builds and hackbench runs as loads and runs cyclictest with a thread on each core:
$ sudo rteval --duration=10m
Clark
--
The United States Coast Guard
Ruining Natural Selection since 1790
Hm that's not much useful, I'd need the line in mm/slub.c
does ./scripts/faddr2line give better output?
Why, yes it does! :)
$ ./scripts/faddr2line /data/o/linux-5.14.y-rt/vmlinux ___slab_alloc+0x340/0x940
___slab_alloc+0x340/0x940:
PageSlabPfmemalloc at include/linux/page-flags.h:814
(inlined by) pfmemalloc_match at mm/slub.c:2772
(inlined by) ___slab_alloc at mm/slub.c:2874
Aha! That's helpful. Hopefully it's just a small issue where we
opportunistically test flags on a page that's protected by the local
lock we didn't take yet, and I didn't realize there's the VM_BUG_ON
which can trigger if our page went away (which we would have realized
after taking the lock).
So hopefully the below diff with uninspired naming should help?
----8<----
@@ -2871,7 +2879,7 @@ static void *___slab_alloc(struct kmem_cache *s, gfp_t gfpflags, int node,*PFMEMALLOCbutrightnow,wearelosingthepfmemalloc*informationwhenthepageleavestheper-cpuallocator*/-if(unlikely(!pfmemalloc_match(page,gfpflags)))+if(unlikely(!try_pfmemalloc_match(page,gfpflags)))gotodeactivate_slab;/* must check again c->page in case we got preempted and it changed */
From: Mike Galbraith <hidden> Date: 2021-08-15 03:13:31
On Sat, 2021-08-14 at 21:08 +0200, Vlastimil Babka wrote:
On 8/12/21 11:44 PM, Clark Williams wrote:
quoted
$ ./scripts/faddr2line /data/o/linux-5.14.y-rt/vmlinux ___slab_alloc+0x340/0x940
___slab_alloc+0x340/0x940:
PageSlabPfmemalloc at include/linux/page-flags.h:814
(inlined by) pfmemalloc_match at mm/slub.c:2772
(inlined by) ___slab_alloc at mm/slub.c:2874
Aha! That's helpful. Hopefully it's just a small issue where we
opportunistically test flags on a page that's protected by the local
lock we didn't take yet, and I didn't realize there's the VM_BUG_ON
which can trigger if our page went away (which we would have realized
after taking the lock).
So hopefully the below diff with uninspired naming should help?
I bet a nickle it does, shall let box slave away testing that theory
while its master pedals around the sunny Bavarian countryside.
-Mike
From: Mike Galbraith <hidden> Date: 2021-08-15 04:17:31
On Sat, 2021-08-14 at 21:08 +0200, Vlastimil Babka wrote:
Aha! That's helpful. Hopefully it's just a small issue where we
opportunistically test flags on a page that's protected by the local
lock we didn't take yet, and I didn't realize there's the VM_BUG_ON
which can trigger if our page went away (which we would have realized
after taking the lock).
Speaking of optimistic peeking perhaps going badly, why is the below
not true? There's protection against ->partial going disappearing
during a preemption... but can't it just as easily appear, so where is
that protection?
If the other side of that window is safe, it could use a comment so
dummies reading this code don't end up asking mm folks why the heck
they don't just take the darn lock and be done with it instead of tap
dancing all around thething :)
---
mm/slub.c | 14 ++++++--------
1 file changed, 6 insertions(+), 8 deletions(-)
--- a/mm/slub.c+++ b/mm/slub.c
@@ -2937,17 +2937,16 @@ static void *___slab_alloc(struct kmem_cnew_slab:+/*+*Toavoidfalsenegativeracewithput_cpu_partial()duringa+*preemption,wemustcallslub_percpu_partial()underlock.+*/+local_lock_irqsave(&s->cpu_slab->lock,flags);if(slub_percpu_partial(c)){-local_lock_irqsave(&s->cpu_slab->lock,flags);if(unlikely(c->page)){local_unlock_irqrestore(&s->cpu_slab->lock,flags);gotoreread_page;}-if(unlikely(!slub_percpu_partial(c))){-local_unlock_irqrestore(&s->cpu_slab->lock,flags);-/* we were preempted and partial list got empty */-gotonew_objects;-}page=c->page=slub_percpu_partial(c);slub_set_percpu_partial(c,page);
On Sat, 2021-08-14 at 21:08 +0200, Vlastimil Babka wrote:
quoted
Aha! That's helpful. Hopefully it's just a small issue where we
opportunistically test flags on a page that's protected by the local
lock we didn't take yet, and I didn't realize there's the VM_BUG_ON
which can trigger if our page went away (which we would have realized
after taking the lock).
Speaking of optimistic peeking perhaps going badly, why is the below
not true? There's protection against ->partial going disappearing
during a preemption... but can't it just as easily appear, so where is
that protection?
If it appears, it appears, we don't care, we just leave it there and
won't use it.
If the other side of that window is safe, it could use a comment so
dummies reading this code don't end up asking mm folks why the heck
they don't just take the darn lock and be done with it instead of tap
dancing all around thething :)
Well, with your patch, ->partial might appear just after the unlock, so
does that really change anything?
The point is to avoid the taking the lock if it's almost certain there
will be nothing to gain.
c->partial appearing is easy to just ignore. c->page appearing, while we
got our own page, is worse as there can be only one c->page. But it's
unavoidable, we can't just keep holding the local lock while going to
the page allocator etc. That's why under retry_load_page: we have to
deactivate a c->page that appeared under us...
@@ -2937,17 +2937,16 @@ static void *___slab_alloc(struct kmem_cnew_slab:+/*+*Toavoidfalsenegativeracewithput_cpu_partial()duringa+*preemption,wemustcallslub_percpu_partial()underlock.+*/+local_lock_irqsave(&s->cpu_slab->lock,flags);if(slub_percpu_partial(c)){-local_lock_irqsave(&s->cpu_slab->lock,flags);if(unlikely(c->page)){local_unlock_irqrestore(&s->cpu_slab->lock,flags);gotoreread_page;}-if(unlikely(!slub_percpu_partial(c))){-local_unlock_irqrestore(&s->cpu_slab->lock,flags);-/* we were preempted and partial list got empty */-gotonew_objects;-}page=c->page=slub_percpu_partial(c);slub_set_percpu_partial(c,page);
From: Mike Galbraith <hidden> Date: 2021-08-15 13:03:46
On Sun, 2021-08-15 at 11:35 +0200, Vlastimil Babka wrote:
On 8/15/21 6:17 AM, Mike Galbraith wrote:
quoted
On Sat, 2021-08-14 at 21:08 +0200, Vlastimil Babka wrote:
quoted
Aha! That's helpful. Hopefully it's just a small issue where we
opportunistically test flags on a page that's protected by the local
lock we didn't take yet, and I didn't realize there's the VM_BUG_ON
which can trigger if our page went away (which we would have realized
after taking the lock).
Speaking of optimistic peeking perhaps going badly, why is the below
not true? There's protection against ->partial going disappearing
during a preemption... but can't it just as easily appear, so where is
that protection?
If it appears, it appears, we don't care, we just leave it there and
won't use it.
quoted
If the other side of that window is safe, it could use a comment so
dummies reading this code don't end up asking mm folks why the heck
they don't just take the darn lock and be done with it instead of tap
dancing all around thething :)
Well, with your patch, ->partial might appear just after the unlock, so
does that really change anything?
Viewed from pov consumption is optional, it makes sense.
-Mike