[BUG] xfs/109 crashed 2k block size reflink enabled XFS

[BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Eryu Guan]

Hi,

I hit an xfs/109 crash today while testing reflink XFS with 2k block
size on x86_64 hosts (both baremetal and kvm guest).

It can be reproduced by running xfs/109 many times, I tried 50-times
loop twice and it crashed at the 21st and 46th runs. And I can reproduce
it with both linus tree (4.9-rc4) and linux-xfs tree for-next branch
(updated on 2016-11-30). I haven't been able to reproduce it with 4k
block size XFS.

Detailed host info and crash log are appended at the end of this mail.

Thanks,
Eryu

fstests config:
TEST_DEV=/dev/mapper/testvg-testlv1
TEST_DIR=/mnt/testarea/test
SCRATCH_DEV=/dev/mapper/testvg-testlv2
SCRATCH_MNT=/mnt/testarea/scratch
MKFS_OPTIONS="-f -b size=2k -m reflink=1,rmapbt=1"

[root@ibm-x3550m3-05 ~]# xfs_info /mnt/testarea/scratch/
meta-data=/dev/mapper/testvg-testlv2 isize=512    agcount=4, agsize=20480 blks
         =                       sectsz=512   attr=2, projid32bit=1
         =                       crc=1        finobt=1 spinodes=0 rmapbt=1
         =                       reflink=1
data     =                       bsize=2048   blocks=81920, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal               bsize=2048   blocks=4608, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0
[root@ibm-x3550m3-05 ~]# free -m
              total        used        free      shared  buff/cache   available
Mem:           7937         127        7482           8         326        7478
Swap:          8191           0        8191
[root@ibm-x3550m3-05 xfstests]# lscpu
Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                8
On-line CPU(s) list:   0,1,4-6,9-11
Thread(s) per core:    1
Core(s) per socket:    4
Socket(s):             2
NUMA node(s):          2
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 44
Model name:            Intel(R) Xeon(R) CPU           E5606  @ 2.13GHz
Stepping:              2
CPU MHz:               2128.000
BogoMIPS:              4266.55
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              8192K
NUMA node0 CPU(s):     0,1,4,5
NUMA node1 CPU(s):     6,9-11
[root@ibm-x3550m3-05 ~]# lvs
  LV      VG       Attr       LSize   Pool Origin Data%  Meta%  Move Log Cpy%Sync Convert
  root    systemvg -wi-ao---- 771.25g                                                    
  swap    systemvg -wi-ao----   8.00g                                                    
  lv50g   testvg   -wi-a-----  50.00g                                                    
  testlv1 testvg   -wi-a-----  15.00g                                                    
  testlv2 testvg   -wi-ao----  15.00g                                                    
  testlv3 testvg   -wi-a-----  15.00g                                                    
  testlv4 testvg   -wi-a-----  15.00g                                                    
  testlv5 testvg   -wi-a-----  15.00g                                                    
[root@ibm-x3550m3-05 ~]# vgs
  VG       #PV #LV #SN Attr   VSize   VFree  
  systemvg   1   2   0 wz--n- 779.25g      0 
  testvg     1   6   0 wz--n- 878.90g 753.90g
[root@ibm-x3550m3-05 ~]# pvs
  PV         VG       Fmt  Attr PSize   PFree  
  /dev/sda2  systemvg lvm2 a--  779.25g      0 
  /dev/sdb1  testvg   lvm2 a--  878.90g 753.90g

