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

Kernel error "task zfs:pid blocked for more than 120 seconds" #7691

Closed
simos opened this issue Jul 9, 2018 · 10 comments
Closed

Kernel error "task zfs:pid blocked for more than 120 seconds" #7691

simos opened this issue Jul 9, 2018 · 10 comments

Comments

@simos
Copy link

simos commented Jul 9, 2018

System information

Type Version/Name
Distribution Name Ubuntu
Distribution Version 18.04
Linux Kernel 4.15.0-20-generic
Architecture amd64
ZFS Version v0.7.5-1ubuntu13
SPL Version v0.7.5-1ubuntu1

Describe the problem you're observing

I am using LXD containers that are configured to use a ZFS storage backend.
I create many containers using a benchmark tool, which probably stresses the use of ZFS.
In two out of four attempts, I got

[  725.970508] INFO: task lxd:4455 blocked for more than 120 seconds.
[  725.976730]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  725.983551] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  725.991624] INFO: task txg_sync:4202 blocked for more than 120 seconds.
[  725.998264]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.005071] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.013313] INFO: task lxd:99919 blocked for more than 120 seconds.
[  726.019609]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.026418] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.034560] INFO: task zfs:100513 blocked for more than 120 seconds.
[  726.040936]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.047746] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.055791] INFO: task zfs:100584 blocked for more than 120 seconds.
[  726.062170]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.068979] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.

Describe how to reproduce the problem

  1. Start an Ubuntu 18.04 LTS server.
  2. Install LXD if not already installed.
sudo apt update
sudo apt install lxd lxd-client lxd-tools zfsutils-linux
  1. Configure LXD with sudo lxd init. When prompted for the storage backend, select ZFS and specify an empty disk.
$ sudo lxd init
Would you like to use LXD clustering? (yes/no) [default=no]: 
 Do you want to configure a new storage pool? (yes/no) [default=yes]: 
 Name of the new storage pool [default=default]: 
 Name of the storage backend to use (dir, zfs) [default=zfs]: 
 Create a new ZFS pool? (yes/no) [default=yes]: 
 Would you like to use an existing block device? (yes/no) [default=no]: yes
 Path to the existing block device: /dev/sdb
 Would you like to connect to a MAAS server? (yes/no) [default=no]: 
 Would you like to create a new local network bridge? (yes/no) [default=yes]: no
 Would you like to configure LXD to use an existing bridge or host interface? (yes/no) [default=no]: no
 Would you like LXD to be available over the network? (yes/no) [default=no]: 
 Would you like stale cached images to be updated automatically? (yes/no) [default=yes] 
 Would you like a YAML "lxd init" preseed to be printed? (yes/no) [default=no]: 
  1. Now run the following to launch 48 containers in batches of 12.
lxd-benchmark launch --count 48 --parallel 12

In two out of four attempts, I got the kernel errors.

I also tried

echo 1 >/sys/module/spl/parameters/spl_taskq_kick

but did not manage to continue.

Include any warning/errors/backtraces from the system logs

dmesg output

