xfs trace in 4.4.2 / also in 4.3.3 WARNING fs/xfs/xfs_aops.c:1232 xfs_vm_releasepage
Stefan Priebe
s.priebe at profihost.ag
Sun Jun 26 00:45:11 CDT 2016
Hi Dave,
today i got this XFS trace while running 4.4.13. I'm not sure if it is
related.
[282732.262739] ------------[ cut here ]------------
[282732.264093] kernel BUG at fs/xfs/xfs_aops.c:1054!
[282732.265459] invalid opcode: 0000 [#1] SMP
[282732.266753] Modules linked in: netconsole xt_multiport
iptable_filter ip_tables x_tables bonding coretemp 8021q garp fuse
sb_edac edac_core xhci_pci i40e(O) xhci_hcd i2c_i801 vxlan shpchp
ip6_udp_tunnel udp_tunnel ipmi_si ipmi_msghandler button btrfs xor
raid6_pq dm_mod raid1 md_mod usbhid usb_storage ohci_hcd sg sd_mod
ehci_pci ehci_hcd usbcore usb_common ahci libahci igb i2c_algo_bit
mpt3sas i2c_core raid_class ptp pps_core scsi_transport_sas
[282732.280494] CPU: 2 PID: 108 Comm: kswapd0 Tainted: G O
4.4.13+36-ph #1
[282732.282707] Hardware name: Supermicro Super Server/X10SRH-CF, BIOS
2.0 12/17/2015
[282732.284873] task: ffff880c4d9ba500 ti: ffff880c4da28000 task.ti:
ffff880c4da28000
[282732.287038] RIP: 0010:[<ffffffff943267f1>] [<ffffffff943267f1>]
xfs_vm_writepage+0x561/0x5c0
[282732.289554] RSP: 0018:ffff880c4da2b8e8 EFLAGS: 00010246
[282732.291095] RAX: 001fffff80020009 RBX: ffffea000186de80 RCX:
000000000000000c
[282732.293161] RDX: 0000000000001800 RSI: ffff880c4da2b9b8 RDI:
ffffea000186de80
[282732.295255] RBP: ffff880c4da2b9a8 R08: 0000000000000003 R09:
7fffffffffffffff
[282732.297340] R10: ffff880c7ffdc6c0 R11: 0000000000000000 R12:
ffffea000186de80
[282732.299405] R13: ffff88001ea855d0 R14: ffff880c4da2bad8 R15:
ffffea000186dea0
[282732.301472] FS: 0000000000000000(0000) GS:ffff880c7fc40000(0000)
knlGS:0000000000000000
[282732.303811] CS: 0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[282732.305480] CR2: ffffffffff600400 CR3: 0000000014c0a000 CR4:
00000000001406e0
[282732.307545] Stack:
[282732.308142] ffff8806c1e980e0 ffff880c442dc800 ffff880100000001
0000000100042000
[282732.310482] ffffea00016db240 ffff880c4da2b968 0000000001800000
ffff880c4da2b9b8
[282732.312822] 0000000000001000 0000000000297000 0000000000000000
0000000000000246
[282732.315161] Call Trace:
[282732.315890] [<ffffffff9415c72e>] ? clear_page_dirty_for_io+0xee/0x1b0
[282732.317782] [<ffffffff94163974>] pageout.isra.43+0x164/0x280
[282732.319449] [<ffffffff94165f4a>] shrink_page_list+0x5ba/0x760
[282732.321143] [<ffffffff941667ce>] shrink_inactive_list+0x1ee/0x500
[282732.322934] [<ffffffff941674e1>] shrink_lruvec+0x621/0x7d0
[282732.324554] [<ffffffff9416776c>] shrink_zone+0xdc/0x2c0
[282732.326096] [<ffffffff941688b9>] kswapd+0x4f9/0x970
[282732.327541] [<ffffffff941683c0>] ?
mem_cgroup_shrink_node_zone+0x1a0/0x1a0
[282732.329561] [<ffffffff940a0dc9>] kthread+0xc9/0xe0
[282732.330979] [<ffffffff940a0d00>] ? kthread_stop+0x100/0x100
[282732.332623] [<ffffffff946b470f>] ret_from_fork+0x3f/0x70
[282732.334191] [<ffffffff940a0d00>] ? kthread_stop+0x100/0x100
[282732.404901] Code: f8 f5 74 a3 4c 89 e7 89 85 50 ff ff ff e8 38 e8 ff
ff f0 41 80 24 24 f7 4c 89 e7 e8 3a bf e2 ff 8b 85 50 ff ff ff e9 39 fd
ff ff <0f> 0b 80 3d 04 fc 9c 00 00 0f 85 6d ff ff ff be d6 03 00 00 48
[282732.556398] RIP [<ffffffff943267f1>] xfs_vm_writepage+0x561/0x5c0
[282732.630207] RSP <ffff880c4da2b8e8>
[282732.703062] ---[ end trace 9ea1afce9e126cdc ]---
[282732.842462] ------------[ cut here ]------------
[282732.914729] WARNING: CPU: 2 PID: 108 at kernel/exit.c:661
do_exit+0x50/0xab0()
[282732.989039] Modules linked in: netconsole xt_multiport
iptable_filter ip_tables x_tables bonding coretemp 8021q garp fuse
sb_edac edac_core xhci_pci i40e(O) xhci_hcd i2c_i801 vxlan shpchp
ip6_udp_tunnel udp_tunnel ipmi_si ipmi_msghandler button btrfs xor
raid6_pq dm_mod raid1 md_mod usbhid usb_storage ohci_hcd sg sd_mod
ehci_pci ehci_hcd usbcore usb_common ahci libahci igb i2c_algo_bit
mpt3sas i2c_core raid_class ptp pps_core scsi_transport_sas
[282733.306619] CPU: 2 PID: 108 Comm: kswapd0 Tainted: G D O
4.4.13+36-ph #1
[282733.386805] Hardware name: Supermicro Super Server/X10SRH-CF, BIOS
2.0 12/17/2015
[282733.467585] 0000000000000000 ffff880c4da2b5d8 ffffffff943c60ff
0000000000000000
[282733.547861] ffffffff94a330a8 ffff880c4da2b618 ffffffff940837a7
ffff880c4da2b838
[282733.626144] 000000000000000b ffff880c4da2b838 0000000000000246
ffff880c4d9ba500
[282733.702723] Call Trace:
[282733.776298] [<ffffffff943c60ff>] dump_stack+0x63/0x84
[282733.849877] [<ffffffff940837a7>] warn_slowpath_common+0x97/0xe0
[282733.922917] [<ffffffff9408380a>] warn_slowpath_null+0x1a/0x20
[282733.994640] [<ffffffff94085a90>] do_exit+0x50/0xab0
[282734.064858] [<ffffffff94008a02>] oops_end+0xa2/0xe0
[282734.133974] [<ffffffff94008b88>] die+0x58/0x80
[282734.202270] [<ffffffff94005ba9>] do_trap+0x69/0x150
[282734.269913] [<ffffffff940a1bc2>] ?
__atomic_notifier_call_chain+0x12/0x20
[282734.337974] [<ffffffff94005d5d>] do_error_trap+0xcd/0xf0
[282734.406008] [<ffffffff943267f1>] ? xfs_vm_writepage+0x561/0x5c0
[282734.474472] [<ffffffff9439c334>] ? generic_make_request+0x104/0x190
[282734.542216] [<ffffffff94006000>] do_invalid_op+0x20/0x30
[282734.609276] [<ffffffff946b5e8e>] invalid_op+0x1e/0x30
[282734.675516] [<ffffffff943267f1>] ? xfs_vm_writepage+0x561/0x5c0
[282734.741307] [<ffffffff94326528>] ? xfs_vm_writepage+0x298/0x5c0
[282734.805722] [<ffffffff9415c72e>] ? clear_page_dirty_for_io+0xee/0x1b0
[282734.870589] [<ffffffff94163974>] pageout.isra.43+0x164/0x280
[282734.934901] [<ffffffff94165f4a>] shrink_page_list+0x5ba/0x760
[282734.998565] [<ffffffff941667ce>] shrink_inactive_list+0x1ee/0x500
[282735.061845] [<ffffffff941674e1>] shrink_lruvec+0x621/0x7d0
[282735.124441] [<ffffffff9416776c>] shrink_zone+0xdc/0x2c0
[282735.186752] [<ffffffff941688b9>] kswapd+0x4f9/0x970
[282735.249021] [<ffffffff941683c0>] ?
mem_cgroup_shrink_node_zone+0x1a0/0x1a0
[282735.312215] [<ffffffff940a0dc9>] kthread+0xc9/0xe0
[282735.375420] [<ffffffff940a0d00>] ? kthread_stop+0x100/0x100
[282735.439012] [<ffffffff946b470f>] ret_from_fork+0x3f/0x70
[282735.502368] [<ffffffff940a0d00>] ? kthread_stop+0x100/0x100
[282735.565534] ---[ end trace 9ea1afce9e126cdd ]---
Stefan
Am 03.06.2016 um 19:56 schrieb Stefan Priebe - Profihost AG:
> Hi,
>
> should i remove the complete if conditions incl. the return 0 or should
> id convert it to if without WARN_ONCE? like below?
>
> if (WARN_ON_ONCE(delalloc))
> return 0;
> if (WARN_ON_ONCE(unwritten))
> return 0;
>
> =>
>
> if (delalloc)
> return 0;
> if (unwritten)
> return 0;
>
>
>
> Am 22.05.2016 um 23:38 schrieb Dave Chinner:
>> On Sun, May 22, 2016 at 09:36:39PM +0200, Stefan Priebe - Profihost AG wrote:
>>> Am 16.05.2016 um 03:06 schrieb Brian Foster:
>>>>> sd_mod ehci_pci ehci_hcd usbcore usb_common igb ahci i2c_algo_bit libahci
>>>>> i2c_core ptp mpt3sas pps_core raid_class scsi_transport_sas
>>>>> [Sun May 15 07:00:44 2016] CPU: 2 PID: 108 Comm: kswapd0 Tainted: G O
>>>>> 4.4.10+25-ph #1
>>>>
>>>> How close is this to an upstream kernel? Upstream XFS? Have you tried to
>>>> reproduce this on an upstream kernel?
>>>
>>> It's a vanilla 4.4.10 + a new adaptec driver and some sched and wq
>>> patches from 4.5 and 4.6 but i can try to replace the kernel on one
>>> machine with a 100% vanilla one if this helps.
>>
>> Please do.
>>
>>>>> [295086.353473] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0x52000 size 0x13d1c8
>>>>> [295086.353476] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0x53000 size 0x13d1c8
>>>>> [295086.353478] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0x54000 size 0x13d1c8
>>>> ...
>>>>> [295086.567508] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0xab000 size 0x13d1c8
>>>>> [295086.567510] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0xac000 size 0x13d1c8
>>>>> [295086.567515] XFS (md127p3): ino 0x600204f delalloc 1 unwritten 0 pgoff
>>>>> 0xad000 size 0x13d1c8
>>>>>
>>>>> The file to the inode number is:
>>>>> /var/lib/apt/lists/security.debian.org_dists_wheezy_updates_main_i18n_Translation-en
>>>>>
>>>>
>>>> xfs_bmap -v might be interesting here as well.
>>>
>>> # xfs_bmap -v
>>> /var/lib/apt/lists/security.debian.org_dists_wheezy_updates_main_i18n_Translation-en
>>> /var/lib/apt/lists/security.debian.org_dists_wheezy_updates_main_i18n_Translation-en:
>>> EXT: FILE-OFFSET BLOCK-RANGE AG AG-OFFSET TOTAL
>>> 0: [0..2567]: 41268928..41271495 3 (374464..377031) 2568
>>
>> So the last file offset with a block is 0x140e00. This means the
>> file is fully allocated. However, the pages inside the file range
>> are still marked delayed allocation. That implies that we've failed
>> to write the pages over a delayed allocation region after we've
>> allocated the space.
>>
>> That, in turn, tends to indicate a problem in page writeback - the
>> first page to be written has triggered delayed allocation of the
>> entire range, but then the subsequent pages have not been written
>> (for some as yet unknown reason). When a page is written, we map it
>> to the current block via xfs_map_at_offset(), and that clears both
>> the buffer delay and unwritten flags.
>>
>> This clearly isn't happening which means either the VFS doesn't
>> think the inode is dirty anymore, writeback is never asking for
>> these pages to be written, or XFs is screwing something up in
>> ->writepage. The XFS writepage code changed significantly in 4.6, so
>> it might be worth seeing if a 4.6 kernel reproduces this same
>> problem....
>>
>> Cheers,
>>
>> Dave.
>>
More information about the xfs
mailing list