[419012.731523] run fstests xfs/109 at 2016-12-05 14:01:26
[419013.066939] XFS (dm-4): Unmounting Filesystem
[419013.089131] XFS (dm-4): EXPERIMENTAL reverse mapping btree feature enabled. Use at your own risk!
[419013.098098] XFS (dm-4): EXPERIMENTAL reflink feature enabled. Use at your own risk!
[419013.106264] XFS (dm-4): Mounting V5 Filesystem
[419013.136734] XFS (dm-4): Ending clean mount
[419013.163906] XFS (dm-4): Unmounting Filesystem
[419013.295657] XFS (dm-4): EXPERIMENTAL reverse mapping btree feature enabled. Use at your own risk!
[419013.304635] XFS (dm-4): EXPERIMENTAL reflink feature enabled. Use at your own risk!
[419013.312666] XFS (dm-4): Mounting V5 Filesystem
[419013.357736] XFS (dm-4): Ending clean mount
[419019.581319] XFS (dm-4): Unmounting Filesystem
[419019.635144] XFS (dm-4): EXPERIMENTAL reverse mapping btree feature enabled. Use at your own risk!
[419019.644118] XFS (dm-4): EXPERIMENTAL reflink feature enabled. Use at your own risk!
[419019.652521] XFS (dm-4): Mounting V5 Filesystem
[419019.859615] XFS (dm-4): Ending clean mount
[419021.380595] XFS (dm-4): _xfs_buf_find: Block out of range: block 0x140000000bffc, EOFS 0x50000
[419021.389457] ------------[ cut here ]------------
[419021.394243] WARNING: CPU: 9 PID: 4984 at fs/xfs/xfs_buf.c:520 _xfs_buf_find+0x2d5/0x340 [xfs]
[419021.402917] Modules linked in:[419021.405962]  xfs overlay arc4 md4 nls_utf8 cifs rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache dm_delay dm_zero btrfs xor raid6_pq dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio loop dm_flakey libcrc32c ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ipmi_ssif ghash_clmulni_intel cdc_ether usbnet aesni_intel lrw gf128mul glue_helper iTCO_wdt iTCO_vendor_support ipmi_devintf mii ablk_helper i2c_i801 cryptd i2c_smbus lpc_ich pcspkr ipmi_si nfsd sg i7core_edac ipmi_msghandler ioatdma edac_core shpchp dca acpi_cpufreq auth_rpcgss nfs_acl lockd grace sunrpc ip_tables ext4 jbd2 mbcache sr_mod sd_mod cdrom mgag200 i2c_algo_bit drm_kms_helper syscopyarea ata_generic sysfillrect pata_acpi sysimgblt fb_sys_fops ttm ata_piix crc32c_intel drm libata serio_raw megaraid_sas i2c_core bnx2 fjes dm_mirror dm_region_hash dm_log dm_mod [last unloaded: xfs]
[419021.527826] CPU: 9 PID: 4984 Comm: kworker/u50:2 Tainted: G        W  OE   4.9.0-rc1.xfs+ #7
[419021.536341] Hardware name: IBM System x3550 M3 -[7944OEJ]-/90Y4784     , BIOS -[D6E150CUS-1.11]- 02/08/2011
[419021.546164] Workqueue: writeback wb_workfn (flush-253:4)
[419021.551594]  ffffc90007b2b300 ffffffff81363bec 0000000000000000 0000000000000000
[419021.559148]  ffffc90007b2b340 ffffffff8108f201 0000020807b2b320 ffffc90007b2b430
[419021.566701]  0000000000000004 ffff880275e7ad80 0000000000000000 0000000000000001
[419021.574255] Call Trace:
[419021.576797]  [<ffffffff81363bec>] dump_stack+0x63/0x87
[419021.582022]  [<ffffffff8108f201>] __warn+0xd1/0xf0
[419021.586896]  [<ffffffff8108f33d>] warn_slowpath_null+0x1d/0x20
[419021.592840]  [<ffffffffa0be7bd5>] _xfs_buf_find+0x2d5/0x340 [xfs]
[419021.599015]  [<ffffffff81369f64>] ? __radix_tree_lookup+0x84/0xf0
[419021.605219]  [<ffffffffa0be7c6a>] xfs_buf_get_map+0x2a/0x280 [xfs]
[419021.611481]  [<ffffffff8136a02d>] ? radix_tree_lookup+0xd/0x10
[419021.617429]  [<ffffffffa0c1bf96>] xfs_trans_get_buf_map+0x116/0x190 [xfs]
[419021.624323]  [<ffffffffa0bb46d4>] xfs_btree_get_bufl+0x74/0x90 [xfs]
[419021.630783]  [<ffffffffa0ba4924>] xfs_bmap_extents_to_btree+0x254/0x630 [xfs]
[419021.638018]  [<ffffffffa0b999fc>] ? xfs_alloc_update_counters.isra.17+0x3c/0x50 [xfs]
[419021.645951]  [<ffffffffa0baaac2>] xfs_bmap_add_extent_delay_real+0x1b42/0x2090 [xfs]
[419021.653797]  [<ffffffffa0baed3b>] xfs_bmapi_write+0x78b/0xba0 [xfs]
[419021.660176]  [<ffffffffa0bf71a6>] xfs_iomap_write_allocate+0x196/0x3a0 [xfs]
[419021.667334]  [<ffffffffa0be09fb>] xfs_map_blocks+0x1eb/0x260 [xfs]
[419021.673624]  [<ffffffffa0be1abc>] xfs_do_writepage+0x1cc/0x6e0 [xfs]
[419021.680061]  [<ffffffff811ad8df>] write_cache_pages+0x26f/0x510
[419021.686067]  [<ffffffff81339daa>] ? blk_queue_bio+0x17a/0x3a0
[419021.691925]  [<ffffffffa0be18f0>] ? xfs_vm_writepages+0xe0/0xe0 [xfs]
[419021.698476]  [<ffffffffa0be18c6>] xfs_vm_writepages+0xb6/0xe0 [xfs]
[419021.704826]  [<ffffffff811ae8fe>] do_writepages+0x1e/0x30
[419021.710310]  [<ffffffff81260795>] __writeback_single_inode+0x45/0x330
[419021.716834]  [<ffffffff81260fd0>] writeback_sb_inodes+0x280/0x570
[419021.723011]  [<ffffffff8126148f>] wb_writeback+0x10f/0x320
[419021.728578]  [<ffffffff81261e29>] wb_workfn+0x109/0x3f0
[419021.733890]  [<ffffffff810a8be2>] process_one_work+0x152/0x400
[419021.739803]  [<ffffffff810a94d5>] worker_thread+0x125/0x4b0
[419021.745460]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419021.751202]  [<ffffffff810a93b0>] ? rescuer_thread+0x380/0x380
[419021.757116]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419021.762859]  [<ffffffff810af039>] kthread+0xd9/0xf0
[419021.767822]  [<ffffffff810aef60>] ? kthread_park+0x60/0x60
[419021.773394]  [<ffffffff8170ff95>] ret_from_fork+0x25/0x30
[419021.778947] ---[ end trace 5fae8d49ab722482 ]---
[419021.783787] XFS (dm-4): _xfs_buf_find: Block out of range: block 0x140000000bffc, EOFS 0x50000
[419021.792583] ------------[ cut here ]------------
[419021.797372] WARNING: CPU: 11 PID: 4984 at fs/xfs/xfs_buf.c:520 _xfs_buf_find+0x2d5/0x340 [xfs]
[419021.806064] Modules linked in:[419021.809097]  xfs overlay arc4 md4 nls_utf8 cifs rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache dm_delay dm_zero btrfs xor raid6_pq dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio loop dm_flakey libcrc32c ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ipmi_ssif ghash_clmulni_intel cdc_ether usbnet aesni_intel lrw gf128mul glue_helper iTCO_wdt iTCO_vendor_support ipmi_devintf mii ablk_helper i2c_i801 cryptd i2c_smbus lpc_ich pcspkr ipmi_si nfsd sg i7core_edac ipmi_msghandler ioatdma edac_core shpchp dca acpi_cpufreq auth_rpcgss nfs_acl lockd grace sunrpc ip_tables ext4 jbd2 mbcache sr_mod sd_mod cdrom mgag200 i2c_algo_bit drm_kms_helper syscopyarea ata_generic sysfillrect pata_acpi sysimgblt fb_sys_fops ttm ata_piix crc32c_intel drm libata serio_raw megaraid_sas i2c_core bnx2 fjes dm_mirror dm_region_hash dm_log dm_mod [last unloaded: xfs]
[419021.930296] CPU: 11 PID: 4984 Comm: kworker/u50:2 Tainted: G        W  OE   4.9.0-rc1.xfs+ #7
[419021.938899] Hardware name: IBM System x3550 M3 -[7944OEJ]-/90Y4784     , BIOS -[D6E150CUS-1.11]- 02/08/2011
[419021.948718] Workqueue: writeback wb_workfn (flush-253:4)
[419021.954147]  ffffc90007b2b300 ffffffff81363bec 0000000000000000 0000000000000000
[419021.961701]  ffffc90007b2b340 ffffffff8108f201 0000020807b2b320 ffffc90007b2b430
[419021.969254]  0000000000000004 ffff880275e7ad80 0000000000000000 0000000000000001
[419021.976807] Call Trace:
[419021.979346]  [<ffffffff81363bec>] dump_stack+0x63/0x87
[419021.984567]  [<ffffffff8108f201>] __warn+0xd1/0xf0
[419021.989444]  [<ffffffff8108f33d>] warn_slowpath_null+0x1d/0x20
[419021.995387]  [<ffffffffa0be7bd5>] _xfs_buf_find+0x2d5/0x340 [xfs]
[419022.001593]  [<ffffffffa0be7e42>] xfs_buf_get_map+0x202/0x280 [xfs]
[419022.007973]  [<ffffffffa0c1bf96>] xfs_trans_get_buf_map+0x116/0x190 [xfs]
[419022.014864]  [<ffffffffa0bb46d4>] xfs_btree_get_bufl+0x74/0x90 [xfs]
[419022.021320]  [<ffffffffa0ba4924>] xfs_bmap_extents_to_btree+0x254/0x630 [xfs]
[419022.028555]  [<ffffffffa0b999fc>] ? xfs_alloc_update_counters.isra.17+0x3c/0x50 [xfs]
[419022.036488]  [<ffffffffa0baaac2>] xfs_bmap_add_extent_delay_real+0x1b42/0x2090 [xfs]
[419022.044335]  [<ffffffffa0baed3b>] xfs_bmapi_write+0x78b/0xba0 [xfs]
[419022.050714]  [<ffffffffa0bf71a6>] xfs_iomap_write_allocate+0x196/0x3a0 [xfs]
[419022.057870]  [<ffffffffa0be09fb>] xfs_map_blocks+0x1eb/0x260 [xfs]
[419022.064158]  [<ffffffffa0be1abc>] xfs_do_writepage+0x1cc/0x6e0 [xfs]
[419022.070593]  [<ffffffff811ad8df>] write_cache_pages+0x26f/0x510
[419022.076596]  [<ffffffff81339daa>] ? blk_queue_bio+0x17a/0x3a0
[419022.082454]  [<ffffffffa0be18f0>] ? xfs_vm_writepages+0xe0/0xe0 [xfs]
[419022.089005]  [<ffffffffa0be18c6>] xfs_vm_writepages+0xb6/0xe0 [xfs]
[419022.095356]  [<ffffffff811ae8fe>] do_writepages+0x1e/0x30
[419022.100839]  [<ffffffff81260795>] __writeback_single_inode+0x45/0x330
[419022.107362]  [<ffffffff81260fd0>] writeback_sb_inodes+0x280/0x570
[419022.113538]  [<ffffffff8126148f>] wb_writeback+0x10f/0x320
[419022.119107]  [<ffffffff81261e29>] wb_workfn+0x109/0x3f0
[419022.124414]  [<ffffffff810a8be2>] process_one_work+0x152/0x400
[419022.130328]  [<ffffffff810a94d5>] worker_thread+0x125/0x4b0
[419022.135984]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419022.141725]  [<ffffffff810a93b0>] ? rescuer_thread+0x380/0x380
[419022.147639]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419022.153380]  [<ffffffff810af039>] kthread+0xd9/0xf0
[419022.158344]  [<ffffffff810aef60>] ? kthread_park+0x60/0x60
[419022.163911]  [<ffffffff8170ff95>] ret_from_fork+0x25/0x30
[419022.169463] ---[ end trace 5fae8d49ab722483 ]---
[419022.174174] BUG: unable to handle kernel NULL pointer dereference at 0000000000000168
[419022.182119] IP: [<ffffffffa0ba492b>] xfs_bmap_extents_to_btree+0x25b/0x630 [xfs]
[419022.189640] PGD 0 [419022.191565]
[419022.193159] Oops: 0002 [#1] SMP
[419022.196388] Modules linked in: xfs overlay arc4 md4 nls_utf8 cifs rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache dm_delay dm_zero btrfs xor raid6_pq dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio loop dm_flakey libcrc32c ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ipmi_ssif ghash_clmulni_intel cdc_ether usbnet aesni_intel lrw gf128mul glue_helper iTCO_wdt iTCO_vendor_support ipmi_devintf mii ablk_helper i2c_i801 cryptd i2c_smbus lpc_ich pcspkr ipmi_si nfsd sg i7core_edac ipmi_msghandler ioatdma edac_core shpchp dca acpi_cpufreq auth_rpcgss nfs_acl lockd grace sunrpc ip_tables ext4 jbd2 mbcache sr_mod sd_mod cdrom mgag200 i2c_algo_bit drm_kms_helper syscopyarea ata_generic sysfillrect pata_acpi sysimgblt fb_sys_fops ttm ata_piix crc32c_intel drm libata serio_raw megaraid_sas i2c_core bnx2 fjes dm_mirror dm_region_hash dm_log dm_mod [last unloaded: xfs]
[419022.316408] CPU: 11 PID: 4984 Comm: kworker/u50:2 Tainted: G        W  OE   4.9.0-rc1.xfs+ #7
[419022.325010] Hardware name: IBM System x3550 M3 -[7944OEJ]-/90Y4784     , BIOS -[D6E150CUS-1.11]- 02/08/2011
[419022.334827] Workqueue: writeback wb_workfn (flush-253:4)
[419022.340255] task: ffff88019d90ab00 task.stack: ffffc90007b28000
[419022.346257] RIP: 0010:[<ffffffffa0ba492b>]  [<ffffffffa0ba492b>] xfs_bmap_extents_to_btree+0x25b/0x630 [xfs]
[419022.356205] RSP: 0018:ffffc90007b2b458  EFLAGS: 00010246
[419022.361599] RAX: 0000000000000000 RBX: ffff880262a31138 RCX: 0000000000cd045a
[419022.368814] RDX: 0000000000cd0459 RSI: 0000000000000000 RDI: ffff8801ff820140
[419022.376026] RBP: ffffc90007b2b578 R08: 000000000001d200 R09: ffffffffa0be6f46
[419022.383242] R10: ffff88027fb5d200 R11: ffffea0009dc5c00 R12: ffff8802502596c8
[419022.390457] R13: ffff880178487000 R14: 0000000000000001 R15: ffff880250259680
[419022.397674] FS:  0000000000000000(0000) GS:ffff88027fb40000(0000) knlGS:0000000000000000
[419022.405841] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[419022.411670] CR2: 0000000000000168 CR3: 0000000001c06000 CR4: 00000000000006e0
[419022.418886] Stack:
[419022.420986]  0000000000000050 0000000000000009 ffffffffa0b999fc 0000000000000000
[419022.428538]  ffffc90007b2b798 ffffc90007b2b5e8 ffff8801ff34ce80 ffffc90007b2b878
[419022.436091]  ffff880276233ea0 ffff880262a31138 ffff880262a31138 ffff880178487000
[419022.443644] Call Trace:
[419022.446202]  [<ffffffffa0b999fc>] ? xfs_alloc_update_counters.isra.17+0x3c/0x50 [xfs]
[419022.454136]  [<ffffffffa0baaac2>] xfs_bmap_add_extent_delay_real+0x1b42/0x2090 [xfs]
[419022.461980]  [<ffffffffa0baed3b>] xfs_bmapi_write+0x78b/0xba0 [xfs]
[419022.468360]  [<ffffffffa0bf71a6>] xfs_iomap_write_allocate+0x196/0x3a0 [xfs]
[419022.475517]  [<ffffffffa0be09fb>] xfs_map_blocks+0x1eb/0x260 [xfs]
[419022.481806]  [<ffffffffa0be1abc>] xfs_do_writepage+0x1cc/0x6e0 [xfs]
[419022.488240]  [<ffffffff811ad8df>] write_cache_pages+0x26f/0x510
[419022.494245]  [<ffffffff81339daa>] ? blk_queue_bio+0x17a/0x3a0
[419022.500103]  [<ffffffffa0be18f0>] ? xfs_vm_writepages+0xe0/0xe0 [xfs]
[419022.506654]  [<ffffffffa0be18c6>] xfs_vm_writepages+0xb6/0xe0 [xfs]
[419022.513004]  [<ffffffff811ae8fe>] do_writepages+0x1e/0x30
[419022.518488]  [<ffffffff81260795>] __writeback_single_inode+0x45/0x330
[419022.525012]  [<ffffffff81260fd0>] writeback_sb_inodes+0x280/0x570
[419022.531189]  [<ffffffff8126148f>] wb_writeback+0x10f/0x320
[419022.536756]  [<ffffffff81261e29>] wb_workfn+0x109/0x3f0
[419022.542066]  [<ffffffff810a8be2>] process_one_work+0x152/0x400
[419022.547980]  [<ffffffff810a94d5>] worker_thread+0x125/0x4b0
[419022.553636]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419022.559376]  [<ffffffff810a93b0>] ? rescuer_thread+0x380/0x380
[419022.565289]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419022.571032]  [<ffffffff810af039>] kthread+0xd9/0xf0
[419022.575996]  [<ffffffff810aef60>] ? kthread_park+0x60/0x60
[419022.581563]  [<ffffffff8170ff95>] ret_from_fork+0x25/0x30
[419022.587046] Code: 49 83 87 18 01 00 00 01 48 89 df e8 e0 b3 07 00 48 8b 95 58 ff ff ff 31 c9 48 89 de 4c 89 ef e8 3c fd 00 00 48 89 85 f8 fe ff ff <48> c7 80 68 01 00 00 d0 b5 c2 a0 48 8b 80 a0 00 00 00 48 89 85
[419022.607262] RIP  [<ffffffffa0ba492b>] xfs_bmap_extents_to_btree+0x25b/0x630 [xfs]
[419022.614866]  RSP <ffffc90007b2b458>
[419022.618441] CR2: 0000000000000168
[419022.718795] ---[ end trace 5fae8d49ab722484 ]---
[419022.723497] Kernel panic - not syncing: Fatal exception
[419022.729283] Kernel Offset: disabled
[419022.732860] ---[ end Kernel panic - not syncing: Fatal exception
[419022.738951] ------------[ cut here ]------------
[419022.743656] WARNING: CPU: 11 PID: 4984 at arch/x86/kernel/smp.c:127 native_smp_send_reschedule+0x3f/0x50
[419022.753210] Modules linked in: xfs overlay arc4 md4 nls_utf8 cifs rpcsec_gss_krb5 nfsv4 dns_resolver nfs fscache dm_delay dm_zero btrfs xor raid6_pq dm_thin_pool dm_persistent_data dm_bio_prison dm_snapshot dm_bufio loop dm_flakey libcrc32c ip6t_rpfilter ipt_REJECT nf_reject_ipv4 ip6t_REJECT nf_reject_ipv6 xt_conntrack ip_set nfnetlink ebtable_nat ebtable_broute bridge stp llc ip6table_nat nf_conntrack_ipv6 nf_defrag_ipv6 nf_nat_ipv6 ip6table_mangle ip6table_security ip6table_raw iptable_nat nf_conntrack_ipv4 nf_defrag_ipv4 nf_nat_ipv4 nf_nat nf_conntrack iptable_mangle iptable_security iptable_raw ebtable_filter ebtables ip6table_filter ip6_tables iptable_filter intel_powerclamp coretemp kvm_intel kvm irqbypass crct10dif_pclmul crc32_pclmul ipmi_ssif ghash_clmulni_intel cdc_ether usbnet aesni_intel lrw gf128mul glue_helper iTCO_wdt iTCO_vendor_support ipmi_devintf mii ablk_helper i2c_i801 cryptd i2c_smbus lpc_ich pcspkr ipmi_si nfsd sg i7core_edac ipmi_msghandler ioatdma edac_core shpchp dca acpi_cpufreq auth_rpcgss nfs_acl lockd grace sunrpc ip_tables ext4 jbd2 mbcache sr_mod sd_mod cdrom mgag200 i2c_algo_bit drm_kms_helper syscopyarea ata_generic sysfillrect pata_acpi sysimgblt fb_sys_fops ttm ata_piix crc32c_intel drm libata serio_raw megaraid_sas i2c_core bnx2 fjes dm_mirror dm_region_hash dm_log dm_mod [last unloaded: xfs]
[419022.873226] CPU: 11 PID: 4984 Comm: kworker/u50:2 Tainted: G      D W  OE   4.9.0-rc1.xfs+ #7
[419022.881828] Hardware name: IBM System x3550 M3 -[7944OEJ]-/90Y4784     , BIOS -[D6E150CUS-1.11]- 02/08/2011
[419022.891645] Workqueue: writeback wb_workfn (flush-253:4)
[419022.897073]  ffff88027fb43c78 ffffffff81363bec 0000000000000000 0000000000000000
[419022.904627]  ffff88027fb43cb8 ffffffff8108f201 0000007f77040f00 ffff880275c2ab00
[419022.912181]  ffff880275c2b61c 0000000000000000 0000000000000046 0000000000019300
[419022.919735] Call Trace:
[419022.922270]  <IRQ> [419022.924288]  [<ffffffff81363bec>] dump_stack+0x63/0x87
[419022.929523]  [<ffffffff8108f201>] __warn+0xd1/0xf0
[419022.934397]  [<ffffffff8108f33d>] warn_slowpath_null+0x1d/0x20
[419022.940312]  [<ffffffff81051c7f>] native_smp_send_reschedule+0x3f/0x50
[419022.946921]  [<ffffffff810bb988>] try_to_wake_up+0x328/0x3b0
[419022.952661]  [<ffffffff810bbac2>] default_wake_function+0x12/0x20
[419022.958840]  [<ffffffff810d56d5>] __wake_up_common+0x55/0x90
[419022.964580]  [<ffffffff810d5723>] __wake_up_locked+0x13/0x20
[419022.970323]  [<ffffffff8127b199>] ep_poll_callback+0xb9/0x200
[419022.976152]  [<ffffffff810d56d5>] __wake_up_common+0x55/0x90
[419022.981893]  [<ffffffff810d5859>] __wake_up+0x39/0x50
[419022.987031]  [<ffffffff810eca90>] wake_up_klogd_work_func+0x40/0x60
[419022.993382]  [<ffffffff8118652d>] irq_work_run_list+0x4d/0x70
[419022.999214]  [<ffffffff81111d90>] ? tick_sched_do_timer+0x50/0x50
[419023.005390]  [<ffffffff811866e0>] irq_work_tick+0x40/0x50
[419023.010873]  [<ffffffff81101bb2>] update_process_times+0x42/0x60
[419023.016961]  [<ffffffff811116d5>] tick_sched_handle.isra.16+0x25/0x60
[419023.023483]  [<ffffffff81111dcd>] tick_sched_timer+0x3d/0x70
[419023.029223]  [<ffffffff811028d3>] __hrtimer_run_queues+0xf3/0x280
[419023.035399]  [<ffffffff81102db8>] hrtimer_interrupt+0xa8/0x1a0
[419023.041313]  [<ffffffff81054635>] local_apic_timer_interrupt+0x35/0x60
[419023.047922]  [<ffffffff817128ed>] smp_apic_timer_interrupt+0x3d/0x50
[419023.054354]  [<ffffffff81711aac>] apic_timer_interrupt+0x8c/0xa0
[419023.060441]  <EOI> [419023.062460]  [<ffffffff8119dde3>] ? panic+0x1f5/0x239
[419023.067613]  [<ffffffff81031a28>] oops_end+0xb8/0xd0
[419023.072665]  [<ffffffff8106b73e>] no_context+0x19e/0x400
[419023.078060]  [<ffffffff8106ba8e>] __bad_area_nosemaphore+0xee/0x1d0
[419023.084409]  [<ffffffff8106bb84>] bad_area_nosemaphore+0x14/0x20
[419023.090496]  [<ffffffff8106c239>] __do_page_fault+0x89/0x4a0
[419023.096236]  [<ffffffff8108f1da>] ? __warn+0xaa/0xf0
[419023.101283]  [<ffffffff8106c680>] do_page_fault+0x30/0x80
[419023.106765]  [<ffffffff81711208>] page_fault+0x28/0x30
[419023.112022]  [<ffffffffa0be6f46>] ? xfs_buf_free+0xb6/0x120 [xfs]
[419023.118221]  [<ffffffffa0ba492b>] ? xfs_bmap_extents_to_btree+0x25b/0x630 [xfs]
[419023.125634]  [<ffffffffa0ba4924>] ? xfs_bmap_extents_to_btree+0x254/0x630 [xfs]
[419023.133043]  [<ffffffffa0b999fc>] ? xfs_alloc_update_counters.isra.17+0x3c/0x50 [xfs]
[419023.140976]  [<ffffffffa0baaac2>] xfs_bmap_add_extent_delay_real+0x1b42/0x2090 [xfs]
[419023.148821]  [<ffffffffa0baed3b>] xfs_bmapi_write+0x78b/0xba0 [xfs]
[419023.155202]  [<ffffffffa0bf71a6>] xfs_iomap_write_allocate+0x196/0x3a0 [xfs]
[419023.162358]  [<ffffffffa0be09fb>] xfs_map_blocks+0x1eb/0x260 [xfs]
[419023.168647]  [<ffffffffa0be1abc>] xfs_do_writepage+0x1cc/0x6e0 [xfs]
[419023.175082]  [<ffffffff811ad8df>] write_cache_pages+0x26f/0x510
[419023.181086]  [<ffffffff81339daa>] ? blk_queue_bio+0x17a/0x3a0
[419023.186944]  [<ffffffffa0be18f0>] ? xfs_vm_writepages+0xe0/0xe0 [xfs]
[419023.193495]  [<ffffffffa0be18c6>] xfs_vm_writepages+0xb6/0xe0 [xfs]
[419023.199846]  [<ffffffff811ae8fe>] do_writepages+0x1e/0x30
[419023.205329]  [<ffffffff81260795>] __writeback_single_inode+0x45/0x330
[419023.211852]  [<ffffffff81260fd0>] writeback_sb_inodes+0x280/0x570
[419023.218029]  [<ffffffff8126148f>] wb_writeback+0x10f/0x320
[419023.223597]  [<ffffffff81261e29>] wb_workfn+0x109/0x3f0
[419023.228906]  [<ffffffff810a8be2>] process_one_work+0x152/0x400
[419023.234820]  [<ffffffff810a94d5>] worker_thread+0x125/0x4b0
[419023.240476]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419023.246217]  [<ffffffff810a93b0>] ? rescuer_thread+0x380/0x380
[419023.252132]  [<ffffffff81003a47>] ? do_syscall_64+0x67/0x180
[419023.257872]  [<ffffffff810af039>] kthread+0xd9/0xf0
[419023.262835]  [<ffffffff810aef60>] ? kthread_park+0x60/0x60
[419023.268402]  [<ffffffff8170ff95>] ret_from_fork+0x25/0x30
[419023.273884] ---[ end trace 5fae8d49ab722485 ]---

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Mon, Dec 05, 2016 at 05:21:12PM +0800, Eryu Guan wrote:
> Hi,
> 
> I hit an xfs/109 crash today while testing reflink XFS with 2k block
> size on x86_64 hosts (both baremetal and kvm guest).
> 
> It can be reproduced by running xfs/109 many times, I tried 50-times
> loop twice and it crashed at the 21st and 46th runs. And I can reproduce
> it with both linus tree (4.9-rc4) and linux-xfs tree for-next branch
> (updated on 2016-11-30). I haven't been able to reproduce it with 4k
> block size XFS.
> 
> Detailed host info and crash log are appended at the end of this mail.