[  725.970508] INFO: task lxd:4455 blocked for more than 120 seconds.
[  725.976730]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  725.983551] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  725.991408] lxd             D    0  4455      1 0x00000000
[  725.991412] Call Trace:
[  725.991424]  __schedule+0x297/0x8b0
[  725.991428]  schedule+0x2c/0x80
[  725.991429]  rwsem_down_write_failed+0x162/0x360
[  725.991460]  ? dbuf_rele_and_unlock+0x1a8/0x4b0 [zfs]
[  725.991465]  call_rwsem_down_write_failed+0x17/0x30
[  725.991468]  ? call_rwsem_down_write_failed+0x17/0x30
[  725.991469]  down_write+0x2d/0x40
[  725.991472]  grab_super+0x30/0x90
[  725.991501]  ? zpl_create+0x160/0x160 [zfs]
[  725.991504]  sget_userns+0x91/0x490
[  725.991507]  ? get_anon_bdev+0x100/0x100
[  725.991534]  ? zpl_create+0x160/0x160 [zfs]
[  725.991537]  sget+0x7d/0xa0
[  725.991540]  ? get_anon_bdev+0x100/0x100
[  725.991567]  zpl_mount+0xa8/0x160 [zfs]
[  725.991570]  mount_fs+0x37/0x150
[  725.991574]  vfs_kern_mount.part.23+0x5d/0x110
[  725.991576]  do_mount+0x5ed/0xce0
[  725.991577]  ? copy_mount_options+0x2c/0x220
[  725.991578]  SyS_mount+0x98/0xe0
[  725.991582]  do_syscall_64+0x73/0x130
[  725.991583]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  725.991585] RIP: 0033:0x4dbd5a
[  725.991586] RSP: 002b:000000c428be6890 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5
[  725.991588] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004dbd5a
[  725.991589] RDX: 000000c421a04b7c RSI: 000000c426f94f40 RDI: 000000c4274ceaa0
[  725.991590] RBP: 000000c428be6930 R08: 000000c425521a90 R09: 0000000000000000
[  725.991590] R10: 0000000000000000 R11: 0000000000000206 R12: ffffffffffffffff
[  725.991591] R13: 000000000000003e R14: 000000000000003d R15: 0000000000000080
[  725.991624] INFO: task txg_sync:4202 blocked for more than 120 seconds.
[  725.998264]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.005071] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.012928] txg_sync        D    0  4202      2 0x80000000
[  726.012930] Call Trace:
[  726.012933]  __schedule+0x297/0x8b0
[  726.012939]  schedule+0x2c/0x80
[  726.012945]  cv_wait_common+0x11e/0x140 [spl]
[  726.012948]  ? wait_woken+0x80/0x80
[  726.012954]  __cv_wait+0x15/0x20 [spl]
[  726.012981]  rrw_enter_write+0x3c/0xa0 [zfs]
[  726.013006]  rrw_enter+0x13/0x20 [zfs]
[  726.013033]  spa_sync+0x7c9/0xd80 [zfs]
[  726.013062]  txg_sync_thread+0x2cd/0x4a0 [zfs]
[  726.013089]  ? txg_quiesce_thread+0x3d0/0x3d0 [zfs]
[  726.013093]  thread_generic_wrapper+0x74/0x90 [spl]
[  726.013098]  kthread+0x121/0x140
[  726.013101]  ? __thread_exit+0x20/0x20 [spl]
[  726.013103]  ? kthread_create_worker_on_cpu+0x70/0x70
[  726.013104]  ret_from_fork+0x22/0x40
[  726.013313] INFO: task lxd:99919 blocked for more than 120 seconds.
[  726.019609]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.026418] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.034272] lxd             D    0 99919  99626 0x00000000
[  726.034274] Call Trace:
[  726.034277]  __schedule+0x297/0x8b0
[  726.034283]  ? __wake_up_common+0x73/0x130
[  726.034286]  schedule+0x2c/0x80
[  726.034290]  cv_wait_common+0x11e/0x140 [spl]
[  726.034293]  ? wait_woken+0x80/0x80
[  726.034297]  __cv_wait+0x15/0x20 [spl]
[  726.034322]  txg_wait_synced+0xdd/0x130 [zfs]
[  726.034349]  zil_create+0x249/0x300 [zfs]
[  726.034376]  zil_commit_writer+0x6d1/0x7c0 [zfs]
[  726.034401]  zil_commit.part.14+0x93/0x100 [zfs]
[  726.034429]  zil_commit+0x17/0x20 [zfs]
[  726.034457]  zfs_sync+0x6e/0xb0 [zfs]
[  726.034484]  zpl_sync_fs+0x50/0x80 [zfs]
[  726.034490]  __sync_filesystem+0x33/0x60
[  726.034493]  sync_filesystem+0x39/0x40
[  726.034495]  generic_shutdown_super+0x27/0x120
[  726.034496]  kill_anon_super+0x12/0x20
[  726.034518]  zpl_kill_sb+0x1a/0x20 [zfs]
[  726.034524]  deactivate_locked_super+0x48/0x80
[  726.034529]  deactivate_super+0x40/0x60
[  726.034532]  cleanup_mnt+0x3f/0x80
[  726.034534]  __cleanup_mnt+0x12/0x20
[  726.034535]  task_work_run+0x9d/0xc0
[  726.034537]  exit_to_usermode_loop+0xc0/0xd0
[  726.034539]  do_syscall_64+0x115/0x130
[  726.034542]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  726.034550] RIP: 0033:0x7fb553b3e8c7
[  726.034551] RSP: 002b:00007fff426c5388 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
[  726.034553] RAX: 0000000000000000 RBX: 000000000000000f RCX: 00007fb553b3e8c7
[  726.034553] RDX: 00007fb55476eb9f RSI: 0000000000000002 RDI: 00007fb554770b6b
[  726.034554] RBP: 000000000000000c R08: 0000000000000000 R09: 00007fb553b8ae67
[  726.034555] R10: 0000000000084000 R11: 0000000000000246 R12: 00007fff426c64a0
[  726.034555] R13: 0000000003176690 R14: 0000000003177810 R15: 00000000031741f0
[  726.034560] INFO: task zfs:100513 blocked for more than 120 seconds.
[  726.040936]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.047746] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.055600] zfs             D    0 100513   2626 0x00000000
[  726.055602] Call Trace:
[  726.055606]  __schedule+0x297/0x8b0
[  726.055609]  schedule+0x2c/0x80
[  726.055613]  cv_wait_common+0x11e/0x140 [spl]
[  726.055615]  ? wait_woken+0x80/0x80
[  726.055619]  __cv_wait+0x15/0x20 [spl]
[  726.055642]  rrw_enter_read_impl+0x4e/0x160 [zfs]
[  726.055666]  rrw_enter+0x1c/0x20 [zfs]
[  726.055691]  dsl_pool_hold+0x5a/0x80 [zfs]
[  726.055713]  dmu_objset_hold+0x33/0xa0 [zfs]
[  726.055740]  zfs_ioc_objset_stats+0x32/0xa0 [zfs]
[  726.055766]  zfsdev_ioctl+0x1e0/0x610 [zfs]
[  726.055771]  do_vfs_ioctl+0xa8/0x630
[  726.055774]  ? handle_mm_fault+0xb1/0x1f0
[  726.055776]  ? __do_page_fault+0x270/0x4d0
[  726.055777]  SyS_ioctl+0x79/0x90
[  726.055779]  do_syscall_64+0x73/0x130
[  726.055781]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  726.055782] RIP: 0033:0x7fd4adc795d7
[  726.055782] RSP: 002b:00007ffe356b8718 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  726.055783] RAX: ffffffffffffffda RBX: 00007ffe356b8740 RCX: 00007fd4adc795d7
[  726.055784] RDX: 00007ffe356b8740 RSI: 0000000000005a12 RDI: 0000000000000003
[  726.055785] RBP: 000055632e278660 R08: 000000000000ffff R09: 00007fd4adcd1ed0
[  726.055785] R10: 2f746c7561666564 R11: 0000000000000246 R12: 000055632e278660
[  726.055788] R13: 00007ffe356beec0 R14: 00007fd4af1756e0 R15: 00007ffe356bbe30
[  726.055791] INFO: task zfs:100584 blocked for more than 120 seconds.
[  726.062170]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  726.068979] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  726.076835] zfs             D    0 100584  15513 0x00000000
[  726.076837] Call Trace:
[  726.076840]  __schedule+0x297/0x8b0
[  726.076845]  schedule+0x2c/0x80
[  726.076851]  cv_wait_common+0x11e/0x140 [spl]
[  726.076854]  ? wait_woken+0x80/0x80
[  726.076859]  __cv_wait+0x15/0x20 [spl]
[  726.076881]  rrw_enter_read_impl+0x4e/0x160 [zfs]
[  726.076905]  rrw_enter+0x1c/0x20 [zfs]
[  726.076929]  dsl_pool_hold+0x5a/0x80 [zfs]
[  726.076951]  dmu_objset_hold+0x33/0xa0 [zfs]
[  726.076977]  zfs_ioc_objset_stats+0x32/0xa0 [zfs]
[  726.077001]  zfsdev_ioctl+0x1e0/0x610 [zfs]
[  726.077005]  do_vfs_ioctl+0xa8/0x630
[  726.077006]  ? handle_mm_fault+0xb1/0x1f0
[  726.077008]  ? __do_page_fault+0x270/0x4d0
[  726.077010]  SyS_ioctl+0x79/0x90
[  726.077011]  do_syscall_64+0x73/0x130
[  726.077013]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  726.077014] RIP: 0033:0x7fc2734075d7
[  726.077014] RSP: 002b:00007fff653a4b08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  726.077015] RAX: ffffffffffffffda RBX: 00007fff653a4b30 RCX: 00007fc2734075d7
[  726.077016] RDX: 00007fff653a4b30 RSI: 0000000000005a12 RDI: 0000000000000003
[  726.077017] RBP: 000055f3576e9660 R08: 000000000000ffff R09: 00007fc27345fed0
[  726.077017] R10: 2f746c7561666564 R11: 0000000000000246 R12: 000055f3576e9660
[  726.077018] R13: 00007fff653aaec0 R14: 00007fc2749036e0 R15: 00007fff653a8220
[  846.801124] INFO: task lxd:4455 blocked for more than 120 seconds.
[  846.807352]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  846.814170] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.822028] lxd             D    0  4455      1 0x00000000
[  846.822031] Call Trace:
[  846.822042]  __schedule+0x297/0x8b0
[  846.822045]  schedule+0x2c/0x80
[  846.822047]  rwsem_down_write_failed+0x162/0x360
[  846.822078]  ? dbuf_rele_and_unlock+0x1a8/0x4b0 [zfs]
[  846.822083]  call_rwsem_down_write_failed+0x17/0x30
[  846.822086]  ? call_rwsem_down_write_failed+0x17/0x30
[  846.822087]  down_write+0x2d/0x40
[  846.822091]  grab_super+0x30/0x90
[  846.822118]  ? zpl_create+0x160/0x160 [zfs]
[  846.822121]  sget_userns+0x91/0x490
[  846.822123]  ? get_anon_bdev+0x100/0x100
[  846.822150]  ? zpl_create+0x160/0x160 [zfs]
[  846.822153]  sget+0x7d/0xa0
[  846.822156]  ? get_anon_bdev+0x100/0x100
[  846.822181]  zpl_mount+0xa8/0x160 [zfs]
[  846.822183]  mount_fs+0x37/0x150
[  846.822188]  vfs_kern_mount.part.23+0x5d/0x110
[  846.822189]  do_mount+0x5ed/0xce0
[  846.822190]  ? copy_mount_options+0x2c/0x220
[  846.822192]  SyS_mount+0x98/0xe0
[  846.822195]  do_syscall_64+0x73/0x130
[  846.822196]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  846.822198] RIP: 0033:0x4dbd5a
[  846.822199] RSP: 002b:000000c428be6890 EFLAGS: 00000206 ORIG_RAX: 00000000000000a5
[  846.822201] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00000000004dbd5a
[  846.822203] RDX: 000000c421a04b7c RSI: 000000c426f94f40 RDI: 000000c4274ceaa0
[  846.822205] RBP: 000000c428be6930 R08: 000000c425521a90 R09: 0000000000000000
[  846.822206] R10: 0000000000000000 R11: 0000000000000206 R12: ffffffffffffffff
[  846.822206] R13: 000000000000003e R14: 000000000000003d R15: 0000000000000080
[  846.822239] INFO: task txg_sync:4202 blocked for more than 120 seconds.
[  846.828882]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  846.835692] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.843549] txg_sync        D    0  4202      2 0x80000000
[  846.843551] Call Trace:
[  846.843554]  __schedule+0x297/0x8b0
[  846.843560]  schedule+0x2c/0x80
[  846.843566]  cv_wait_common+0x11e/0x140 [spl]
[  846.843570]  ? wait_woken+0x80/0x80
[  846.843574]  __cv_wait+0x15/0x20 [spl]
[  846.843603]  rrw_enter_write+0x3c/0xa0 [zfs]
[  846.843629]  rrw_enter+0x13/0x20 [zfs]
[  846.843654]  spa_sync+0x7c9/0xd80 [zfs]
[  846.843682]  txg_sync_thread+0x2cd/0x4a0 [zfs]
[  846.843708]  ? txg_quiesce_thread+0x3d0/0x3d0 [zfs]
[  846.843713]  thread_generic_wrapper+0x74/0x90 [spl]
[  846.843717]  kthread+0x121/0x140
[  846.843720]  ? __thread_exit+0x20/0x20 [spl]
[  846.843721]  ? kthread_create_worker_on_cpu+0x70/0x70
[  846.843723]  ret_from_fork+0x22/0x40
[  846.843931] INFO: task lxd:99919 blocked for more than 120 seconds.
[  846.850227]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  846.857040] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.864892] lxd             D    0 99919  99626 0x00000000
[  846.864894] Call Trace:
[  846.864897]  __schedule+0x297/0x8b0
[  846.864903]  ? __wake_up_common+0x73/0x130
[  846.864906]  schedule+0x2c/0x80
[  846.864910]  cv_wait_common+0x11e/0x140 [spl]
[  846.864912]  ? wait_woken+0x80/0x80
[  846.864917]  __cv_wait+0x15/0x20 [spl]
[  846.864942]  txg_wait_synced+0xdd/0x130 [zfs]
[  846.864971]  zil_create+0x249/0x300 [zfs]
[  846.864998]  zil_commit_writer+0x6d1/0x7c0 [zfs]
[  846.865023]  zil_commit.part.14+0x93/0x100 [zfs]
[  846.865051]  zil_commit+0x17/0x20 [zfs]
[  846.865080]  zfs_sync+0x6e/0xb0 [zfs]
[  846.865107]  zpl_sync_fs+0x50/0x80 [zfs]
[  846.865111]  __sync_filesystem+0x33/0x60
[  846.865113]  sync_filesystem+0x39/0x40
[  846.865114]  generic_shutdown_super+0x27/0x120
[  846.865116]  kill_anon_super+0x12/0x20
[  846.865138]  zpl_kill_sb+0x1a/0x20 [zfs]
[  846.865140]  deactivate_locked_super+0x48/0x80
[  846.865143]  deactivate_super+0x40/0x60
[  846.865145]  cleanup_mnt+0x3f/0x80
[  846.865147]  __cleanup_mnt+0x12/0x20
[  846.865148]  task_work_run+0x9d/0xc0
[  846.865150]  exit_to_usermode_loop+0xc0/0xd0
[  846.865152]  do_syscall_64+0x115/0x130
[  846.865153]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  846.865154] RIP: 0033:0x7fb553b3e8c7
[  846.865155] RSP: 002b:00007fff426c5388 EFLAGS: 00000246 ORIG_RAX: 00000000000000a6
[  846.865156] RAX: 0000000000000000 RBX: 000000000000000f RCX: 00007fb553b3e8c7
[  846.865158] RDX: 00007fb55476eb9f RSI: 0000000000000002 RDI: 00007fb554770b6b
[  846.865159] RBP: 000000000000000c R08: 0000000000000000 R09: 00007fb553b8ae67
[  846.865162] R10: 0000000000084000 R11: 0000000000000246 R12: 00007fff426c64a0
[  846.865162] R13: 0000000003176690 R14: 0000000003177810 R15: 00000000031741f0
[  846.865167] INFO: task zfs:100513 blocked for more than 120 seconds.
[  846.871546]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  846.878357] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.886214] zfs             D    0 100513   2626 0x00000000
[  846.886215] Call Trace:
[  846.886218]  __schedule+0x297/0x8b0
[  846.886223]  schedule+0x2c/0x80
[  846.886230]  cv_wait_common+0x11e/0x140 [spl]
[  846.886232]  ? wait_woken+0x80/0x80
[  846.886237]  __cv_wait+0x15/0x20 [spl]
[  846.886261]  rrw_enter_read_impl+0x4e/0x160 [zfs]
[  846.886284]  rrw_enter+0x1c/0x20 [zfs]
[  846.886309]  dsl_pool_hold+0x5a/0x80 [zfs]
[  846.886331]  dmu_objset_hold+0x33/0xa0 [zfs]
[  846.886357]  zfs_ioc_objset_stats+0x32/0xa0 [zfs]
[  846.886383]  zfsdev_ioctl+0x1e0/0x610 [zfs]
[  846.886388]  do_vfs_ioctl+0xa8/0x630
[  846.886391]  ? handle_mm_fault+0xb1/0x1f0
[  846.886394]  ? __do_page_fault+0x270/0x4d0
[  846.886396]  SyS_ioctl+0x79/0x90
[  846.886397]  do_syscall_64+0x73/0x130
[  846.886399]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  846.886400] RIP: 0033:0x7fd4adc795d7
[  846.886402] RSP: 002b:00007ffe356b8718 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  846.886405] RAX: ffffffffffffffda RBX: 00007ffe356b8740 RCX: 00007fd4adc795d7
[  846.886406] RDX: 00007ffe356b8740 RSI: 0000000000005a12 RDI: 0000000000000003
[  846.886406] RBP: 000055632e278660 R08: 000000000000ffff R09: 00007fd4adcd1ed0
[  846.886407] R10: 2f746c7561666564 R11: 0000000000000246 R12: 000055632e278660
[  846.886408] R13: 00007ffe356beec0 R14: 00007fd4af1756e0 R15: 00007ffe356bbe30
[  846.886410] INFO: task zfs:100584 blocked for more than 120 seconds.
[  846.892790]       Tainted: P           O     4.15.0-20-generic #21-Ubuntu
[  846.899598] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  846.907454] zfs             D    0 100584  15513 0x00000000
[  846.907456] Call Trace:
[  846.907459]  __schedule+0x297/0x8b0
[  846.907465]  schedule+0x2c/0x80
[  846.907470]  cv_wait_common+0x11e/0x140 [spl]
[  846.907471]  ? wait_woken+0x80/0x80
[  846.907477]  __cv_wait+0x15/0x20 [spl]
[  846.907499]  rrw_enter_read_impl+0x4e/0x160 [zfs]
[  846.907523]  rrw_enter+0x1c/0x20 [zfs]
[  846.907547]  dsl_pool_hold+0x5a/0x80 [zfs]
[  846.907568]  dmu_objset_hold+0x33/0xa0 [zfs]
[  846.907594]  zfs_ioc_objset_stats+0x32/0xa0 [zfs]
[  846.907618]  zfsdev_ioctl+0x1e0/0x610 [zfs]
[  846.907622]  do_vfs_ioctl+0xa8/0x630
[  846.907624]  ? handle_mm_fault+0xb1/0x1f0
[  846.907625]  ? __do_page_fault+0x270/0x4d0
[  846.907627]  SyS_ioctl+0x79/0x90
[  846.907628]  do_syscall_64+0x73/0x130
[  846.907630]  entry_SYSCALL_64_after_hwframe+0x3d/0xa2
[  846.907631] RIP: 0033:0x7fc2734075d7
[  846.907631] RSP: 002b:00007fff653a4b08 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[  846.907633] RAX: ffffffffffffffda RBX: 00007fff653a4b30 RCX: 00007fc2734075d7
[  846.907633] RDX: 00007fff653a4b30 RSI: 0000000000005a12 RDI: 0000000000000003
[  846.907634] RBP: 000055f3576e9660 R08: 000000000000ffff R09: 00007fc27345fed0
[  846.907635] R10: 2f746c7561666564 R11: 0000000000000246 R12: 000055f3576e9660
[  846.907637] R13: 00007fff653aaec0 R14: 00007fc2749036e0 R15: 00007fff653a8220

