Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

extreme delays when running zpool import -FX #1128

Closed
micia opened this issue Dec 4, 2012 · 7 comments
Closed

extreme delays when running zpool import -FX #1128

micia opened this issue Dec 4, 2012 · 7 comments
Labels
Type: Documentation Indicates a requested change to the documentation
Milestone

Comments

@micia
Copy link

micia commented Dec 4, 2012

Due to a power outage I've been forced to try some recovery tool to restore my ZFS pool.
The ZFS pool, named rpool, is located in the /dev/sda disk, which is entirely formatted with ZFS, it contains the root for my installation (Sabayon 10 amd64, kernel 3.6).
These operations have been performed in live mode, on a netbook with limited amount of RAM (1GB) and no swap at all.

Output for importing the rpool ZFS pool was:

zpool import -fF -R /mnt/sabayon rpool
cannot import 'rpool': I/O error
    Destroy and re-create the pool from
    a backup source.

My first attempt has been the -F option to recover the pool, output from:
zpool import -nfF -R /mnt/sabayon rpool
was none, it simply executed the command and returned me to the prompt, running the command without the n option wasn't successful:

zpool import -fF -R /mnt/sabayon rpool
cannot import 'rpool': I/O error
    Destroy and re-create the pool from
    a backup source.

My next attempt has been adding the -X option to the command, running:

zpool import -nfFX -R /mnt/sabayon rpool

This operation hanged for about 40 minutes before completing.
Dmesg output was:

[ 4667.944296] zpool: page allocation failure: order:5, mode:0x4030
[ 4667.944317] Pid: 14960, comm: zpool Tainted: P         C O 3.5.0-sabayon #1
[ 4667.944325] Call Trace:
[ 4667.944354]  [<ffffffff8109741a>] warn_alloc_failed+0x110/0x125
[ 4667.944374]  [<ffffffff817fbb2d>] ? __alloc_pages_direct_compact+0xb2/0x194
[ 4667.944390]  [<ffffffff810658a0>] ? on_each_cpu_mask+0x38/0x42
[ 4667.944407]  [<ffffffff81099f19>] __alloc_pages_nodemask+0x714/0x76a
[ 4667.944429]  [<ffffffff810c3789>] alloc_pages_current+0xcd/0xee
[ 4667.944445]  [<ffffffff81096cf5>] __get_free_pages+0x9/0x37
[ 4667.944459]  [<ffffffff810ca493>] __kmalloc+0x36/0xe7
[ 4667.944517]  [<ffffffffa02db46e>] spl_kmem_cache_alloc+0x503/0xa22 [spl]
[ 4667.944667]  [<ffffffffa03c71c5>] ? vdev_mirror_map_free+0x1d/0x1d [zfs]
[ 4667.944683]  [<ffffffff8180b99f>] ? mutex_lock+0x11/0x32
[ 4667.944701]  [<ffffffff81042169>] ? abort_exclusive_wait+0x89/0x89
[ 4667.944857]  [<ffffffffa03f4a20>] zio_data_buf_alloc+0x1d/0x1f [zfs]
[ 4667.944992]  [<ffffffffa03b0ad3>] spa_load_verify_cb+0x35/0x8d [zfs]
[ 4667.945107]  [<ffffffffa038c3f4>] traverse_visitbp+0x124/0x49a [zfs]
[ 4667.945297]  [<ffffffffa03f6054>] ? zio_nowait+0xd5/0xfd [zfs]
[ 4667.945400]  [<ffffffffa0379819>] ? arc_buf_remove_ref+0xbd/0xbd [zfs]
[ 4667.945516]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.945691]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.945862]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4667.946001]  [<ffffffffa038c5c4>] traverse_visitbp+0x2f4/0x49a [zfs]
[ 4667.946118]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946266]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946383]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946500]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946615]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946731]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4667.946850]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4667.946988]  [<ffffffffa038c65f>] traverse_visitbp+0x38f/0x49a [zfs]
[ 4667.947102]  [<ffffffffa038c973>] traverse_impl+0x209/0x2ba [zfs]
[ 4667.947240]  [<ffffffffa038ca56>] traverse_dataset+0x32/0x34 [zfs]
[ 4667.947351]  [<ffffffffa038cde0>] traverse_pool+0x210/0x293 [zfs]
[ 4667.947522]  [<ffffffffa03f546c>] ? zio_create+0x336/0x348 [zfs]
[ 4667.947660]  [<ffffffffa03b0a9e>] ? spa_error_entry_compare+0x22/0x22 [zfs]
[ 4667.947823]  [<ffffffffa03fdb8b>] spa_load_verify+0x6e/0x1ca [zfs]
[ 4667.947958]  [<ffffffffa03b63cd>] spa_load+0xff0/0x123e [zfs]
[ 4667.948100]  [<ffffffffa03b3779>] ? spa_activate+0x251/0x274 [zfs]
[ 4667.948267]  [<ffffffffa03b676a>] spa_load_best+0x14f/0x1bd [zfs]
[ 4667.948404]  [<ffffffffa03b6e48>] spa_import+0x16a/0x5b4 [zfs]
[ 4667.948615]  [<ffffffffa03dac64>] zfs_ioc_pool_import+0xb4/0x106 [zfs]
[ 4667.948763]  [<ffffffffa03de635>] zfsdev_ioctl+0x107/0x160 [zfs]
[ 4667.948783]  [<ffffffff810e81a4>] do_vfs_ioctl+0x444/0x485
[ 4667.948798]  [<ffffffff810efeaf>] ? alloc_fd+0x6d/0xfc
[ 4667.948813]  [<ffffffff810c9efd>] ? kmem_cache_free+0x15/0x8c
[ 4667.948824]  [<ffffffff810e8236>] sys_ioctl+0x51/0x77
[ 4667.948836]  [<ffffffff8180dee6>] system_call_fastpath+0x1a/0x1f
[ 4667.948840] Mem-Info:
[ 4667.948853] Node 0 DMA per-cpu:
[ 4667.948873] CPU    0: hi:    0, btch:   1 usd:   0
[ 4667.948883] CPU    1: hi:    0, btch:   1 usd:   0
[ 4667.948893] CPU    2: hi:    0, btch:   1 usd:   0
[ 4667.948904] CPU    3: hi:    0, btch:   1 usd:   0
[ 4667.948912] Node 0 DMA32 per-cpu:
[ 4667.948930] CPU    0: hi:  186, btch:  31 usd:  10
[ 4667.948938] CPU    1: hi:  186, btch:  31 usd: 159
[ 4667.948949] CPU    2: hi:  186, btch:  31 usd:   0
[ 4667.948959] CPU    3: hi:  186, btch:  31 usd:   0
[ 4667.948982] active_anon:42415 inactive_anon:2481 isolated_anon:0
[ 4667.948982]  active_file:3763 inactive_file:6800 isolated_file:0
[ 4667.948982]  unevictable:0 dirty:0 writeback:0 unstable:0
[ 4667.948982]  free:18440 slab_reclaimable:3352 slab_unreclaimable:5800
[ 4667.948982]  mapped:3995 shmem:3089 pagetables:3289 bounce:0
[ 4667.948991] Node 0 DMA free:4268kB min:688kB low:860kB high:1032kB active_anon:2036kB inactive_anon:12kB active_file:1440kB inactive_file:2572kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:224kB slab_unreclaimable:236kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4667.949060] lowmem_reserve[]: 0 981 981 981
[ 4667.949072] Node 0 DMA32 free:69492kB min:44364kB low:55452kB high:66544kB active_anon:167624kB inactive_anon:9912kB active_file:13612kB inactive_file:24628kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1004624kB mlocked:0kB dirty:0kB writeback:0kB mapped:14988kB shmem:12332kB slab_reclaimable:13184kB slab_unreclaimable:22964kB kernel_stack:2712kB pagetables:13040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:1 all_unreclaimable? no
[ 4667.949108] lowmem_reserve[]: 0 0 0 0
[ 4667.949137] Node 0 DMA: 87*4kB 112*8kB 87*16kB 27*32kB 4*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 4268kB
[ 4667.949222] Node 0 DMA32: 371*4kB 1619*8kB 3223*16kB 64*32kB 4*64kB 0*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 69588kB
[ 4667.949292] 13667 total pagecache pages
[ 4667.949296] 0 pages in swap cache
[ 4667.949303] Swap cache stats: add 0, delete 0, find 0/0
[ 4667.949307] Free swap  = 0kB
[ 4667.949312] Total swap = 0kB
[ 4667.965046] 259808 pages RAM
[ 4667.965056] 8395 pages reserved
[ 4667.965062] 35498 pages shared
[ 4667.965068] 224752 pages non-shared
[ 4668.515348] zpool: page allocation failure: order:5, mode:0x4030
[ 4668.515368] Pid: 14960, comm: zpool Tainted: P         C O 3.5.0-sabayon #1
[ 4668.515376] Call Trace:
[ 4668.515404]  [<ffffffff8109741a>] warn_alloc_failed+0x110/0x125
[ 4668.515424]  [<ffffffff817fbb2d>] ? __alloc_pages_direct_compact+0xb2/0x194
[ 4668.515440]  [<ffffffff810658a0>] ? on_each_cpu_mask+0x38/0x42
[ 4668.515457]  [<ffffffff81099f19>] __alloc_pages_nodemask+0x714/0x76a
[ 4668.515478]  [<ffffffff810c3789>] alloc_pages_current+0xcd/0xee
[ 4668.515495]  [<ffffffff81096cf5>] __get_free_pages+0x9/0x37
[ 4668.515509]  [<ffffffff810ca493>] __kmalloc+0x36/0xe7
[ 4668.515571]  [<ffffffffa02db46e>] spl_kmem_cache_alloc+0x503/0xa22 [spl]
[ 4668.515589]  [<ffffffff81042169>] ? abort_exclusive_wait+0x89/0x89
[ 4668.515748]  [<ffffffffa03f44e7>] zio_buf_alloc+0x1d/0x1f [zfs]
[ 4668.515891]  [<ffffffffa03c70c2>] vdev_mirror_io_start+0x230/0x316 [zfs]
[ 4668.515906]  [<ffffffff8180b99f>] ? mutex_lock+0x11/0x32
[ 4668.516047]  [<ffffffffa03bc39f>] ? spa_config_enter+0xbc/0xd8 [zfs]
[ 4668.516244]  [<ffffffffa03f5c73>] zio_vdev_io_start+0x4a/0x225 [zfs]
[ 4668.516399]  [<ffffffffa03f6054>] zio_nowait+0xd5/0xfd [zfs]
[ 4668.516538]  [<ffffffffa03b0b1e>] spa_load_verify_cb+0x80/0x8d [zfs]
[ 4668.516655]  [<ffffffffa038c3f4>] traverse_visitbp+0x124/0x49a [zfs]
[ 4668.516818]  [<ffffffffa03f6054>] ? zio_nowait+0xd5/0xfd [zfs]
[ 4668.516940]  [<ffffffffa0379819>] ? arc_buf_remove_ref+0xbd/0xbd [zfs]
[ 4668.517093]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.517262]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.517448]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4668.517640]  [<ffffffffa038c5c4>] traverse_visitbp+0x2f4/0x49a [zfs]
[ 4668.517839]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.517998]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.518143]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.518313]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.518464]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.518615]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4668.518761]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4668.518933]  [<ffffffffa038c65f>] traverse_visitbp+0x38f/0x49a [zfs]
[ 4668.519076]  [<ffffffffa038c973>] traverse_impl+0x209/0x2ba [zfs]
[ 4668.519232]  [<ffffffffa038ca56>] traverse_dataset+0x32/0x34 [zfs]
[ 4668.519305]  [<ffffffffa038cde0>] traverse_pool+0x210/0x293 [zfs]
[ 4668.519398]  [<ffffffffa03f546c>] ? zio_create+0x336/0x348 [zfs]
[ 4668.519480]  [<ffffffffa03b0a9e>] ? spa_error_entry_compare+0x22/0x22 [zfs]
[ 4668.519569]  [<ffffffffa03fdb8b>] spa_load_verify+0x6e/0x1ca [zfs]
[ 4668.519677]  [<ffffffffa03b63cd>] spa_load+0xff0/0x123e [zfs]
[ 4668.519764]  [<ffffffffa03b3779>] ? spa_activate+0x251/0x274 [zfs]
[ 4668.519849]  [<ffffffffa03b676a>] spa_load_best+0x14f/0x1bd [zfs]
[ 4668.519928]  [<ffffffffa03b6e48>] spa_import+0x16a/0x5b4 [zfs]
[ 4668.520014]  [<ffffffffa03dac64>] zfs_ioc_pool_import+0xb4/0x106 [zfs]
[ 4668.520103]  [<ffffffffa03de635>] zfsdev_ioctl+0x107/0x160 [zfs]
[ 4668.520130]  [<ffffffff810e81a4>] do_vfs_ioctl+0x444/0x485
[ 4668.520138]  [<ffffffff810efeaf>] ? alloc_fd+0x6d/0xfc
[ 4668.520147]  [<ffffffff810c9efd>] ? kmem_cache_free+0x15/0x8c
[ 4668.520159]  [<ffffffff810e8236>] sys_ioctl+0x51/0x77
[ 4668.520173]  [<ffffffff8180dee6>] system_call_fastpath+0x1a/0x1f
[ 4668.520177] Mem-Info:
[ 4668.520180] Node 0 DMA per-cpu:
[ 4668.520190] CPU    0: hi:    0, btch:   1 usd:   0
[ 4668.520196] CPU    1: hi:    0, btch:   1 usd:   0
[ 4668.520201] CPU    2: hi:    0, btch:   1 usd:   0
[ 4668.520206] CPU    3: hi:    0, btch:   1 usd:   0
[ 4668.520210] Node 0 DMA32 per-cpu:
[ 4668.520219] CPU    0: hi:  186, btch:  31 usd:   0
[ 4668.520225] CPU    1: hi:  186, btch:  31 usd:  64
[ 4668.520230] CPU    2: hi:  186, btch:  31 usd:   0
[ 4668.520236] CPU    3: hi:  186, btch:  31 usd:   0
[ 4668.520249] active_anon:42390 inactive_anon:2481 isolated_anon:0
[ 4668.520249]  active_file:3763 inactive_file:6118 isolated_file:0
[ 4668.520249]  unevictable:0 dirty:0 writeback:0 unstable:0
[ 4668.520249]  free:18156 slab_reclaimable:3352 slab_unreclaimable:5800
[ 4668.520249]  mapped:3995 shmem:3089 pagetables:3289 bounce:0
[ 4668.520259] Node 0 DMA free:4268kB min:688kB low:860kB high:1032kB active_anon:2036kB inactive_anon:12kB active_file:1440kB inactive_file:2572kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:224kB slab_unreclaimable:236kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4668.520281] lowmem_reserve[]: 0 981 981 981
[ 4668.520297] Node 0 DMA32 free:68356kB min:44364kB low:55452kB high:66544kB active_anon:167524kB inactive_anon:9912kB active_file:13612kB inactive_file:21900kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1004624kB mlocked:0kB dirty:0kB writeback:0kB mapped:14988kB shmem:12332kB slab_reclaimable:13184kB slab_unreclaimable:22964kB kernel_stack:2712kB pagetables:13040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4668.520319] lowmem_reserve[]: 0 0 0 0
[ 4668.520335] Node 0 DMA: 87*4kB 112*8kB 87*16kB 27*32kB 4*64kB 0*128kB 0*256kB 1*512kB 0*1024kB 0*2048kB 0*4096kB = 4268kB
[ 4668.520390] Node 0 DMA32: 309*4kB 1271*8kB 3243*16kB 114*32kB 5*64kB 1*128kB 0*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 68412kB
[ 4668.520416] 13038 total pagecache pages
[ 4668.520440] 0 pages in swap cache
[ 4668.520443] Swap cache stats: add 0, delete 0, find 0/0
[ 4668.520445] Free swap  = 0kB
[ 4668.520446] Total swap = 0kB
[ 4668.533203] 259808 pages RAM
[ 4668.533209] 8395 pages reserved
[ 4668.533212] 35407 pages shared
[ 4668.533214] 225244 pages non-shared
[ 4679.529167] zpool: page allocation failure: order:5, mode:0x4030
[ 4679.529190] Pid: 14960, comm: zpool Tainted: P         C O 3.5.0-sabayon #1
[ 4679.529199] Call Trace:
[ 4679.529232]  [<ffffffff8109741a>] warn_alloc_failed+0x110/0x125
[ 4679.529257]  [<ffffffff817fbb2d>] ? __alloc_pages_direct_compact+0xb2/0x194
[ 4679.529273]  [<ffffffff810658a0>] ? on_each_cpu_mask+0x38/0x42
[ 4679.529290]  [<ffffffff81099f19>] __alloc_pages_nodemask+0x714/0x76a
[ 4679.529311]  [<ffffffff810c3789>] alloc_pages_current+0xcd/0xee
[ 4679.529327]  [<ffffffff81096cf5>] __get_free_pages+0x9/0x37
[ 4679.529341]  [<ffffffff810ca493>] __kmalloc+0x36/0xe7
[ 4679.529398]  [<ffffffffa02db46e>] spl_kmem_cache_alloc+0x503/0xa22 [spl]
[ 4679.529416]  [<ffffffff81042169>] ? abort_exclusive_wait+0x89/0x89
[ 4679.529574]  [<ffffffffa03f44e7>] zio_buf_alloc+0x1d/0x1f [zfs]
[ 4679.529716]  [<ffffffffa03c70c2>] vdev_mirror_io_start+0x230/0x316 [zfs]
[ 4679.529731]  [<ffffffff8180b99f>] ? mutex_lock+0x11/0x32
[ 4679.529872]  [<ffffffffa03bc39f>] ? spa_config_enter+0xbc/0xd8 [zfs]
[ 4679.530027]  [<ffffffffa03f5c73>] zio_vdev_io_start+0x4a/0x225 [zfs]
[ 4679.530181]  [<ffffffffa03f6054>] zio_nowait+0xd5/0xfd [zfs]
[ 4679.530401]  [<ffffffffa03b0b1e>] spa_load_verify_cb+0x80/0x8d [zfs]
[ 4679.530557]  [<ffffffffa038c3f4>] traverse_visitbp+0x124/0x49a [zfs]
[ 4679.530747]  [<ffffffffa03f6054>] ? zio_nowait+0xd5/0xfd [zfs]
[ 4679.530887]  [<ffffffffa0379819>] ? arc_buf_remove_ref+0xbd/0xbd [zfs]
[ 4679.531047]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.531215]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.531238] spl_system_task: page allocation failure: order:5, mode:0x4030
[ 4679.531262] Pid: 5064, comm: spl_system_task Tainted: P         C O 3.5.0-sabayon #1
[ 4679.531278] Call Trace:
[ 4679.531323]  [<ffffffff8109741a>] warn_alloc_failed+0x110/0x125
[ 4679.531359]  [<ffffffff817fbb2d>] ? __alloc_pages_direct_compact+0xb2/0x194
[ 4679.531450]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.531468]  [<ffffffff810658a0>] ? on_each_cpu_mask+0x38/0x42
[ 4679.531484]  [<ffffffff81099f19>] __alloc_pages_nodemask+0x714/0x76a
[ 4679.531559]  [<ffffffffa038c5c4>] traverse_visitbp+0x2f4/0x49a [zfs]
[ 4679.531576]  [<ffffffff810c3789>] alloc_pages_current+0xcd/0xee
[ 4679.531589]  [<ffffffff81096cf5>] __get_free_pages+0x9/0x37
[ 4679.531655]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.531671]  [<ffffffff810ca493>] __kmalloc+0x36/0xe7
[ 4679.531741]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.531758]  [<ffffffffa02db46e>] spl_kmem_cache_alloc+0x503/0xa22 [spl]
[ 4679.531842]  [<ffffffffa03f6054>] ? zio_nowait+0xd5/0xfd [zfs]
[ 4679.531853]  [<ffffffff81042169>] ? abort_exclusive_wait+0x89/0x89
[ 4679.531938]  [<ffffffffa03f4a20>] zio_data_buf_alloc+0x1d/0x1f [zfs]
[ 4679.531989]  [<ffffffffa0378c80>] arc_get_data_buf+0x1a5/0x38e [zfs]
[ 4679.532064]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.532140]  [<ffffffffa03794cc>] arc_buf_alloc+0xa9/0xd7 [zfs]
[ 4679.532215]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.532297]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.532354]  [<ffffffffa037a0eb>] arc_read_nolock+0x232/0x620 [zfs]
[ 4679.532423]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.532479]  [<ffffffffa037a578>] arc_read+0x9f/0x13b [zfs]
[ 4679.532548]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.532612]  [<ffffffffa03a673e>] dsl_read+0x2c/0x2e [zfs]
[ 4679.532673]  [<ffffffffa038c65f>] traverse_visitbp+0x38f/0x49a [zfs]
[ 4679.532721]  [<ffffffffa038c2bf>] traverse_prefetcher+0xef/0x100 [zfs]
[ 4679.532784]  [<ffffffffa038c973>] traverse_impl+0x209/0x2ba [zfs]
[ 4679.532831]  [<ffffffffa038c3f4>] traverse_visitbp+0x124/0x49a [zfs]
[ 4679.532894]  [<ffffffffa038ca56>] traverse_dataset+0x32/0x34 [zfs]
[ 4679.532934]  [<ffffffffa0379819>] ? arc_buf_remove_ref+0xbd/0xbd [zfs]
[ 4679.532996]  [<ffffffffa038cde0>] traverse_pool+0x210/0x293 [zfs]
[ 4679.533043]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.533126]  [<ffffffffa03f546c>] ? zio_create+0x336/0x348 [zfs]
[ 4679.533176]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.533252]  [<ffffffffa03b0a9e>] ? spa_error_entry_compare+0x22/0x22 [zfs]
[ 4679.533298]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.533376]  [<ffffffffa03fdb8b>] spa_load_verify+0x6e/0x1ca [zfs]
[ 4679.533459]  [<ffffffffa03b63cd>] spa_load+0xff0/0x123e [zfs]
[ 4679.533503]  [<ffffffffa038c5c4>] traverse_visitbp+0x2f4/0x49a [zfs]
[ 4679.533564]  [<ffffffffa03b3779>] ? spa_activate+0x251/0x274 [zfs]
[ 4679.533625]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.533688]  [<ffffffffa03b676a>] spa_load_best+0x14f/0x1bd [zfs]
[ 4679.533747]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.533810]  [<ffffffffa03b6e48>] spa_import+0x16a/0x5b4 [zfs]
[ 4679.533874]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.533940]  [<ffffffffa03dac64>] zfs_ioc_pool_import+0xb4/0x106 [zfs]
[ 4679.533991]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.534046]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.534112]  [<ffffffffa03de635>] zfsdev_ioctl+0x107/0x160 [zfs]
[ 4679.534157]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.534172]  [<ffffffff810e81a4>] do_vfs_ioctl+0x444/0x485
[ 4679.534218]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.534225]  [<ffffffff810efeaf>] ? alloc_fd+0x6d/0xfc
[ 4679.534275]  [<ffffffffa038c65f>] traverse_visitbp+0x38f/0x49a [zfs]
[ 4679.534280]  [<ffffffff810c9efd>] ? kmem_cache_free+0x15/0x8c
[ 4679.534330]  [<ffffffffa038cb9f>] traverse_prefetch_thread+0x67/0x98 [zfs]
[ 4679.534334]  [<ffffffff810e8236>] sys_ioctl+0x51/0x77
[ 4679.534384]  [<ffffffffa038c1d0>] ? dmu_recv_end+0x1c7/0x1c7 [zfs]
[ 4679.534390]  [<ffffffff8180dee6>] system_call_fastpath+0x1a/0x1f
[ 4679.534395] Mem-Info:
[ 4679.534408]  [<ffffffffa02df35d>] taskq_thread+0x29d/0x4f6 [spl]
[ 4679.534409] Node 0 
[ 4679.534413] DMA per-cpu:
[ 4679.534423]  [<ffffffff8104b739>] ? try_to_wake_up+0x21b/0x21b
[ 4679.534426] CPU    0: hi:    0, btch:   1 usd:   0
[ 4679.534429] CPU    1: hi:    0, btch:   1 usd:   0
[ 4679.534443]  [<ffffffffa02df0c0>] ? task_done+0x109/0x109 [spl]
[ 4679.534446] CPU    2: hi:    0, btch:   1 usd:   0
[ 4679.534449] CPU    3: hi:    0, btch:   1 usd:   0
[ 4679.534458]  [<ffffffff81041ae9>] kthread+0x86/0x8e
[ 4679.534459] Node 0 DMA32 per-cpu:
[ 4679.534469]  [<ffffffff8180f314>] kernel_thread_helper+0x4/0x10
[ 4679.534472] CPU    0: hi:  186, btch:  31 usd:   0
[ 4679.534475] CPU    1: hi:  186, btch:  31 usd:   0
[ 4679.534484]  [<ffffffff81041a63>] ? kthread_freezable_should_stop+0x52/0x52
[ 4679.534487] CPU    2: hi:  186, btch:  31 usd:  28
[ 4679.534490] CPU    3: hi:  186, btch:  31 usd:   0
[ 4679.534497]  [<ffffffff8180f310>] ? gs_change+0xb/0xb
[ 4679.534508] active_anon:42428 inactive_anon:2484 isolated_anon:0
[ 4679.534508]  active_file:3895 inactive_file:3975 isolated_file:0
[ 4679.534508]  unevictable:0 dirty:0 writeback:0 unstable:0
[ 4679.534508]  free:18003 slab_reclaimable:3351 slab_unreclaimable:5800
[ 4679.534508]  mapped:3996 shmem:3093 pagetables:3289 bounce:0
[ 4679.534509] Mem-Info:
[ 4679.534513] Node 0 Node 0 DMA free:4392kB min:688kB low:860kB high:1032kB active_anon:2036kB inactive_anon:12kB active_file:1440kB inactive_file:2264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:224kB slab_unreclaimable:236kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.534530] DMA per-cpu:
[ 4679.534532] lowmem_reserve[]:CPU    0: hi:    0, btch:   1 usd:   0
[ 4679.534538]  0CPU    1: hi:    0, btch:   1 usd:   0
[ 4679.534544]  981CPU    2: hi:    0, btch:   1 usd:   0
[ 4679.534549]  981CPU    3: hi:    0, btch:   1 usd:   0
[ 4679.534553]  981Node 0 
[ 4679.534559] DMA32 per-cpu:
[ 4679.534563] Node 0 CPU    0: hi:  186, btch:  31 usd:   0
[ 4679.534580] DMA32 free:67620kB min:44364kB low:55452kB high:66544kB active_anon:167676kB inactive_anon:9924kB active_file:14140kB inactive_file:13636kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1004624kB mlocked:0kB dirty:0kB writeback:0kB mapped:14992kB shmem:12348kB slab_reclaimable:13180kB slab_unreclaimable:22964kB kernel_stack:2688kB pagetables:13040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.534583] CPU    1: hi:  186, btch:  31 usd:   0
[ 4679.534584] lowmem_reserve[]:CPU    2: hi:  186, btch:  31 usd:  28
[ 4679.534590]  0CPU    3: hi:  186, btch:  31 usd:   0
[ 4679.534602]  0active_anon:42428 inactive_anon:2484 isolated_anon:0
[ 4679.534610]  active_file:3895 inactive_file:3975 isolated_file:0
[ 4679.534610]  unevictable:0 dirty:0 writeback:0 unstable:0
[ 4679.534610]  free:18003 slab_reclaimable:3351 slab_unreclaimable:5800
[ 4679.534610]  mapped:3996 shmem:3093 pagetables:3289 bounce:0
[ 4679.534613]  0Node 0  0DMA free:4392kB min:688kB low:860kB high:1032kB active_anon:2036kB inactive_anon:12kB active_file:1440kB inactive_file:2264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:224kB slab_unreclaimable:236kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.534629] 
[ 4679.534630] lowmem_reserve[]:Node 0  0DMA:  9818*4kB  98137*8kB  98186*16kB 
[ 4679.534656] 32*32kB Node 0 6*64kB DMA32 free:67620kB min:44364kB low:55452kB high:66544kB active_anon:167676kB inactive_anon:9924kB active_file:14140kB inactive_file:13636kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1004624kB mlocked:0kB dirty:0kB writeback:0kB mapped:14992kB shmem:12348kB slab_reclaimable:13180kB slab_unreclaimable:22964kB kernel_stack:2688kB pagetables:13040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.534673] 0*128kB lowmem_reserve[]:1*256kB  00*512kB  01*1024kB  00*2048kB  00*4096kB 
[ 4679.534697] = 4392kB
[ 4679.534698] Node 0 Node 0 DMA: DMA32: 8*4kB 2066*4kB 37*8kB 493*8kB 86*16kB 3037*16kB 32*32kB 167*32kB 6*64kB 4*64kB 0*128kB 1*128kB 1*256kB 0*256kB 0*512kB 0*512kB 1*1024kB 1*1024kB 0*2048kB 0*2048kB 0*4096kB 0*4096kB = 4392kB
[ 4679.534768] = 67552kB
[ 4679.534769] Node 0 10919 total pagecache pages
[ 4679.534774] DMA32: 0 pages in swap cache
[ 4679.534779] 2066*4kB Swap cache stats: add 0, delete 0, find 0/0
[ 4679.534783] 493*8kB Free swap  = 0kB
[ 4679.534787] 3037*16kB Total swap = 0kB
[ 4679.534790] 167*32kB 4*64kB 1*128kB 0*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 67552kB
[ 4679.534815] 10919 total pagecache pages
[ 4679.534817] 0 pages in swap cache
[ 4679.534822] Swap cache stats: add 0, delete 0, find 0/0
[ 4679.534826] Free swap  = 0kB
[ 4679.534828] Total swap = 0kB
[ 4679.543503] 259808 pages RAM
[ 4679.543508] 8395 pages reserved
[ 4679.543511] 34957 pages shared
[ 4679.543514] 225884 pages non-shared
[ 4679.549467] zpool: page allocation failure: order:5, mode:0x4030
[ 4679.549480] Pid: 14960, comm: zpool Tainted: P         C O 3.5.0-sabayon #1
[ 4679.549485] Call Trace:
[ 4679.549503]  [<ffffffff8109741a>] warn_alloc_failed+0x110/0x125
[ 4679.549516]  [<ffffffff817fbb2d>] ? __alloc_pages_direct_compact+0xb2/0x194
[ 4679.549527]  [<ffffffff810658a0>] ? on_each_cpu_mask+0x38/0x42
[ 4679.549538]  [<ffffffff81099f19>] __alloc_pages_nodemask+0x714/0x76a
[ 4679.549552]  [<ffffffff810c3789>] alloc_pages_current+0xcd/0xee
[ 4679.549562]  [<ffffffff81096cf5>] __get_free_pages+0x9/0x37
[ 4679.549571]  [<ffffffff810ca493>] __kmalloc+0x36/0xe7
[ 4679.549618]  [<ffffffffa02db46e>] spl_kmem_cache_alloc+0x503/0xa22 [spl]
[ 4679.549630]  [<ffffffff81042169>] ? abort_exclusive_wait+0x89/0x89
[ 4679.549716]  [<ffffffffa03f44e7>] zio_buf_alloc+0x1d/0x1f [zfs]
[ 4679.549795]  [<ffffffffa03c70c2>] vdev_mirror_io_start+0x230/0x316 [zfs]
[ 4679.549807]  [<ffffffff8180b99f>] ? mutex_lock+0x11/0x32
[ 4679.549885]  [<ffffffffa03bc39f>] ? spa_config_enter+0xbc/0xd8 [zfs]
[ 4679.549970]  [<ffffffffa03f5c73>] zio_vdev_io_start+0x4a/0x225 [zfs]
[ 4679.550054]  [<ffffffffa03f6054>] zio_nowait+0xd5/0xfd [zfs]
[ 4679.550144]  [<ffffffffa03b0b1e>] spa_load_verify_cb+0x80/0x8d [zfs]
[ 4679.550217]  [<ffffffffa038c3f4>] traverse_visitbp+0x124/0x49a [zfs]
[ 4679.550298]  [<ffffffffa03f6054>] ? zio_nowait+0xd5/0xfd [zfs]
[ 4679.550352]  [<ffffffffa0379819>] ? arc_buf_remove_ref+0xbd/0xbd [zfs]
[ 4679.550412]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550467]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550528]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.550590]  [<ffffffffa038c5c4>] traverse_visitbp+0x2f4/0x49a [zfs]
[ 4679.550648]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550704]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550759]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550818]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550874]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550934]  [<ffffffffa038c4e7>] traverse_visitbp+0x217/0x49a [zfs]
[ 4679.550990]  [<ffffffffa038cacc>] traverse_dnode+0x74/0xe0 [zfs]
[ 4679.551117]  [<ffffffffa038c65f>] traverse_visitbp+0x38f/0x49a [zfs]
[ 4679.551176]  [<ffffffffa038c973>] traverse_impl+0x209/0x2ba [zfs]
[ 4679.551235]  [<ffffffffa038ca56>] traverse_dataset+0x32/0x34 [zfs]
[ 4679.551291]  [<ffffffffa038cde0>] traverse_pool+0x210/0x293 [zfs]
[ 4679.551378]  [<ffffffffa03f546c>] ? zio_create+0x336/0x348 [zfs]
[ 4679.551453]  [<ffffffffa03b0a9e>] ? spa_error_entry_compare+0x22/0x22 [zfs]
[ 4679.551531]  [<ffffffffa03fdb8b>] spa_load_verify+0x6e/0x1ca [zfs]
[ 4679.551599]  [<ffffffffa03b63cd>] spa_load+0xff0/0x123e [zfs]
[ 4679.551671]  [<ffffffffa03b3779>] ? spa_activate+0x251/0x274 [zfs]
[ 4679.551748]  [<ffffffffa03b676a>] spa_load_best+0x14f/0x1bd [zfs]
[ 4679.551824]  [<ffffffffa03b6e48>] spa_import+0x16a/0x5b4 [zfs]
[ 4679.551902]  [<ffffffffa03dac64>] zfs_ioc_pool_import+0xb4/0x106 [zfs]
[ 4679.551981]  [<ffffffffa03de635>] zfsdev_ioctl+0x107/0x160 [zfs]
[ 4679.551994]  [<ffffffff810e81a4>] do_vfs_ioctl+0x444/0x485
[ 4679.552001]  [<ffffffff810efeaf>] ? alloc_fd+0x6d/0xfc
[ 4679.552008]  [<ffffffff810c9efd>] ? kmem_cache_free+0x15/0x8c
[ 4679.552015]  [<ffffffff810e8236>] sys_ioctl+0x51/0x77
[ 4679.552050]  [<ffffffff8180dee6>] system_call_fastpath+0x1a/0x1f
[ 4679.552053] Mem-Info:
[ 4679.552056] Node 0 DMA per-cpu:
[ 4679.552061] CPU    0: hi:    0, btch:   1 usd:   0
[ 4679.552064] CPU    1: hi:    0, btch:   1 usd:   0
[ 4679.552067] CPU    2: hi:    0, btch:   1 usd:   0
[ 4679.552070] CPU    3: hi:    0, btch:   1 usd:   0
[ 4679.552072] Node 0 DMA32 per-cpu:
[ 4679.552077] CPU    0: hi:  186, btch:  31 usd:   0
[ 4679.552079] CPU    1: hi:  186, btch:  31 usd:   0
[ 4679.552082] CPU    2: hi:  186, btch:  31 usd:   0
[ 4679.552085] CPU    3: hi:  186, btch:  31 usd:   0
[ 4679.552096] active_anon:42428 inactive_anon:2484 isolated_anon:0
[ 4679.552096]  active_file:3895 inactive_file:3900 isolated_file:0
[ 4679.552096]  unevictable:0 dirty:0 writeback:0 unstable:0
[ 4679.552096]  free:18171 slab_reclaimable:3351 slab_unreclaimable:5800
[ 4679.552096]  mapped:3996 shmem:3093 pagetables:3289 bounce:0
[ 4679.552098] Node 0 DMA free:4392kB min:688kB low:860kB high:1032kB active_anon:2036kB inactive_anon:12kB active_file:1440kB inactive_file:2264kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15648kB mlocked:0kB dirty:0kB writeback:0kB mapped:992kB shmem:24kB slab_reclaimable:224kB slab_unreclaimable:236kB kernel_stack:8kB pagetables:116kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.552115] lowmem_reserve[]: 0 981 981 981
[ 4679.552121] Node 0 DMA32 free:68292kB min:44364kB low:55452kB high:66544kB active_anon:167676kB inactive_anon:9924kB active_file:14140kB inactive_file:13336kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:1004624kB mlocked:0kB dirty:0kB writeback:0kB mapped:14992kB shmem:12348kB slab_reclaimable:13180kB slab_unreclaimable:22964kB kernel_stack:2688kB pagetables:13040kB unstable:0kB bounce:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
[ 4679.552138] lowmem_reserve[]: 0 0 0 0
[ 4679.552144] Node 0 DMA: 8*4kB 37*8kB 86*16kB 32*32kB 6*64kB 0*128kB 1*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 4392kB
[ 4679.552162] Node 0 DMA32: 2077*4kB 500*8kB 3051*16kB 168*32kB 4*64kB 4*128kB 0*256kB 0*512kB 1*1024kB 0*2048kB 0*4096kB = 68292kB
[ 4679.552181] 10882 total pagecache pages
[ 4679.552183] 0 pages in swap cache
[ 4679.552186] Swap cache stats: add 0, delete 0, find 0/0
[ 4679.552187] Free swap  = 0kB
[ 4679.552189] Total swap = 0kB
[ 4679.552731] 259808 pages RAM
[ 4679.552733] 8395 pages reserved
[ 4679.552735] 34956 pages shared
[ 4679.552736] 225873 pages non-shared
[ 4679.561474] 259808 pages RAM
[ 4679.561481] 8395 pages reserved
[ 4679.561485] 34952 pages shared
[ 4679.561489] 226337 pages non-shared