FYI, I've got a bug report for a very similar OOPS on a 4k file system,
but the reproducer is not xfstests but a complex customer workload.

The actual out of range block number is a little different, but it's
the same odd pattern with something set in the highest byte of the block
number.

I'll start looking into it today, and this reproducer might be really
useful.

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Mon, Dec 05, 2016 at 05:21:12PM +0800, Eryu Guan wrote:
> Hi,
> 
> I hit an xfs/109 crash today while testing reflink XFS with 2k block
> size on x86_64 hosts (both baremetal and kvm guest).
> 
> It can be reproduced by running xfs/109 many times, I tried 50-times
> loop twice and it crashed at the 21st and 46th runs. And I can reproduce
> it with both linus tree (4.9-rc4) and linux-xfs tree for-next branch
> (updated on 2016-11-30). I haven't been able to reproduce it with 4k
> block size XFS.

Haven't been able to reproduce it yet unfortunately.  But from looking
at the out of range block this looks like it could be NULLFSBLOCK
converted to a daddr.

I assume you are running without CONFIG_XFS_DEBUG or CONFIG_XFS_WARN
enabled?

Below would catch this issue in a non-debug build.  Still trying to
reproduce in the meantime..


diff --git a/fs/xfs/libxfs/xfs_bmap.c b/fs/xfs/libxfs/xfs_bmap.c
index c6eb219..2c19b11 100644
--- a/fs/xfs/libxfs/xfs_bmap.c
+++ b/fs/xfs/libxfs/xfs_bmap.c
@@ -780,12 +780,14 @@ try_another_ag:
 	if (xfs_sb_version_hasreflink(&cur->bc_mp->m_sb) &&
 	    args.fsbno == NULLFSBLOCK &&
 	    args.type == XFS_ALLOCTYPE_NEAR_BNO) {
+		printk("trying another AG\n");
 		dfops->dop_low = true;
 		goto try_another_ag;
 	}
 	/*
 	 * Allocation can't fail, the space was reserved.
 	 */