Contents of "/proc/spl/kstat/zfs/arcstats"

13 1 0x01 96 4608 11300672527 1808059980062
name                            type data
hits                            4    44186496
misses                          4    1247761
demand_data_hits                4    3327097
demand_data_misses              4    17953
demand_metadata_hits            4    39832270
demand_metadata_misses          4    1076950
prefetch_data_hits              4    1357
prefetch_data_misses            4    23
prefetch_metadata_hits          4    1025772
prefetch_metadata_misses        4    152835
mru_hits                        4    18193851
mru_ghost_hits                  4    0
mfu_hits                        4    24976976
mfu_ghost_hits                  4    0
deleted                         4    10
mutex_miss                      4    0
access_skip                     4    68
evict_skip                      4    1
evict_not_enough                4    0
evict_l2_cached                 4    0
evict_l2_eligible               4    101376
evict_l2_ineligible             4    2048
evict_l2_skip                   4    0
hash_elements                   4    38683
hash_elements_max               4    57741
hash_collisions                 4    1520
hash_chains                     4    5
hash_chain_max                  4    1
p                               4    16815604736
c                               4    33631209472
c_min                           4    2101950592
c_max                           4    33631209472
size                            4    833199872
compressed_size                 4    286609408
uncompressed_size               4    831992320
overhead_size                   4    330568192
hdr_size                        4    14660144
data_size                       4    193579520
metadata_size                   4    423598080
dbuf_size                       4    46065424
dnode_size                      4    112384064
bonus_size                      4    42912640
anon_size                       4    36502016
anon_evictable_data             4    0
anon_evictable_metadata         4    0
mru_size                        4    310932480
mru_evictable_data              4    27623424
mru_evictable_metadata          4    136801792
mru_ghost_size                  4    0
mru_ghost_evictable_data        4    0
mru_ghost_evictable_metadata    4    0
mfu_size                        4    269743104
mfu_evictable_data              4    53612032
mfu_evictable_metadata          4    3195392
mfu_ghost_size                  4    0
mfu_ghost_evictable_data        4    0
mfu_ghost_evictable_metadata    4    0
l2_hits                         4    0
l2_misses                       4    0
l2_feeds                        4    0
l2_rw_clash                     4    0
l2_read_bytes                   4    0
l2_write_bytes                  4    0
l2_writes_sent                  4    0
l2_writes_done                  4    0
l2_writes_error                 4    0
l2_writes_lock_retry            4    0
l2_evict_lock_retry             4    0
l2_evict_reading                4    0
l2_evict_l1cached               4    0
l2_free_on_write                4    0
l2_abort_lowmem                 4    0
l2_cksum_bad                    4    0
l2_io_error                     4    0
l2_size                         4    0
l2_asize                        4    0
l2_hdr_size                     4    0
memory_throttle_count           4    0
memory_direct_count             4    0
memory_indirect_count           4    0
memory_all_bytes                4    67262418944
memory_free_bytes               4    57157578752
memory_available_bytes          3    56106606592
arc_no_grow                     4    0
arc_tempreserve                 4    0
arc_loaned_bytes                4    0
arc_prune                       4    0
arc_meta_used                   4    639620352
arc_meta_limit                  4    25223407104
arc_dnode_limit                 4    2522340710
arc_meta_max                    4    965175896
arc_meta_min                    4    16777216
sync_wait_for_async             4    168
demand_hit_predictive_prefetch  4    999
arc_need_free                   4    0
arc_sys_free                    4    1050975296

