4.11: oops in lookup_fast -> __d_lookup
From: Christian Borntraeger
Date: Tue May 16 2017 - 04:35:54 EST
Over night I had the following oops on my system (some KVM guests with memory pressure)
[10752.649057] Unable to handle kernel pointer dereference in virtual kernel address space
[10752.649062] Failing address: fffffffffffff000 TEID: fffffffffffff803
[10752.649063] Fault in home space mode while using kernel ASCE.
[10752.649066] AS:0000000000d3c007 R3:0000000125278007 S:0000000000000020
[10752.649173] Oops: 0038 ilc:3 [#1] SMP
[10752.649176] Modules linked in: xt_CHECKSUM iptable_mangle ipt_MASQUERADE nf_nat_masquerade_ipv4 iptable_nat nf_nat_ipv4 nf_nat nf_conntrack_ipv4 nf_defrag_ipv4 xt_conntrack nf_conntrack libcrc32c ipt_REJECT nf_reject_ipv4 bridge stp llc ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter btrfs raid6_pq xor dm_service_time crc32_vx_s390 ghash_s390 prng aes_s390 des_s390 des_generic sha512_s390 qeth_l2 sha256_s390 sha1_s390 sha_common eadm_sch qeth ccwgroup zcrypt_cex4 zcrypt vfio_ccw nfsd auth_rpcgss oid_registry nfs_acl lockd grace sch_fq_codel sunrpc vhost_net vhost tap dm_multipath ip_tables
[10752.649214] CPU: 29 PID: 32982 Comm: ps Not tainted 4.11.0+ #528
[10752.649215] Hardware name: IBM 2964 NC9 704 (LPAR)
[10752.649216] task: 000000008047da00 task.stack: 000000000141c000
[10752.649218] Krnl PSW : 0704d00180000000 00000000003482ee (__d_lookup+0x6e/0x180)
[10752.649227] R:0 T:1 IO:1 EX:1 Key:0 M:1 W:0 P:0 AS:3 CC:1 PM:0 RI:0 EA:3
[10752.649229] Krnl GPRS: 0000000000000000 000003e080622028 00000000b5d8b500 0000000000bbcf60
[10752.649231] 000000000141fd30 000000000141fd2c 000002aa000462e0 000000000141fdc8
[10752.649232] 0000000000000000 00000000b5d8b500 00000000c4405699 0000000000000000
[10752.649234] fffffffffffffffe 000000000082d450 000000000141fbd0 000000000141fb78
[10752.649266] Krnl Code: 00000000003482e2: b9040092 lgr %r9,%r2
00000000003482e6: a7880000 lhi %r8,0
#00000000003482ea: a7f40008 brc 15,3482fa
>00000000003482ee: e3c0c0000004 lg %r12,0(%r12)
00000000003482f4: ecc80021007c cgij %r12,0,8,348336
00000000003482fa: 59a0c01c c %r10,28(%r12)
00000000003482fe: a774fff8 brc 7,3482ee
0000000000348302: 41b0c050 la %r11,80(%r12)
[10752.649284] Call Trace:
[10752.649285] ([<0000000000000000>] (null))
[10752.649290] [<000000000033a234>] lookup_fast+0x20c/0x3e8
[10752.649292] [<000000000033b88e>] path_openat+0x22e/0x1268
[10752.649294] [<000000000033dd76>] do_filp_open+0x86/0x108
[10752.649298] [<00000000003286dc>] do_sys_open+0x174/0x250
[10752.649303] [<000000000080112c>] system_call+0xc4/0x24c
[10752.649304] Last Breaking-Event-Address:
[10752.649306] [<00000000003482fe>] __d_lookup+0x7e/0x180
[10752.649307]
[10752.649308] Kernel panic - not syncing: Fatal exception: panic_on_oops
It looks like it tries to dereference a pointer containing -ENOENT.
The process ps was spawned by ksmtuned.
Before that I had some memory allocation failures like the following. These happened
2500 seconds earlier and ksmtuned has probably called ps a lot of times, so I assume
it is not related.
Bad news is: I have seen this only once and I have no idea how to reproduce.
Good news: I have a kdump so I can certainly start digging deeper, I just do not know
where. Any idea?
[ 7534.137248] libvirtd: page allocation failure: order:0, mode:0x1200000(GFP_NOWAIT|__GFP_NOTRACK), nodemask=(null)
[ 7534.137255] libvirtd cpuset=/ mems_allowed=0
[ 7534.137259] CPU: 22 PID: 26735 Comm: libvirtd Not tainted 4.11.0+ #528
[ 7534.137260] Hardware name: IBM 2964 NC9 704 (LPAR)
[ 7534.137261] Stack:
[ 7534.137262] 000000001d243650 000000001d2436e0 0000000000000003 0000000000000000
[ 7534.137265] 000000001d243780 000000001d2436f8 000000001d2436f8 0000000000000020
[ 7534.137267] 0000000000000057 0000000100000020 000000000000000a 000000000000000a
[ 7534.137269] 000000000000000c 000000001d243748 0000000000000000 0000000000000000
[ 7534.137272] 00000000008278f8 00000000001130ac 000000001d2436e0 000000001d243738
[ 7534.137274] Call Trace:
[ 7534.137281] ([<0000000000112f62>] show_trace+0x62/0x78)
[ 7534.137284] [<0000000000113050>] show_stack+0x68/0xe0
[ 7534.137289] [<00000000004fba6e>] dump_stack+0x7e/0xb0
[ 7534.137292] [<0000000000299352>] warn_alloc+0xf2/0x190
[ 7534.137294] [<000000000029a34a>] __alloc_pages_nodemask+0xeda/0xfe0
[ 7534.137300] [<00000000002fa660>] alloc_pages_current+0xb8/0x170
[ 7534.137303] [<000000000030423e>] new_slab+0x366/0x6a0
[ 7534.137305] [<0000000000306a2e>] ___slab_alloc+0x4fe/0x5c8
[ 7534.137306] [<0000000000306b2c>] __slab_alloc+0x34/0x50
[ 7534.137308] [<0000000000306f7a>] kmem_cache_alloc_trace+0x1ea/0x258
[ 7534.137312] [<00000000003212a6>] memcg_kmem_get_cache+0xce/0x1a0
[ 7534.137313] [<0000000000306c56>] kmem_cache_alloc+0x10e/0x248
[ 7534.137338] [<000000000018d2f4>] prepare_creds+0x3c/0xf8
[ 7534.137339] [<000000000018d682>] prepare_exec_creds+0x2a/0x70
[ 7534.137342] [<00000000003335ce>] prepare_bprm_creds+0x4e/0x98
[ 7534.137343] [<0000000000333704>] do_execveat_common.isra.16+0xec/0x740
[ 7534.137345] [<0000000000333ff8>] SyS_execve+0x58/0x68
[ 7534.137349] [<000000000080112c>] system_call+0xc4/0x24c
[ 7534.137350] Mem-Info:
[ 7534.137354] active_anon:547705 inactive_anon:282612 isolated_anon:97
active_file:7926 inactive_file:6666 isolated_file:0
unevictable:2463 dirty:34 writeback:50645 unstable:0
slab_reclaimable:22926 slab_unreclaimable:72705
mapped:6104 shmem:170 pagetables:23204 bounce:0
free:8318 free_pcp:1350 free_cma:0
[ 7534.137363] Node 0 active_anon:2190820kB inactive_anon:1130448kB active_file:31704kB inactive_file:26664kB unevictable:9852kB isolated(anon):388kB isolated(file):0kB mapped:24416kB dirty:136kB writeback:202580kB shmem:680kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 3072kB writeback_tmp:0kB unstable:0kB pages_scanned:24 all_unreclaimable? no
[ 7534.137365] Node 0 DMA free:20492kB min:9656kB low:12068kB high:14480kB active_anon:1228540kB inactive_anon:615920kB active_file:16628kB inactive_file:14720kB unevictable:1056kB writepending:116368kB present:2097152kB managed:2084468kB mlocked:1056kB slab_reclaimable:35964kB slab_unreclaimable:103816kB kernel_stack:1856kB pagetables:34264kB bounce:0kB free_pcp:3008kB local_pcp:8kB free_cma:0kB
[ 7534.137370] lowmem_reserve[]: 0 2711 2711
[ 7534.137372] Node 0 Normal free:12780kB min:12868kB low:16084kB high:19300kB active_anon:961724kB inactive_anon:512740kB active_file:13604kB inactive_file:11524kB unevictable:8796kB writepending:86360kB present:3145728kB managed:2776300kB mlocked:8796kB slab_reclaimable:55740kB slab_unreclaimable:187004kB kernel_stack:12992kB pagetables:58552kB bounce:0kB free_pcp:2392kB local_pcp:0kB free_cma:0kB
[ 7534.137377] lowmem_reserve[]: 0 0 0
[ 7534.137378] Node 0 DMA: 5*4kB (UME) 4*8kB (UE) 18*16kB (UEH) 19*32kB (MH) 283*64kB (UMEH) 14*128kB (MH) 2*256kB (H) 0*512kB 0*1024kB = 21364kB
[ 7534.137384] Node 0 Normal: 535*4kB (UEH) 912*8kB (UMEH) 205*16kB (UMEH) 27*32kB (MH) 6*64kB (M) 1*128kB (H) 0*256kB 0*512kB 0*1024kB = 14092kB
[ 7534.137389] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1024kB
[ 7534.137390] 76821 total pagecache pages
[ 7534.137773] 60542 pages in swap cache
[ 7534.137774] Swap cache stats: add 594098548, delete 593784235, find 364251852/418810125
[ 7534.137775] Free swap = 1089481760kB
[ 7534.137776] Total swap = 1092514336kB
[ 7534.137777] 1310720 pages RAM
[ 7534.137777] 0 pages HighMem/MovableOnly
[ 7534.137778] 95528 pages reserved
[ 7534.137780] SLUB: Unable to allocate memory on node -1, gfp=0x1000000(GFP_NOWAIT)
[ 7534.137781] cache: kmalloc-64, object size: 64, buffer size: 64, default order: 0, min order: 0
[ 7534.137782] node 0: slabs: 1945, objs: 124480, free: 0
[ 7534.137789] libvirtd: page allocation failure: order:0, mode:0x1200000(GFP_NOWAIT|__GFP_NOTRACK), nodemask=(null)
[ 7534.137792] libvirtd cpuset=/ mems_allowed=0
[ 7534.137794] CPU: 22 PID: 26735 Comm: libvirtd Not tainted 4.11.0+ #528
[ 7534.137795] Hardware name: IBM 2964 NC9 704 (LPAR)
[ 7534.137796] Stack:
[ 7534.137796] 000000001d2436c0 000000001d243750 0000000000000003 0000000000000000
[ 7534.137798] 000000001d2437f0 000000001d243768 000000001d243768 0000000000000020
[ 7534.137800] 0000000000000057 0000000100000020 000000000000000a 000000000000000a
[ 7534.137802] 000000000000000c 000000001d2437b8 0000000000000000 0000000000000000
[ 7534.137803] 00000000008278f8 00000000001130ac 000000001d243750 000000001d2437a8
[ 7534.137805] Call Trace:
[ 7534.137807] ([<0000000000112f62>] show_trace+0x62/0x78)
[ 7534.137808] [<0000000000113050>] show_stack+0x68/0xe0
[ 7534.137810] [<00000000004fba6e>] dump_stack+0x7e/0xb0
[ 7534.137811] [<0000000000299352>] warn_alloc+0xf2/0x190
[ 7534.137813] [<000000000029a34a>] __alloc_pages_nodemask+0xeda/0xfe0
[ 7534.137815] [<00000000002fa660>] alloc_pages_current+0xb8/0x170
[ 7534.137816] [<000000000030423e>] new_slab+0x366/0x6a0
[ 7534.137818] [<0000000000306a2e>] ___slab_alloc+0x4fe/0x5c8
[ 7534.137819] [<0000000000306b2c>] __slab_alloc+0x34/0x50
[ 7534.137821] [<0000000000306f7a>] kmem_cache_alloc_trace+0x1ea/0x258
[ 7534.137822] [<00000000003212a6>] memcg_kmem_get_cache+0xce/0x1a0
[ 7534.137824] [<0000000000306c56>] kmem_cache_alloc+0x10e/0x248
[ 7534.137828] [<000000000016283e>] mm_alloc+0x36/0x80
[ 7534.137830] [<00000000003338a6>] do_execveat_common.isra.16+0x28e/0x740
[ 7534.137831] [<0000000000333ff8>] SyS_execve+0x58/0x68
[ 7534.137833] [<000000000080112c>] system_call+0xc4/0x24c
[ 7534.137834] SLUB: Unable to allocate memory on node -1, gfp=0x1000000(GFP_NOWAIT)
[ 7534.137835] cache: kmalloc-64, object size: 64, buffer size: 64, default order: 0, min order: 0
[ 7534.137836] node 0: slabs: 1945, objs: 124480, free: 0