+	BUG_ON(args.fsbno == NULLFSBLOCK);
 	ASSERT(args.fsbno != NULLFSBLOCK);
 	ASSERT(*firstblock == NULLFSBLOCK ||
 	       args.agno == XFS_FSB_TO_AGNO(mp, *firstblock) ||

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Mon, Dec 05, 2016 at 06:39:06AM -0800, Christoph Hellwig wrote:
> On Mon, Dec 05, 2016 at 05:21:12PM +0800, Eryu Guan wrote:
> > Hi,
> > 
> > I hit an xfs/109 crash today while testing reflink XFS with 2k block
> > size on x86_64 hosts (both baremetal and kvm guest).
> > 
> > It can be reproduced by running xfs/109 many times, I tried 50-times
> > loop twice and it crashed at the 21st and 46th runs. And I can reproduce
> > it with both linus tree (4.9-rc4) and linux-xfs tree for-next branch
> > (updated on 2016-11-30). I haven't been able to reproduce it with 4k
> > block size XFS.
> 
> Haven't been able to reproduce it yet unfortunately.  But from looking
> at the out of range block this looks like it could be NULLFSBLOCK
> converted to a daddr.
> 
> I assume you are running without CONFIG_XFS_DEBUG or CONFIG_XFS_WARN
> enabled?
> 
> Below would catch this issue in a non-debug build.  Still trying to
> reproduce in the meantime..

Ok, finally managed to reproduce it and hit my BUG_ON below after
hitting the the "trying another AG" printk (only once so far).

Seems like the retry case for COW file systems doesn't work reliably.
That being said given that this tests doesn't even exercise the COW
functionality we shouldn't normally even hit this case, should we?

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Darrick J. Wong]