Command "slabtop -o"

 Active / Total Objects (% used)    : 28354235 / 29140626 (97.3%)
 Active / Total Slabs (% used)      : 382017 / 382017 (100.0%)
 Active / Total Caches (% used)     : 95 / 128 (74.2%)
 Active / Total Size (% used)       : 4580408.56K / 4743868.00K (96.6%)
 Minimum / Average / Maximum Object : 0.01K / 0.16K / 21.81K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
17206144 17204917   0%    0.03K 134423      128    537692K kmalloc-32             
1141392 966790   0%    0.19K  27176       42    217408K dentry                 
1114496 1004537   0%    0.06K  17414       64     69656K kmalloc-64             
1088192 1078186   0%    0.50K  17003       64    544096K kmalloc-512            
1038300 714247   0%    0.13K  17305       60    138440K kernfs_node_cache      
937536 931296   0%    0.25K  14649       64    234384K filp                   
684160 682244   0%    0.06K  10690       64     42760K pid                    
582099 569877   0%    0.59K  10983       53    351456K inode_cache            
520104 518529   0%    0.20K  13336       39    106688K vm_area_struct         
404334 388371   0%    0.09K   9627       42     38508K kmalloc-96             
342286 341596   0%    0.09K   7441       46     29764K anon_vma               
342016 338948   0%    0.25K   5344       64     85504K kmalloc-256            
277032 276822   0%    0.19K   6596       42     52768K cred_jar               
248352 241634   0%    0.66K   5174       48    165568K proc_inode_cache       
248320 233052   0%    0.01K    485      512      1940K kmalloc-8              
214984 143177   0%    0.57K   3839       56    122848K radix_tree_node        
@gmelikov
Copy link
Member