Output of free -m during the "stall" condition was:
Mem: 982 858 123 0 5 43
-/+ buffers/cache: 809 172
Swap: 0 0 0

@behlendorf
Copy link
Contributor

@micia The delay is expected in your case. ZFS is basically attempting to rollback through previous TXGs until it finds a good one and this can take some time depending on how far back it needs to go. The more concerning issue is that this was required in the first place. Usually this sort of issue means your hardware isn't properly honoring cache flush commands.

As for the dmesg output that has been fixed in the latest ZoL source and is harmless. It will be fixed once Sabayon picks up the latest ZoL packages.

@ryao
Copy link
Contributor

ryao commented Dec 4, 2012

@behlendorf I pushed updated ZFS code into Sabayon's kernel source tree earlier today. It should be included with the next kernel update that the Sabayon developers do.

@micia
Copy link
Author

micia commented Dec 4, 2012

According to the zpool import -fFX -R /mnt/sabayon rpool output, there have been 30 seconds of lost transactions, the command still took the same amount of time to complete, if that's expected then there is no problem, what made me think that it could have been a bug is the dmesg output that is apparently a completely different issue.

By the way, wouldn't it be nice to include some documentation about the -X option (that did manage to get my system up and running again) in the man page?
It looks like a pretty important feature to me, but I had to make some research on the internet to find out about it, if I had to rely only on the man page, I couldn't have managed to recover my system.
Should I create a separate issue report about this?