On Mon, Dec 05, 2016 at 07:36:25AM -0800, Christoph Hellwig wrote:
> On Mon, Dec 05, 2016 at 06:39:06AM -0800, Christoph Hellwig wrote:
> > On Mon, Dec 05, 2016 at 05:21:12PM +0800, Eryu Guan wrote:
> > > Hi,
> > > 
> > > I hit an xfs/109 crash today while testing reflink XFS with 2k block
> > > size on x86_64 hosts (both baremetal and kvm guest).
> > > 
> > > It can be reproduced by running xfs/109 many times, I tried 50-times
> > > loop twice and it crashed at the 21st and 46th runs. And I can reproduce
> > > it with both linus tree (4.9-rc4) and linux-xfs tree for-next branch
> > > (updated on 2016-11-30). I haven't been able to reproduce it with 4k
> > > block size XFS.
> > 
> > Haven't been able to reproduce it yet unfortunately.  But from looking
> > at the out of range block this looks like it could be NULLFSBLOCK
> > converted to a daddr.
> > 
> > I assume you are running without CONFIG_XFS_DEBUG or CONFIG_XFS_WARN
> > enabled?
> > 
> > Below would catch this issue in a non-debug build.  Still trying to
> > reproduce in the meantime..
> 
> Ok, finally managed to reproduce it and hit my BUG_ON below after
> hitting the the "trying another AG" printk (only once so far).
> 
> Seems like the retry case for COW file systems doesn't work reliably.
> That being said given that this tests doesn't even exercise the COW
> functionality we shouldn't normally even hit this case, should we?