gmelikov commented Jul 9, 2018

Duplicate of #7659 ?

@simos
Copy link
Author

simos commented Jul 9, 2018

Indeed, it is a duplicate.

Duplicate of #7659

@stgraber
Copy link

stgraber commented Jul 9, 2018

@sforshee @ColinIanKing probably something to at least keep track of

@stgraber
Copy link

stgraber commented Jul 9, 2018

@simos do you know if a matching Launchpad bug report exists for this issue (would help with tracking the upstream fix and making sure it makes it to our kernel once resolved).

@ColinIanKing
Copy link
Contributor

Does setting 'spl_kmem_cache_slab_limit to 0' help?

behlendorf added a commit to behlendorf/zfs that referenced this issue Jul 9, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting user
namespaces.

```
-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting ON A
```

Signed-off-by: Brian Behlendorf <[email protected]>
Issue openzfs#7691
behlendorf added a commit to behlendorf/zfs that referenced this issue Jul 9, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

```
-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting ON A
```

Signed-off-by: Brian Behlendorf <[email protected]>
Issue openzfs#7691
@behlendorf behlendorf mentioned this issue Jul 9, 2018
13 tasks
@simos
Copy link
Author

simos commented Jul 9, 2018

@ColinIanKing I tried your workaround,

root@myserver:~# cat /sys/module/spl/parameters/spl_kmem_cache_slab_limit 
0

