zfsonlinux/zfs — Issue #520: Adjusting zfs_vdev_aggregation_limit caused lockup, corrupt pool
Author: akorn
Created: 2012-01-08 00:00:25+00:00
State: open

Hi,

as part of my experiment to test the robustness of zfsonlinux, I raised zfs_vdev_aggregation_limit to 1048576 (from the default 131072) by echoing that value into /sys/module/zfs/parameters/zfs_vdev_aggregation_limit.

A few seconds later the box locked up and likely kernel panicked, because it rebooted.

After the reboot, my pool was in the following state:

pool: tank
state: UNAVAIL
status: One or more devices could not be used because the label is missing
or invalid. There are insufficient replicas for the pool to continue
functioning.
action: Destroy and re-create the pool from
a backup source.
see: http://zfsonlinux.org/msg/ZFS-8000-5E
scan: none requested
config:

NAME STATE READ WRITE CKSUM
tank UNAVAIL 0 0 0 insufficient replicas
raidz2-0 UNAVAIL 0 0 0 insufficient replicas
sdc UNAVAIL 0 0 0 corrupted data
sdd UNAVAIL 0 0 0 corrupted data
sde FAULTED 0 0 0 corrupted data
sdf FAULTED 0 0 0 corrupted data
sdg FAULTED 0 0 0 corrupted data
logs
zfs_zil ONLINE 0 0 0

The write cache on the drives had been disabled.