Hmm.  Purely speculating here (I haven't yet been able to reproduce it)
but I wonder if we're nearly out of space, fdblocks is still large
enough that we can start delalloc reservations, but something is
stealing blocks out of the AGs such that when we go to look for one
there aren't any (or the per AG reservation denies it).

Does it happen if rmapbt=0 ?  Since xfs/109 isn't doing any CoW, it's
possible that this could be another symptom of the bug where we reserve
all the bmap+rmap blocks we need via indlen, but discard the entire
reservation in the transaction roll that happens before we start the
rmap update, which effectively means we're allocating space that we
didn't previously reserve...

I suppose you could constrict the reflink exception thing further by
passing bma->flags to xfs_bmap_extents_to_btree and only allowing the
ENOSPC retry if XFS_BMAPI_REMAP is set.

--D

> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Mon, Dec 05, 2016 at 10:28:02AM -0800, Darrick J. Wong wrote:
> Hmm.  Purely speculating here (I haven't yet been able to reproduce it)
> but I wonder if we're nearly out of space, fdblocks is still large
> enough that we can start delalloc reservations, but something is
> stealing blocks out of the AGs such that when we go to look for one
> there aren't any (or the per AG reservation denies it).
> 
> Does it happen if rmapbt=0 ?  Since xfs/109 isn't doing any CoW, it's
> possible that this could be another symptom of the bug where we reserve
> all the bmap+rmap blocks we need via indlen, but discard the entire
> reservation in the transaction roll that happens before we start the
> rmap update, which effectively means we're allocating space that we
> didn't previously reserve...

I'm pretty sure it's something like that, but I don't think rmap
needs to be in the game - at least my customer report does not have rmap
enabled.

> I suppose you could constrict the reflink exception thing further by
> passing bma->flags to xfs_bmap_extents_to_btree and only allowing the
> ENOSPC retry if XFS_BMAPI_REMAP is set.

Well, we assert on having an allocation even without that exception,
so I'm not sure that would help us - it's just an oddity I noticed
while looking at the code.

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Eryu Guan]

On Mon, Dec 05, 2016 at 10:28:02AM -0800, Darrick J. Wong wrote:
> Does it happen if rmapbt=0 ?  Since xfs/109 isn't doing any CoW, it's

FYI, I looped xfs/109 for 150 times with rmapbt=0, and didn't hit any
problem.

[root@ibm-x3550m3-05 xfstests]# xfs_info /mnt/xfs
meta-data=/dev/mapper/testvg-testlv2 isize=512    agcount=4, agsize=20480 blks
         =                       sectsz=512   attr=2, projid32bit=1
         =                       crc=1        finobt=1 spinodes=0 rmapbt=0
         =                       reflink=0
data     =                       bsize=2048   blocks=81920, imaxpct=25
         =                       sunit=0      swidth=0 blks
naming   =version 2              bsize=4096   ascii-ci=0 ftype=1
log      =internal               bsize=2048   blocks=1445, version=2
         =                       sectsz=512   sunit=0 blks, lazy-count=1
realtime =none                   extsz=4096   blocks=0, rtextents=0

Thanks,
Eryu

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

Hi Eryu,

my attempts at reproducing this are still not very reliable, someimes
it takes three iterations, sometimes it's doing fine for 100+.

Can you try reverting commit 0af32fb46 ("xfs: fix bogus space
reservation in xfs_iomap_write_allocate") and give this a spin on your
test setup?  I wonder if somehow our accounting for the case where
we convert from inline extents to the btree format is not correct,
and the code before that commit was papering over that fact.

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

I think the problem is that the extents -> btree conversion does not
use the per-AG reservations, but it should probably use it (even if it
predates if of course).

In the reproduce the fs still has enough blocks to allocate the
one block for the first bmap btree leave.  But all free space sits
in AGs with a lower agno then what we used for allocating the actual
extent, and thus xfs_alloc_vextent never manages to allocate it.

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Brian Foster]

On Tue, Dec 06, 2016 at 06:45:59AM -0800, Christoph Hellwig wrote:
> I think the problem is that the extents -> btree conversion does not
> use the per-AG reservations, but it should probably use it (even if it
> predates if of course).
> 
> In the reproduce the fs still has enough blocks to allocate the
> one block for the first bmap btree leave.  But all free space sits
> in AGs with a lower agno then what we used for allocating the actual
> extent, and thus xfs_alloc_vextent never manages to allocate it.

Not that I have any insight into the problem here... :P but I'm still[1]
kind of wondering how that mechanism is supposed to work when it
ultimately calls xfs_mod_fdblocks() for each AG..?

Brian

[1] http://www.spinics.net/lists/linux-xfs/msg01509.html

> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Eryu Guan]

On Tue, Dec 06, 2016 at 05:48:47AM -0800, Christoph Hellwig wrote:
> Hi Eryu,
> 
> my attempts at reproducing this are still not very reliable, someimes
> it takes three iterations, sometimes it's doing fine for 100+.
> 
> Can you try reverting commit 0af32fb46 ("xfs: fix bogus space
> reservation in xfs_iomap_write_allocate") and give this a spin on your
> test setup?  I wonder if somehow our accounting for the case where

Sure, test is running now.

Looking at this commit, reminds me another bug I reported in Aug. that I
wasn't able to find a simpler reproducer..

https://www.spinics.net/lists/xfs/msg42159.html

Thanks,
Eryu

> we convert from inline extents to the btree format is not correct,
> and the code before that commit was papering over that fact.
> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Eryu Guan]

On Tue, Dec 06, 2016 at 11:24:09PM +0800, Eryu Guan wrote:
> On Tue, Dec 06, 2016 at 05:48:47AM -0800, Christoph Hellwig wrote:
> > Hi Eryu,
> > 
> > my attempts at reproducing this are still not very reliable, someimes
> > it takes three iterations, sometimes it's doing fine for 100+.
> > 
> > Can you try reverting commit 0af32fb46 ("xfs: fix bogus space
> > reservation in xfs_iomap_write_allocate") and give this a spin on your
> > test setup?  I wonder if somehow our accounting for the case where
> 
> Sure, test is running now.

XFS with this patch reverted still crashes in the same way, at the 36th
iteration this time.

Thanks,
Eryu

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Darrick J. Wong]

On Tue, Dec 06, 2016 at 10:19:46AM -0500, Brian Foster wrote:
> On Tue, Dec 06, 2016 at 06:45:59AM -0800, Christoph Hellwig wrote:
> > I think the problem is that the extents -> btree conversion does not
> > use the per-AG reservations, but it should probably use it (even if it
> > predates if of course).
> > 
> > In the reproduce the fs still has enough blocks to allocate the
> > one block for the first bmap btree leave.  But all free space sits
> > in AGs with a lower agno then what we used for allocating the actual
> > extent, and thus xfs_alloc_vextent never manages to allocate it.
> 
> Not that I have any insight into the problem here... :P but I'm still[1]
> kind of wondering how that mechanism is supposed to work when it
> ultimately calls xfs_mod_fdblocks() for each AG..?

Oh, heh, I was meaning to reply to that and never did. :(

Will go work on that!

--D

> 
> Brian
> 
> [1] http://www.spinics.net/lists/linux-xfs/msg01509.html
> 
> > --
> > To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> > the body of a message to majordomo@vger.kernel.org
> > More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Darrick J. Wong]

On Tue, Dec 06, 2016 at 06:45:59AM -0800, Christoph Hellwig wrote:
> I think the problem is that the extents -> btree conversion does not
> use the per-AG reservations, but it should probably use it (even if it
> predates if of course).
> 
> In the reproduce the fs still has enough blocks to allocate the
> one block for the first bmap btree leave.  But all free space sits
> in AGs with a lower agno then what we used for allocating the actual
> extent, and thus xfs_alloc_vextent never manages to allocate it.

Wellll... I cobbled together a crappy patch that flips on
XFS_AG_RESV_AGFL if xfs_bmap_extents_to_btree really can't get a block.
It seems to have survived ~175 iterations of xfs/109 so I'll try to
clean it up tomorrow.

Not sure that helps Christoph's situation though... if you're not
running rmap or reflink then the AG reservation is always zero.

--D

> --
> To unsubscribe from this list: send the line "unsubscribe linux-xfs" in
> the body of a message to majordomo@vger.kernel.org
> More majordomo info at  http://vger.kernel.org/majordomo-info.html

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Tue, Dec 06, 2016 at 07:49:03PM -0800, Darrick J. Wong wrote:
> On Tue, Dec 06, 2016 at 06:45:59AM -0800, Christoph Hellwig wrote:
> > I think the problem is that the extents -> btree conversion does not
> > use the per-AG reservations, but it should probably use it (even if it
> > predates if of course).
> > 
> > In the reproduce the fs still has enough blocks to allocate the
> > one block for the first bmap btree leave.  But all free space sits
> > in AGs with a lower agno then what we used for allocating the actual
> > extent, and thus xfs_alloc_vextent never manages to allocate it.
> 
> Wellll... I cobbled together a crappy patch that flips on
> XFS_AG_RESV_AGFL if xfs_bmap_extents_to_btree really can't get a block.
> It seems to have survived ~175 iterations of xfs/109 so I'll try to
> clean it up tomorrow.