and I no longer get those deadlocks.

ubuntu@myserver:~$ lxd-benchmark init --count 60 --parallel 12
Test environment:
  Server backend: lxd
  Server version: 3.0.1
  Kernel: Linux
  Kernel architecture: x86_64
  Kernel version: 4.15.0-20-generic
  Storage backend: zfs
  Storage version: 0.7.5-1ubuntu13
  Container backend: lxc
  Container version: 3.0.1

Test variables:
  Container count: 60
  Container mode: unprivileged
  Startup mode: normal startup
  Image: ubuntu:
  Batches: 5
  Batch size: 12
  Remainder: 0

[Jul  9 18:40:17.931] Found image in local store: f2228450779fee27020d6024af587379b8f51062c32a335327f2b028c924bfa1
[Jul  9 18:40:17.931] Batch processing start
[Jul  9 18:40:23.636] Processed 12 containers in 5.704s (2.104/s)
[Jul  9 18:40:30.194] Processed 24 containers in 12.263s (1.957/s)
[Jul  9 18:40:46.549] Processed 48 containers in 28.617s (1.677/s)
[Jul  9 18:40:56.652] Batch processing completed in 38.721s

I am running now a bigger benchmark and it did not deadlock yet.
The performance of the container creation degrades over time, though.
For example,