@behlendorf
Copy link
Contributor

@micia It's undocumented because if your hardware is behaving correctly it should never be needed. That said, with us pushing ZFS in to Linux there's no avoiding it running on a wider variety of misbehaving hardware than ever before. So we probably should add the option to the man page with a nice description of why this shouldn't be needed, but if it is how to use it as a last resort.

@ryao
Copy link
Contributor

ryao commented Dec 5, 2012

According to @micia in IRC, he was removing a large quantity of files when the power outage occurred. It might be possible to reproduce his failure in a VM.

@voidzero
Copy link

I'm having similar problems and currently trying to recover two disks forming a mirrored pool. The original machine had memory errors so I am trying to recover on a different machine but with the same version numbers for most software.

So far the zpool import command does not help me. Even worse: when I look at vmstat -d, the counters do not add up, they stay at the same number.

Can I post dmesg output here? Should I open a new issue? I could really use some help, guys.

@dweeezil
Copy link
Contributor

@slacks42 I began an outline of an un-importable pool diagnostic procedure on the zfs-discuss mailing list which you can see at https://groups.google.com/a/zfsonlinux.org/d/msg/zfs-discuss/LuxsAqaK6AM/sQNz8mVohNMJ. Unfortunately, memory errors can be very toxic because the ZFS code is filled with a ton of asserts and other internal consistency checks.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Type: Documentation Indicates a requested change to the documentation
Projects
None yet
Development

No branches or pull requests

5 participants