I tried it with XFS_AG_RESV_METADATA, but that didn't work.  But then
again I didn't add an additional reservation and I was about to head
out for dinner so I didn't investigate the details.  It might have been
the case Ross pointed out yeserday, so I'll look into the details more
today.

> Not sure that helps Christoph's situation though... if you're not
> running rmap or reflink then the AG reservation is always zero.

For now I was just running xfs/109.  The customer workload uses
reflinks, but not rmap.  That being said I think this issue can
in theory happen without eithr one due to the way the AG loop
works in xfs_alloc_vextext - while we have a reservation for the
indirect block(s) there is no guarantee it is in an AG that is
greater or equal to that use for the actual extent allocation.

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Tue, Dec 06, 2016 at 11:18:57PM -0800, Christoph Hellwig wrote:
> > Wellll... I cobbled together a crappy patch that flips on
> > XFS_AG_RESV_AGFL if xfs_bmap_extents_to_btree really can't get a block.
> > It seems to have survived ~175 iterations of xfs/109 so I'll try to
> > clean it up tomorrow.
> 
> I tried it with XFS_AG_RESV_METADATA, but that didn't work.  But then
> again I didn't add an additional reservation and I was about to head
> out for dinner so I didn't investigate the details.  It might have been
> the case Ross pointed out yeserday, so I'll look into the details more
> today.

XFS_AG_RESV_AGFL works.  For some kinds of "work".  I can't see the
original issue anymore, but I can see this related assert a lot (which
I've also seen before, but no as often), so there is some more I need
to look into.

[ 2594.324341] XFS: Assertion failed: fs_is_ok, file: fs/xfs/libxfs/xfs_btree.c, line: 3484
[ 2594.329918] ------------[ cut here ]------------
[ 2594.330309] kernel BUG at fs/xfs/xfs_message.c:113!
[ 2594.330641] invalid opcode: 0000 [#1] SMP
[ 2594.330912] Modules linked in:
[ 2594.331129] CPU: 2 PID: 29744 Comm: kworker/u8:0 Tainted: G        W 4.9.0-rc1+ #1758
[ 2594.331680] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
[ 2594.332353] Workqueue: writeback wb_workfn (flush-252:32)
[ 2594.332731] task: ffff88000d86ccc0 task.stack: ffffc90009f74000
[ 2594.333127] RIP: 0010:[<ffffffff815aee1d>]  [<ffffffff815aee1d>] assfail+0x1d/0x20
[ 2594.333214] RSP: 0018:ffffc90009f774c8  EFLAGS: 00010282
[ 2594.333214] RAX: 00000000ffffffea RBX: ffff880132b2ac08 RCX: 0000000000000021
[ 2594.333214] RDX: ffffc90009f773f0 RSI: 000000000000000a RDI: ffffffff8240a75b
[ 2594.333214] RBP: ffffc90009f774c8 R08: 0000000000000000 R09: 0000000000000000
[ 2594.333214] R10: 000000000000000a R11: f000000000000000 R12: ffff880132b2ac08
[ 2594.333214] R13: 0000000000000000 R14: ffffc90009f774ec R15: ffffc90009f775dc
[ 2594.333214] FS:  0000000000000000(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
[ 2594.333214] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2594.333214] CR2: 00007f7f7c43c6c0 CR3: 0000000002606000 CR4: 00000000000006e0
[ 2594.333214] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
[ 2594.333214] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
[ 2594.333214] Stack:
[ 2594.333214]  ffffc90009f77568 ffffffff8154fddc ffffc90009f774ec 000000000000007b
[ 2594.333214]  0000000009f77568 ffffffffffffffff 0000000000000000 00c01e0000000000
[ 2594.333214]  1f0000b830000000 ffffffffffffffff 600f000000000000 ffffffff8157102d
[ 2594.333214] Call Trace:
[ 2594.333214]  [<ffffffff8154fddc>] xfs_btree_insert+0xac/0x1f0
[ 2594.333214]  [<ffffffff8157102d>] ? xfs_iext_insert+0xad/0x1e0
[ 2594.333214]  [<ffffffff81536802>] ? xfs_bmap_add_extent_delay_real+0xe22/0x3670
[ 2594.333214]  [<ffffffff8153887f>] xfs_bmap_add_extent_delay_real+0x2e9f/0x3670
[ 2594.333214]  [<ffffffff8154072a>] xfs_bmapi_write+0xb5a/0x1200
[ 2594.333214]  [<ffffffff815a45ad>] xfs_iomap_write_allocate+0x18d/0x370
[ 2594.333214]  [<ffffffff81587274>] xfs_map_blocks+0x214/0x460
[ 2594.333214]  [<ffffffff8158847c>] xfs_do_writepage+0x2bc/0x800
[ 2594.333214]  [<ffffffff811cbfea>] write_cache_pages+0x1fa/0x5a0
[ 2594.333214]  [<ffffffff815881c0>] ? xfs_aops_discard_page+0x140/0x140
[ 2594.333214]  [<ffffffff8158779e>] xfs_vm_writepages+0x9e/0xd0
[ 2594.333214]  [<ffffffff811ce77c>] do_writepages+0x1c/0x30
[ 2594.333214]  [<ffffffff8124a84c>] __writeback_single_inode+0x5c/0x6f0
[ 2594.333214]  [<ffffffff8124bb91>] writeback_sb_inodes+0x2a1/0x5e0
[ 2594.333214]  [<ffffffff8124c142>] wb_writeback+0x112/0x4f0
[ 2594.333214]  [<ffffffff8124cc05>] wb_workfn+0x115/0x5f0
[ 2594.333214]  [<ffffffff810f70fb>] ? process_one_work+0x13b/0x600
[ 2594.333214]  [<ffffffff810f7181>] process_one_work+0x1c1/0x600
[ 2594.333214]  [<ffffffff810f70fb>] ? process_one_work+0x13b/0x600
[ 2594.333214]  [<ffffffff810f7624>] worker_thread+0x64/0x4a0
[ 2594.333214]  [<ffffffff810f75c0>] ? process_one_work+0x600/0x600
[ 2594.333214]  [<ffffffff810f75c0>] ? process_one_work+0x600/0x600
[ 2594.333214]  [<ffffffff810fd2e2>] kthread+0xf2/0x110
[ 2594.333214]  [<ffffffff810d5a1e>] ? put_task_stack+0x15e/0x190
[ 2594.333214]  [<ffffffff810fd1f0>] ? kthread_park+0x60/0x60
[ 2594.333214]  [<ffffffff81e7156a>] ret_from_fork+0x2a/0x40

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Darrick J. Wong]

On Wed, Dec 07, 2016 at 09:40:32AM -0800, Christoph Hellwig wrote:
> On Tue, Dec 06, 2016 at 11:18:57PM -0800, Christoph Hellwig wrote:
> > > Wellll... I cobbled together a crappy patch that flips on
> > > XFS_AG_RESV_AGFL if xfs_bmap_extents_to_btree really can't get a block.
> > > It seems to have survived ~175 iterations of xfs/109 so I'll try to
> > > clean it up tomorrow.
> > 
> > I tried it with XFS_AG_RESV_METADATA, but that didn't work.  But then
> > again I didn't add an additional reservation and I was about to head
> > out for dinner so I didn't investigate the details.  It might have been
> > the case Ross pointed out yeserday, so I'll look into the details more
> > today.
> 
> XFS_AG_RESV_AGFL works.  For some kinds of "work".  I can't see the
> original issue anymore, but I can see this related assert a lot (which
> I've also seen before, but no as often), so there is some more I need
> to look into.

I bet that assert is a result of the btree insert failing to find a new
block to expand into.  I've felt for a while that we ought to yell ENOSPC
louder when this happens, since I've hit it numerous times and grumbled
about it not being obvious that we ran out of space.

Anyway, XFS_AG_RESV_AGFL only gets a reservation if rmapbt=1 (or if you
added an additional reservation after dinner), so if you're running
reflink only then it's not surprising that it still runs out of space,
since reflink=1 only reserves RESV_METADATA space.

In any case I'm persuaded that we're failing to account for that bmbt
expansion block when we make the first allocation.  AFAICT in
xfs_bmapi_allocate we ask the allocator for exactly as many blocks as we
need to satisfy the data block write; if there are exactly that many
blocks in the last AG then we get blocks out of that last AG.  But then
we have to convert extents_to_btree, so we make a second allocation
request (and we have to start with that same AG) for another block,
which it doesn't have, so it blows up.

It might work to just increase args->minfree if we have an extents file
and think we might have to convert it to btree format.  (It's late, not
going to try this until the morning.)

--D

> [ 2594.324341] XFS: Assertion failed: fs_is_ok, file: fs/xfs/libxfs/xfs_btree.c, line: 3484
> [ 2594.329918] ------------[ cut here ]------------
> [ 2594.330309] kernel BUG at fs/xfs/xfs_message.c:113!
> [ 2594.330641] invalid opcode: 0000 [#1] SMP
> [ 2594.330912] Modules linked in:
> [ 2594.331129] CPU: 2 PID: 29744 Comm: kworker/u8:0 Tainted: G        W 4.9.0-rc1+ #1758
> [ 2594.331680] Hardware name: QEMU Standard PC (i440FX + PIIX, 1996), BIOS 1.7.5-20140531_083030-gandalf 04/01/2014
> [ 2594.332353] Workqueue: writeback wb_workfn (flush-252:32)
> [ 2594.332731] task: ffff88000d86ccc0 task.stack: ffffc90009f74000
> [ 2594.333127] RIP: 0010:[<ffffffff815aee1d>]  [<ffffffff815aee1d>] assfail+0x1d/0x20
> [ 2594.333214] RSP: 0018:ffffc90009f774c8  EFLAGS: 00010282
> [ 2594.333214] RAX: 00000000ffffffea RBX: ffff880132b2ac08 RCX: 0000000000000021
> [ 2594.333214] RDX: ffffc90009f773f0 RSI: 000000000000000a RDI: ffffffff8240a75b
> [ 2594.333214] RBP: ffffc90009f774c8 R08: 0000000000000000 R09: 0000000000000000
> [ 2594.333214] R10: 000000000000000a R11: f000000000000000 R12: ffff880132b2ac08
> [ 2594.333214] R13: 0000000000000000 R14: ffffc90009f774ec R15: ffffc90009f775dc
> [ 2594.333214] FS:  0000000000000000(0000) GS:ffff88013fd00000(0000) knlGS:0000000000000000
> [ 2594.333214] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
> [ 2594.333214] CR2: 00007f7f7c43c6c0 CR3: 0000000002606000 CR4: 00000000000006e0
> [ 2594.333214] DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
> [ 2594.333214] DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
> [ 2594.333214] Stack:
> [ 2594.333214]  ffffc90009f77568 ffffffff8154fddc ffffc90009f774ec 000000000000007b
> [ 2594.333214]  0000000009f77568 ffffffffffffffff 0000000000000000 00c01e0000000000
> [ 2594.333214]  1f0000b830000000 ffffffffffffffff 600f000000000000 ffffffff8157102d
> [ 2594.333214] Call Trace:
> [ 2594.333214]  [<ffffffff8154fddc>] xfs_btree_insert+0xac/0x1f0
> [ 2594.333214]  [<ffffffff8157102d>] ? xfs_iext_insert+0xad/0x1e0
> [ 2594.333214]  [<ffffffff81536802>] ? xfs_bmap_add_extent_delay_real+0xe22/0x3670
> [ 2594.333214]  [<ffffffff8153887f>] xfs_bmap_add_extent_delay_real+0x2e9f/0x3670
> [ 2594.333214]  [<ffffffff8154072a>] xfs_bmapi_write+0xb5a/0x1200
> [ 2594.333214]  [<ffffffff815a45ad>] xfs_iomap_write_allocate+0x18d/0x370
> [ 2594.333214]  [<ffffffff81587274>] xfs_map_blocks+0x214/0x460
> [ 2594.333214]  [<ffffffff8158847c>] xfs_do_writepage+0x2bc/0x800
> [ 2594.333214]  [<ffffffff811cbfea>] write_cache_pages+0x1fa/0x5a0
> [ 2594.333214]  [<ffffffff815881c0>] ? xfs_aops_discard_page+0x140/0x140
> [ 2594.333214]  [<ffffffff8158779e>] xfs_vm_writepages+0x9e/0xd0
> [ 2594.333214]  [<ffffffff811ce77c>] do_writepages+0x1c/0x30
> [ 2594.333214]  [<ffffffff8124a84c>] __writeback_single_inode+0x5c/0x6f0
> [ 2594.333214]  [<ffffffff8124bb91>] writeback_sb_inodes+0x2a1/0x5e0
> [ 2594.333214]  [<ffffffff8124c142>] wb_writeback+0x112/0x4f0
> [ 2594.333214]  [<ffffffff8124cc05>] wb_workfn+0x115/0x5f0
> [ 2594.333214]  [<ffffffff810f70fb>] ? process_one_work+0x13b/0x600
> [ 2594.333214]  [<ffffffff810f7181>] process_one_work+0x1c1/0x600
> [ 2594.333214]  [<ffffffff810f70fb>] ? process_one_work+0x13b/0x600
> [ 2594.333214]  [<ffffffff810f7624>] worker_thread+0x64/0x4a0
> [ 2594.333214]  [<ffffffff810f75c0>] ? process_one_work+0x600/0x600
> [ 2594.333214]  [<ffffffff810f75c0>] ? process_one_work+0x600/0x600
> [ 2594.333214]  [<ffffffff810fd2e2>] kthread+0xf2/0x110
> [ 2594.333214]  [<ffffffff810d5a1e>] ? put_task_stack+0x15e/0x190
> [ 2594.333214]  [<ffffffff810fd1f0>] ? kthread_park+0x60/0x60
> [ 2594.333214]  [<ffffffff81e7156a>] ret_from_fork+0x2a/0x40
> 

Re: [BUG] xfs/109 crashed 2k block size reflink enabled XFS

[Christoph Hellwig]

On Wed, Dec 07, 2016 at 10:35:03PM -0800, Darrick J. Wong wrote:
> I bet that assert is a result of the btree insert failing to find a new
> block to expand into.  I've felt for a while that we ought to yell ENOSPC
> louder when this happens, since I've hit it numerous times and grumbled
> about it not being obvious that we ran out of space.

Heh.  Took me a while to figure out what caused it last night as well.

> Anyway, XFS_AG_RESV_AGFL only gets a reservation if rmapbt=1 (or if you
> added an additional reservation after dinner), so if you're running
> reflink only then it's not surprising that it still runs out of space,
> since reflink=1 only reserves RESV_METADATA space.

I'm not running reflink only - this is the testcase from Eryu with
reflink and rmpbt for now.

But at that point I didn't add RESV_METADATA to xfs_bmbt_alloc_block.
With that one liner added xfs/109 seems to be doing fine so far, and
I've had it running for a few hours already today.  Note that this
is still without actually reserving additional block in
xfs_ag_resv_init, which is probably needed.