[Jul  9 18:42:37.621] Processed 24 containers in 13.633s (1.760/s)
[Jul  9 18:42:57.610] Processed 48 containers in 33.623s (1.428/s)
[Jul  9 18:44:06.108] Processed 96 containers in 102.121s (0.940/s)
[Jul  9 18:50:04.460] Processed 192 containers in 460.472s (0.417/s)
(30 minutes/18000 seconds have passed and did not reach the next set of 384 containers).

I think this degradation issue is not related to the ZFS deadlocks.

@simos
Copy link
Author

simos commented Jul 9, 2018

@stgraber There are two related bug reports on Launchpad:

  1. Task (usually mongod) blocked more 120 seconds (lock-ups) in juju on lxc/lxd + zfs
  2. zfs hangs on mount/unmount

In both cases, the kernel call trace is similar to this bug report. And it's on Ubuntu 18.04.
In the first report, it mentions mongod appearing in the call trace. It does appear, but immediatelly next there is a call trace relating to zfs.
In the second report, it mentions that they managed to trigger the bug with simple manual lxc operations.

@fwaggle
Copy link

fwaggle commented Jul 10, 2018

@simos Not sure if you're working on the same sort of stuff I am, but your LXD benchmark degradation may be related to https://github.com/lxc/lxd/issues/4708