I suspect there is no way to recover from this state (which is "fine", it wasn't a live system).

Unfortunately, I wasn't able to capture the kernel message, if any.

The last interesting bit from the kernel log was logged about an hour earlier:

Jan 7 22:12:05 jayhawk kernel: SLUB: Unable to allocate memory on node -1 (gfp=0x20)
Jan 7 22:12:05 jayhawk kernel: cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
Jan 7 22:12:05 jayhawk kernel: node 0: slabs: 583, objs: 9328, free: 0
Jan 7 22:12:05 jayhawk kernel: arc_reclaim: page allocation failure: order:0, mode:0x4020
Jan 7 22:12:05 jayhawk kernel: Pid: 1906, comm: arc_reclaim Tainted: P 3.1.6-vs2.3.2.5-newjayhawk #4
Jan 7 22:12:05 jayhawk kernel: Call Trace:
Jan 7 22:12:05 jayhawk kernel: [] warn_alloc_failed+0xe6/0x140
Jan 7 22:12:05 jayhawk kernel: [] __alloc_pages_nodemask+0x5df/0x800
Jan 7 22:12:05 jayhawk kernel: [] alloc_pages_current+0x99/0x100
Jan 7 22:12:05 jayhawk kernel: [] new_slab+0x2a9/0x2c0
Jan 7 22:12:05 jayhawk kernel: [] __slab_alloc+0x2ce/0x3fe
Jan 7 22:12:05 jayhawk kernel: [] ? __netdev_alloc_skb+0x1f/0x40
Jan 7 22:12:05 jayhawk kernel: [] ? __alloc_skb+0x7e/0x220
Jan 7 22:12:05 jayhawk kernel: [] __kmalloc_node_track_caller+0x84/0x1a0
Jan 7 22:12:05 jayhawk kernel: [] ? __alloc_skb+0x4a/0x220
Jan 7 22:12:05 jayhawk kernel: [] ? __netdev_alloc_skb+0x1f/0x40
Jan 7 22:12:05 jayhawk kernel: [] __alloc_skb+0x7e/0x220
Jan 7 22:12:05 jayhawk kernel: [] __netdev_alloc_skb+0x1f/0x40
Jan 7 22:12:05 jayhawk kernel: [] e1000_alloc_rx_buffers+0x1bf/0x2c0 [e1000e]
Jan 7 22:12:05 jayhawk kernel: [] ? napi_gro_receive+0xad/0xc0
Jan 7 22:12:05 jayhawk kernel: [] e1000_clean_rx_irq+0x329/0x420 [e1000e]
Jan 7 22:12:05 jayhawk kernel: [] e1000_clean+0xa7/0x2a0 [e1000e]
Jan 7 22:12:05 jayhawk kernel: [] net_rx_action+0x12c/0x270
Jan 7 22:12:05 jayhawk kernel: [] __do_softirq+0xa0/0x200
Jan 7 22:12:05 jayhawk kernel: [] ? _raw_spin_lock+0x9/0x10
Jan 7 22:12:05 jayhawk kernel: [] ? handle_irq_event+0x54/0x70
Jan 7 22:12:05 jayhawk kernel: [] call_softirq+0x1c/0x30
Jan 7 22:12:05 jayhawk kernel: [] do_softirq+0x65/0xa0
Jan 7 22:12:05 jayhawk kernel: [] irq_exit+0x86/0xa0
Jan 7 22:12:05 jayhawk kernel: [] do_IRQ+0x5e/0xd0
Jan 7 22:12:05 jayhawk kernel: [] common_interrupt+0x6e/0x6e
Jan 7 22:12:05 jayhawk kernel: [] ? l2arc_read_done+0x220/0x220 [zfs]
Jan 7 22:12:05 jayhawk kernel: [] ? buf_dest+0x10/0x90 [zfs]
Jan 7 22:12:05 jayhawk kernel: [] spl_slab_reclaim+0x1a9/0x270 [spl]
Jan 7 22:12:05 jayhawk kernel: [] spl_kmem_cache_reap_now+0x47/0x60 [spl]
Jan 7 22:12:05 jayhawk kernel: [] __spl_kmem_cache_generic_shrinker.isra.10+0x64/0xa0 [spl]
Jan 7 22:12:05 jayhawk kernel: [] spl_kmem_reap+0x20/0x30 [spl]
Jan 7 22:12:05 jayhawk kernel: [] arc_kmem_reap_now+0x8e/0x110 [zfs]
Jan 7 22:12:05 jayhawk kernel: [] arc_reclaim_thread+0x6f/0x150 [zfs]
Jan 7 22:12:05 jayhawk kernel: [] ? arc_shrinker_func+0xd0/0xd0 [zfs]
Jan 7 22:12:05 jayhawk kernel: [] thread_generic_wrapper+0x73/0x90 [spl]
Jan 7 22:12:05 jayhawk kernel: [] ? __thread_create+0x160/0x160 [spl]
Jan 7 22:12:05 jayhawk kernel: [] kthread+0x87/0x90
Jan 7 22:12:05 jayhawk kernel: [] kernel_thread_helper+0x4/0x10
Jan 7 22:12:05 jayhawk kernel: [] ? flush_kthread_worker+0xa0/0xa0
Jan 7 22:12:05 jayhawk kernel: [] ? gs_change+0x13/0x13
Jan 7 22:12:05 jayhawk kernel: Mem-Info:
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA per-cpu:
Jan 7 22:12:05 jayhawk kernel: CPU 0: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 1: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 2: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 3: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 4: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 5: hi: 0, btch: 1 usd: 0
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA32 per-cpu:
Jan 7 22:12:05 jayhawk kernel: CPU 0: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 1: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 2: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 3: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 4: hi: 186, btch: 31 usd: 163
Jan 7 22:12:05 jayhawk kernel: CPU 5: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: Node 0 Normal per-cpu:
Jan 7 22:12:05 jayhawk kernel: CPU 0: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 1: hi: 186, btch: 31 usd: 107
Jan 7 22:12:05 jayhawk kernel: CPU 2: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: CPU 3: hi: 186, btch: 31 usd: 90
Jan 7 22:12:05 jayhawk kernel: CPU 4: hi: 186, btch: 31 usd: 162
Jan 7 22:12:05 jayhawk kernel: CPU 5: hi: 186, btch: 31 usd: 0
Jan 7 22:12:05 jayhawk kernel: active_anon:170738 inactive_anon:23028 isolated_anon:0
Jan 7 22:12:05 jayhawk kernel: active_file:107137 inactive_file:192920 isolated_file:0
Jan 7 22:12:05 jayhawk kernel: unevictable:516 dirty:5 writeback:0 unstable:0
Jan 7 22:12:05 jayhawk kernel: free:7978 slab_reclaimable:544352 slab_unreclaimable:427758
Jan 7 22:12:05 jayhawk kernel: mapped:1827 shmem:146 pagetables:1360 bounce:0
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA free:8084kB min:60kB low:72kB high:88kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15628kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:0kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Jan 7 22:12:05 jayhawk kernel: lowmem_reserve[]: 0 3502 16102 16102
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA32 free:9220kB min:14684kB low:18352kB high:22024kB active_anon:101156kB inactive_anon:24076kB active_file:36596kB inactive_file:269076kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:3586880kB mlocked:0kB dirty:4kB writeback:0kB mapped:28kB shmem:0kB slab_reclaimable:594536kB slab_unreclaimable:306060kB kernel_stack:72kB pagetables:144kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:16 all_unreclaimable? no
Jan 7 22:12:05 jayhawk kernel: lowmem_reserve[]: 0 0 12600 12600
Jan 7 22:12:05 jayhawk kernel: Node 0 Normal free:16592kB min:52832kB low:66040kB high:79248kB active_anon:581992kB inactive_anon:68036kB active_file:391952kB inactive_file:500468kB unevictable:2064kB isolated(anon):0kB isolated(file):0kB present:12902400kB mlocked:2064kB dirty:16kB writeback:0kB mapped:7280kB shmem:584kB slab_reclaimable:1582676kB slab_unreclaimable:1404972kB kernel_stack:4224kB pagetables:5296kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Jan 7 22:12:05 jayhawk kernel: lowmem_reserve[]: 0 0 0 0
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA: 1*4kB 0*8kB 1*16kB 0*32kB 0*64kB 1*128kB 1*256kB 1*512kB 1*1024kB 1*2048kB 1*4096kB = 8084kB
Jan 7 22:12:05 jayhawk kernel: Node 0 DMA32: 568*4kB 252*8kB 171*16kB 93*32kB 7*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 10448kB
Jan 7 22:12:05 jayhawk kernel: Node 0 Normal: 3007*4kB 476*8kB 122*16kB 14*32kB 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 18236kB
Jan 7 22:12:05 jayhawk kernel: 303055 total pagecache pages
Jan 7 22:12:05 jayhawk kernel: 3506 pages in swap cache
Jan 7 22:12:05 jayhawk kernel: Swap cache stats: add 1677496, delete 1673990, find 677188/741654
Jan 7 22:12:05 jayhawk kernel: Free swap = 3849660kB
Jan 7 22:12:05 jayhawk kernel: Total swap = 4194300kB
Jan 7 22:12:05 jayhawk kernel: 4194288 pages RAM
Jan 7 22:12:05 jayhawk kernel: 101818 pages reserved
Jan 7 22:12:05 jayhawk kernel: 291975 pages shared
Jan 7 22:12:05 jayhawk kernel: 2368120 pages non-shared
Jan 7 22:12:05 jayhawk kernel: SLUB: Unable to allocate memory on node -1 (gfp=0x20)
Jan 7 22:12:05 jayhawk kernel: cache: kmalloc-2048, object size: 2048, buffer size: 2048, default order: 3, min order: 0
Jan 7 22:12:05 jayhawk kernel: node 0: slabs: 583, objs: 9328, free: 0