zfsonlinux/zfs — Issue #477: System wedge/lock.
Author: Ryan-Weiss-ddn
Created: 2011-12-01 09:01:15+00:00
State: open

I just had a hard hang/lock I was running a scrub, while rsyncing over some files. network died, numlock, etc non responsive, Had to do an ATX power off.
Last events before the power off had 'z_wr_iss/0: page allocation failure. order:3, mode:0x4020' type messages - but I even had those when I was running zfs-fuse (but without crash): "zfs-fuse: page allocation failure. order:3, mode:0x4020"

This occurred with the up to date git version downloaded as zip files:
zfsonlinux-spl-spl-0.6.0-rc6-13-ge05bec8.zip
zfsonlinux-zfs-zfs-0.6.0-rc6-20-gb9c59ec.zip

ubuntu 11.04: 2.6.38-13-server #52-Ubuntu SMP Tue Nov 8 17:11:08 UTC 2011 x86_64 x86_64

zfs tests passed:
zconfig.sh -c
1 persistent zpool.cache Pass
2 scan disks for pools to import Pass
3 zpool import/export device Pass
4 zpool insmod/rmmod device Pass
5 zvol+ext3 volume Pass
6 zvol+ext2 snapshot Pass
7 zvol+ext2 clone Pass
8 zfs send/receive Pass
9 zpool events Pass
10 zpool add/remove vdev Pass

egrep '^Nov 30 23:42' kern.log|head -700
is here: http://pastebin.com/6DKqN4nB
subset here

$ egrep '^Nov 30 23:42' kern.log|head -70
Nov 30 23:42:49 r1501 kernel: [133589.275863] __alloc_pages_slowpath: 5571 callbacks suppressed
Nov 30 23:42:49 r1501 kernel: [133589.275871] z_wr_iss/0: page allocation failure. order:3, mode:0x4020
Nov 30 23:42:49 r1501 kernel: [133589.275879] Pid: 28631, comm: z_wr_iss/0 Tainted: P 2.6.38-13-server #52-Ubuntu
Nov 30 23:42:49 r1501 kernel: [133589.275885] Call Trace:
Nov 30 23:42:49 r1501 kernel: [133589.275889] [] ? __alloc_pages_nodemask+0x5f4/0x830
Nov 30 23:42:49 r1501 kernel: [133589.275914] [] ? kmalloc_large_node+0x6b/0xc0
Nov 30 23:42:49 r1501 kernel: [133589.275922] [] ? __kmalloc_node_track_caller+0x155/0x1a0
Nov 30 23:42:49 r1501 kernel: [133589.275940] [] ? rx_submit+0x3f/0x310 [asix]
Nov 30 23:42:49 r1501 kernel: [133589.275949] [] ? __alloc_skb+0x83/0x170
Nov 30 23:42:49 r1501 kernel: [133589.275959] [] ? rx_submit+0x3f/0x310 [asix]
Nov 30 23:42:49 r1501 kernel: [133589.275968] [] ? defer_bh+0xba/0xf0 [asix]
Nov 30 23:42:49 r1501 kernel: [133589.275978] [] ? rx_complete+0x238/0x2a0 [asix]
Nov 30 23:42:49 r1501 kernel: [133589.275987] [] ? usb_hcd_giveback_urb+0x64/0xe0
Nov 30 23:42:49 r1501 kernel: [133589.275996] [] ? ehci_urb_done+0xe2/0x120
Nov 30 23:42:49 r1501 kernel: [133589.276004] [] ? qh_completions+0x1f6/0x470
Nov 30 23:42:49 r1501 kernel: [133589.276013] [] ? scan_async+0x11b/0x1f0
Nov 30 23:42:49 r1501 kernel: [133589.276021] [] ? ehci_work+0x3b/0x80
Nov 30 23:42:49 r1501 kernel: [133589.276028] [] ? ehci_irq+0x1cc/0x240
Nov 30 23:42:49 r1501 kernel: [133589.276035] [] ? ftrace_call+0x5/0x2b
Nov 30 23:42:49 r1501 kernel: [133589.276043] [] ? usb_hcd_irq+0x3d/0x70
Nov 30 23:42:49 r1501 kernel: [133589.276051] [] ? handle_IRQ_event+0x54/0x180
Nov 30 23:42:49 r1501 kernel: [133589.276060] [] ? handle_fasteoi_irq+0x87/0x110
Nov 30 23:42:49 r1501 kernel: [133589.276068] [] ? handle_irq+0x22/0x40
Nov 30 23:42:49 r1501 kernel: [133589.276076] [] ? do_IRQ+0x5d/0xe0
Nov 30 23:42:49 r1501 kernel: [133589.276084] [] ? ret_from_intr+0x0/0x15
Nov 30 23:42:49 r1501 kernel: [133589.276089] [] ? mutex_unlock+0x0/0x20
Nov 30 23:42:49 r1501 kernel: [133589.276170] [] ? zio_add_child+0x100/0x120 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276213] [] ? zio_create+0x3dd/0x490 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276257] [] ? zio_vdev_child_io+0xb3/0xe0 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276299] [] ? vdev_raidz_child_done+0x0/0x30 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276344] [] ? vdev_raidz_io_start+0x602/0x6f0 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276387] [] ? vdev_raidz_child_done+0x0/0x30 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276432] [] ? zio_vdev_io_start+0xab/0x300 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276474] [] ? zio_nowait+0xb0/0x180 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276518] [] ? vdev_mirror_io_start+0x186/0x3d0 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276561] [] ? vdev_mirror_child_done+0x0/0x30 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276604] [] ? zio_vdev_io_start+0x237/0x300 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276648] [] ? zio_execute+0xb0/0x150 [zfs]
Nov 30 23:42:49 r1501 kernel: [133589.276655] [] ? ftrace_call+0x5/0x2b
Nov 30 23:42:49 r1501 kernel: [133589.276675] [] ? taskq_thread+0x1c0/0x390 [spl]
Nov 30 23:42:49 r1501 kernel: [133589.276684] [] ? default_wake_function+0x0/0x20
Nov 30 23:42:49 r1501 kernel: [133589.276697] [] ? taskq_thread+0x0/0x390 [spl]
Nov 30 23:42:49 r1501 kernel: [133589.276705] [] ? kthread+0x96/0xa0
Nov 30 23:42:49 r1501 kernel: [133589.276713] [] ? kernel_thread_helper+0x4/0x10
Nov 30 23:42:49 r1501 kernel: [133589.276722] [] ? kthread+0x0/0xa0
Nov 30 23:42:49 r1501 kernel: [133589.276729] [] ? kernel_thread_helper+0x0/0x10
Nov 30 23:42:49 r1501 kernel: [133589.276734] Mem-Info:
Nov 30 23:42:50 r1501 kernel: [133589.276737] Node 0 DMA per-cpu:
Nov 30 23:42:50 r1501 kernel: [133589.276743] CPU 0: hi: 0, btch: 1 usd: 0
Nov 30 23:42:50 r1501 kernel: [133589.276747] Node 0 DMA32 per-cpu:
Nov 30 23:42:50 r1501 kernel: [133589.276752] CPU 0: hi: 186, btch: 31 usd: 174
Nov 30 23:42:50 r1501 kernel: [133589.276761] active_anon:16830 inactive_anon:10513 isolated_anon:0
Nov 30 23:42:50 r1501 kernel: [133589.276764] active_file:21286 inactive_file:14619 isolated_file:0
Nov 30 23:42:50 r1501 kernel: [133589.276767] unevictable:0 dirty:7 writeback:0 unstable:0
Nov 30 23:42:50 r1501 kernel: [133589.276770] free:2485 slab_reclaimable:7502 slab_unreclaimable:8018
Nov 30 23:42:50 r1501 kernel: [133589.276774] mapped:3566 shmem:110 pagetables:1010 bounce:0
Nov 30 23:42:50 r1501 kernel: [133589.276779] Node 0 DMA free:5524kB min:52kB low:64kB high:76kB active_anon:0kB inactive_anon:56kB active_file:16kB inactive_file:80kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15676kB mlocked:0kB dirty:0kB writeback:0kB mapped:0kB shmem:0kB slab_reclaimable:36kB slab_unreclaimable:620kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov 30 23:42:50 r1501 kernel: [133589.276805] lowmem_reserve[]: 0 1371 1371 1371
Nov 30 23:42:50 r1501 kernel: [133589.276813] Node 0 DMA32 free:4416kB min:4708kB low:5884kB high:7060kB active_anon:67320kB inactive_anon:41996kB active_file:85128kB inactive_file:58396kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1404340kB mlocked:0kB dirty:28kB writeback:0kB mapped:14264kB shmem:440kB slab_reclaimable:29972kB slab_unreclaimable:31452kB kernel_stack:2304kB pagetables:4040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Nov 30 23:42:50 r1501 kernel: [133589.276840] lowmem_reserve[]: 0 0 0 0
Nov 30 23:42:50 r1501 kernel: [133589.276848] Node 0 DMA: 9*4kB 4*8kB 9*16kB 8*32kB 5*64kB 7*128kB 3*256kB 0*512kB 1*1024kB 1*2048kB 0*4096kB = 5524kB
Nov 30 23:42:50 r1501 kernel: [133589.276868] Node 0 DMA32: 844*4kB 68*8kB 15*16kB 0*32kB 0*64kB 0*128kB 1*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 4416kB
Nov 30 23:42:50 r1501 kernel: [133589.276888] 36070 total pagecache pages
Nov 30 23:42:50 r1501 kernel: [133589.276892] 55 pages in swap cache
Nov 30 23:42:50 r1501 kernel: [133589.276896] Swap cache stats: add 212, delete 157, find 405/415
Nov 30 23:42:50 r1501 kernel: [133589.276901] Free swap = 1951296kB
Nov 30 23:42:50 r1501 kernel: [133589.276904] Total swap = 1951740kB
Nov 30 23:42:50 r1501 kernel: [133589.280016] 360032 pages RAM
Nov 30 23:42:50 r1501 kernel: [133589.280016] 8052 pages reserved
Nov 30 23:42:50 r1501 kernel: [133589.280016] 33092 pages shared

Any thoughts?

Cheers,
Ryan