behlendorf added a commit to behlendorf/zfs that referenced this issue Jul 11, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Signed-off-by: Brian Behlendorf <[email protected]>
Issue openzfs#7691
behlendorf added a commit that referenced this issue Jul 11, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Reviewed by: Alek Pinchuk <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes #7598 
Closes #7659 
Closes #7691 
Closes #7693
@simos
Copy link
Author

simos commented Jul 13, 2018

@stgraber @ColinIanKing

This ZFS issue has been fixed in ZFS upstream.
I have done some stress-testing in LXD and could not reproduce this specific issue with the upstream ZFS.

The relevant Launchpad report for this is Bug #1773392 - zfs hangs on mount/unmount.

I believe that it's time for this ZFS fix to be added to the appropriate Ubuntu Linux kernels.

@ColinIanKing
Copy link
Contributor

This bug is being tracked by https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1781364

tonyhutter pushed a commit to tonyhutter/zfs that referenced this issue Aug 15, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Reviewed by: Alek Pinchuk <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes openzfs#7598 
Closes openzfs#7659 
Closes openzfs#7691 
Closes openzfs#7693
tonyhutter pushed a commit to tonyhutter/zfs that referenced this issue Aug 23, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Reviewed by: Alek Pinchuk <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes openzfs#7598 
Closes openzfs#7659 
Closes openzfs#7691 
Closes openzfs#7693
tonyhutter pushed a commit to tonyhutter/zfs that referenced this issue Aug 27, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Reviewed by: Alek Pinchuk <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes openzfs#7598 
Closes openzfs#7659 
Closes openzfs#7691 
Closes openzfs#7693
tonyhutter pushed a commit to tonyhutter/zfs that referenced this issue Sep 5, 2018
Commit 93b43af inadvertently introduced the following scenario which
can result in a deadlock.  This issue was most easily reproduced by
LXD containers using a ZFS storage backend but should be reproducible
under any workload which is frequently mounting and unmounting.

-- THREAD A --
spa_sync()
  spa_sync_upgrades()
    rrw_enter(&dp->dp_config_rwlock, RW_WRITER, FTAG); <- Waiting on B

-- THREAD B --
mount_fs()
  zpl_mount()
    zpl_mount_impl()
      dmu_objset_hold()
        dmu_objset_hold_flags()
          dsl_pool_hold()
            dsl_pool_config_enter()
              rrw_enter(&dp->dp_config_rwlock, RW_READER, tag);
    sget()
      sget_userns()
        grab_super()
          down_write(&s->s_umount); <- Waiting on C

-- THREAD C --
cleanup_mnt()
  deactivate_super()
    down_write(&s->s_umount);
    deactivate_locked_super()
      zpl_kill_sb()
        kill_anon_super()
          generic_shutdown_super()
            sync_filesystem()
              zpl_sync_fs()
                zfs_sync()
                  zil_commit()
                    txg_wait_synced() <- Waiting on A

Reviewed by: Alek Pinchuk <[email protected]>
Signed-off-by: Brian Behlendorf <[email protected]>
Closes openzfs#7598 
Closes openzfs#7659 
Closes openzfs#7691 
Closes openzfs#7693
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants