Open AlexOwen opened 5 years ago
prgwiz
commented
5 years ago We had these issues with Ubuntu 18.04 Have you tried: zfs_prefetch_disable=1 and maybe zfs_nocacheflush=1
I am not sure but running the rsync with "nice -n 19" may have helped.
We have not seen many issues with latest patches for Ubuntu Eoan.
c0d3z3r0
commented
5 years ago @BrainSlayer isn't that the same problem we had with #9034? o.O
BrainSlayer
commented
5 years ago looks identical, yes. but we triggered the memory allocation problems by wrong flags. here it might be a real out of memory problem which again triggers the endless loop in memory allocation procedure i love so much
Am 07.08.2019 um 22:29 schrieb Michael Niewöhner:
@BrainSlayer https://github.com/BrainSlayer isn't that the same problem we had with #9034 https://github.com/zfsonlinux/zfs/pull/9034? o.O
— You are receiving this because you were mentioned. Reply to this email directly, view it on GitHub https://github.com/zfsonlinux/zfs/issues/9130?email_source=notifications&email_token=AB2WNEYD5U2UTYU4LUQX6UDQDMWCXA5CNFSM4IJY3MZKYY3PNVWWK3TUL52HS4DFVREXG43VMVBW63LNMVXHJKTDN5WW2ZLOORPWSZGOD3ZTU3A#issuecomment-519256684, or mute the thread https://github.com/notifications/unsubscribe-auth/AB2WNE5CEJJPMOM7JBATEE3QDMWCXANCNFSM4IJY3MZA.
c0d3z3r0
commented
5 years ago which again triggers the endless loop in memory allocation procedure i love so much
which should be fixed by our patch; so maybe we even fix a very common, recurring problem - great!
pkramme
commented
4 years ago I may have the same problem, altough my hang appears when I delete many snapshots (>10000). Is this the same problem? RAIDZ1 on Ubuntu 18.04 LTS with HWE kernel (5.0.0-31-generic). If this is indeed the same problem, i can send you more information, because i still have 30000 snapshots i need to delete and everytime I try deleting large amounts, ZFS hangs. dmesg_zfs_hung_tasks_after_deleting_many_snapshots.log
HiFiPhile
commented
4 years ago Having the same problem while pools under heavy IO
| Type | Version/Name |
|---|---|
| Distribution Name | Proxmox |
| Distribution Version | 6.0-11 |
| Linux Kernel | 5.0.21-4-pve |
| Architecture | amd64 |
| ZFS Version | 0.8.2-pve2 |
| SPL Version | 0.8.2-pve2 |
CPU: Xeon E3-1285L V3
RAM: 32GB DDR3-1600 ECC
HBA: LSI9305-24iroot@pve:~# zpool status
pool: NAS
state: ONLINE
scan: scrub repaired 0B in 0 days 07:58:47 with 0 errors on Sun Nov 10 08:22:49 2019
config:
NAME STATE READ WRITE CKSUM
NAS ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
wwn-0x5000cca26bd9cc69 ONLINE 0 0 0
ata-HGST_HUH721010ALE600_7JJ3GG4C ONLINE 0 0 0
ata-HGST_HUH721010ALE600_7JJ535MC ONLINE 0 0 0
errors: No known data errors
pool: S860
state: ONLINE
scan: scrub repaired 0B in 0 days 00:06:37 with 0 errors on Sun Nov 10 00:30:44 2019
config:
NAME STATE READ WRITE CKSUM
S860 ONLINE 0 0 0
ata-Samsung_SSD_860_EVO_4TB_S3YPNB0KA00732Y ONLINE 0 0 0
ata-Samsung_SSD_860_EVO_4TB_S3YPNB0KA00919A ONLINE 0 0 0
errors: No known data errorstxg_sync hang during heavy IO, in my case during fio benchmark of NAS and S860 pool st the same time.
Run fio benchmark of both pools at the same time:
[global]
name=fio-seq-write
filename=fio-seq-write
rw=write
bs=256K
direct=0
numjobs=1
time_based=1
runtime=300
[file1]
size=50G
ioengine=libaio
iodepth=16[ 968.292727] INFO: task txg_sync:2130 blocked for more than 120 seconds.
[ 968.292762] Tainted: P 0 5.0.21-4-pve #1
[ 968.292784] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 968.292815] txg_sync D 0 2130 2 0x80000000
[ 968.292837] Call Trace:
[ 968.292855] __schedule+0x2d4/0x870
[ 968.292872] schedule+Ox2c/0x70
[ 968.292887] schedule_timeout+0x157/0x360
[ 968.292906] ? __next_timer_interrupt+OxdO/OxdO
[ 968.292925] io_schedule_timeout+Ox1e/Ox50
[ 968.292946] __cv_timedwait_common+Oxl2f/0x170 [spl]
[ 968.292968] ? wait_woken+0x80/0x80
[ 968.292985] __cv_timedwait_io+0x19/0x20 [spl]
[ 968.293049] zio_wait+Ox13a/0x280 [zfs]
[ 968.293067] ? _cond_resched+0x19/0x30
[ 968.293115] dsl_pool_sync+Oxdc/Ox4f0 [zfs]
[ 968.293168] spa_sync+0x5b2/Oxfc0 [zfs]
[ 968.293221] ? spa_txg_history_init_io+0x106/0x110 [zfs]
[ 968.293278] txg_sync_thread+0x2d9/0x4c0 [zfs]
[ 968.293331] ? txg_thread_exit.isra.11+0x60/0x60 [zfs]
[ 968.293355] thread_generic_wrapper+0x74/0x90 [spl]
[ 968.293376] kthread+Ox120/0x140
[ 968.293393] ? __thread_exit+0x20/0x20 [sell
[ 968.293410] __kthread_parkme+0x70/0x70
[ 968.293428] ret_from_fork+0x35/0x40
PrivatePuffin
commented
4 years ago I've seen the same issue and just like @BrainSlayer and @c0d3z3r0 it was due to low memory. In my case VM's with proxmox with not enough Memory (for its taste).
seanmikhaels
commented
4 years ago I have the same issue. A bandwidth limited rsync job at 12MB/s, or vm starting in virtual box triggers this and the entire file system freezes. Doesn't seem to be memory related nor CPU related as both stay low during transfers and file access. Disc IO also stays low.
OS - Debian Stretch Kernel - 4.19.0-0.bpo.6-amd64 ZFS Version - 0.8.2-1 Pool: 3 Drive RaidZ1 L2ARC : 80GB SSD Drive. CPU - AMD Athlon 240G System Memory: 32GB System Ram.
ov 13 11:23:32 nas kernel: [59329.141166] INFO: task txg_sync:1228 blocked for more than 120 seconds. Nov 13 11:23:32 nas kernel: [59329.141368] Tainted: P OE 4.19.0-0.bpo.6-amd64 #1 Debian 4.19.67-2+deb10u1~bpo9+1 Nov 13 11:23:32 nas kernel: [59329.141598] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. Nov 13 11:23:32 nas kernel: [59329.141827] txg_sync D 0 1228 2 0x80000000 Nov 13 11:23:32 nas kernel: [59329.141833] Call Trace: Nov 13 11:23:32 nas kernel: [59329.141846] ? schedule+0x3f5/0x880 Nov 13 11:23:32 nas kernel: [59329.141920] ? spa_taskq_dispatch_ent+0x85/0xc0 [zfs] Nov 13 11:23:32 nas kernel: [59329.141924] schedule+0x32/0x80 Nov 13 11:23:32 nas kernel: [59329.141927] schedule_timeout+0x16f/0x350 Nov 13 11:23:32 nas kernel: [59329.141931] ? next_timer_interrupt+0xc0/0xc0 Nov 13 11:23:32 nas kernel: [59329.141934] io_schedule_timeout+0x19/0x40 Nov 13 11:23:32 nas kernel: [59329.141942] cv_timedwait_common+0x122/0x160 [spl] Nov 13 11:23:32 nas kernel: [59329.141947] ? remove_wait_queue+0x60/0x60 Nov 13 11:23:32 nas kernel: [59329.142006] zio_wait+0x124/0x260 [zfs] Nov 13 11:23:32 nas kernel: [59329.142060] dsl_pool_sync+0x106/0x520 [zfs] Nov 13 11:23:32 nas kernel: [59329.142118] spa_sync+0x550/0xf90 [zfs] Nov 13 11:23:32 nas kernel: [59329.142177] ? spa_txg_history_init_io+0xfe/0x110 [zfs] Nov 13 11:23:32 nas kernel: [59329.142235] txg_sync_thread+0x291/0x450 [zfs] Nov 13 11:23:32 nas kernel: [59329.142331] ? txg_wait_open+0xd0/0xd0 [zfs] Nov 13 11:23:32 nas kernel: [59329.142350] thread_generic_wrapper+0x6f/0x80 [spl] Nov 13 11:23:32 nas kernel: [59329.142353] kthread+0xf8/0x130 Nov 13 11:23:32 nas kernel: [59329.142360] ? thread_exit+0x20/0x20 [spl] Nov 13 11:23:32 nas kernel: [59329.142361] ? kthread_create_worker_on_cpu+0x70/0x70 Nov 13 11:23:32 nas kernel: [59329.142364] ret_from_fork+0x22/0x40
avg-cpu: %user %nice %system %iowait %steal %idle 9.39 0.00 22.83 9.81 0.00 57.97
NAME STATE READ WRITE CKSUM zfspool ONLINE 0 0 0 raidz1-0 ONLINE 0 0 0 sde ONLINE 0 0 0 ata-ST4000VN000-1H4168_Z301425Y ONLINE 0 0 0 ata-ST4000DM005-2DP166_ZDH164PY ONLINE 0 0 0 logs sdf3 ONLINE 0 0 0
ZFS Subsystem Report Wed Nov 13 11:30:46 2019 ARC Summary: (HEALTHY) Memory Throttle Count: 0
ARC Misc: Deleted: 649.80k Mutex Misses: 21 Evict Skips: 12
ARC Size: 98.85% 15.43 GiB Target Size: (Adaptive) 100.00% 15.61 GiB Min Size (Hard Limit): 6.25% 998.92 MiB Max Size (High Water): 16:1 15.61 GiB
ARC Size Breakdown: Recently Used Cache Size: 43.61% 4.38 GiB Frequently Used Cache Size: 56.39% 5.66 GiB
ARC Hash Breakdown: Elements Max: 1.20M Elements Current: 89.82% 1.08M Collisions: 1.07M Chain Max: 5 Chains: 117.18k
ARC Total accesses: 497.41M Cache Hit Ratio: 99.73% 496.07M Cache Miss Ratio: 0.27% 1.34M Actual Hit Ratio: 99.73% 496.06M
Data Demand Efficiency: 99.17% 433.01k Data Prefetch Efficiency: 8.47% 2.87k
CACHE HITS BY CACHE LIST: Most Recently Used: 2.84% 14.08M Most Frequently Used: 97.16% 481.98M Most Recently Used Ghost: 0.05% 262.03k Most Frequently Used Ghost: 0.00% 11.54k
CACHE HITS BY DATA TYPE: Demand Data: 0.09% 429.42k Prefetch Data: 0.00% 243 Demand Metadata: 99.91% 495.63M Prefetch Metadata: 0.00% 15.26k
CACHE MISSES BY DATA TYPE: Demand Data: 0.27% 3.59k Prefetch Data: 0.20% 2.63k Demand Metadata: 82.28% 1.10M Prefetch Metadata: 17.26% 231.71k
PrivatePuffin
commented
4 years ago This might all be related to:
lassebm
commented
4 years ago I'm experiencing a similar issue, seen with ZFS packages from Ubuntu Eoan and packages built from ba434b18ec6bcedb9d9eb39fa234fbba55032381, containing the fix from #9583. The issue is seen on a mirrored pool with encrypted datasets, running on a Raspberry Pi 4B, 4 GB RAM, zfs_arc_max=536870912. The Pi is running various Docker workloads backed by the dockerd ZFS storage driver. The average free memory is around 1.5 GB.
[238407.538074] INFO: task z_wr_iss:1683 blocked for more than 120 seconds.
[238407.545147] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.552411] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.560642] z_wr_iss D 0 1683 2 0x00000028
[238407.560651] Call trace:
[238407.560665] __switch_to+0xf0/0x150
[238407.560671] __schedule+0x2cc/0x718
[238407.560675] schedule+0x3c/0xb8
[238407.560679] io_schedule+0x20/0x40
[238407.560685] rq_qos_wait+0x100/0x178
[238407.560690] wbt_wait+0xb4/0xf0
[238407.560694] __rq_qos_throttle+0x38/0x50
[238407.560699] blk_mq_make_request+0x120/0x5f8
[238407.560704] generic_make_request+0xb4/0x2d8
[238407.560708] submit_bio+0x44/0x1b0
[238407.560885] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238407.560992] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.561093] zio_nowait+0xd4/0x170 [zfs]
[238407.561193] vdev_queue_io+0x24c/0x268 [zfs]
[238407.561297] zio_vdev_io_start+0x94/0x2b8 [zfs]
[238407.561401] zio_nowait+0xd4/0x170 [zfs]
[238407.561502] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.561605] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.561707] zio_nowait+0xd4/0x170 [zfs]
[238407.561808] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.561907] zio_vdev_io_start+0x248/0x2b8 [zfs]
[238407.562012] zio_execute+0xac/0x110 [zfs]
[238407.562084] taskq_thread+0x304/0x580 [spl]
[238407.562097] kthread+0x104/0x130
[238407.562104] ret_from_fork+0x10/0x1c
[238407.562117] INFO: task z_wr_iss_h:1685 blocked for more than 120 seconds.
[238407.569281] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.576523] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.584745] z_wr_iss_h D 0 1685 2 0x00000028
[238407.584755] Call trace:
[238407.584768] __switch_to+0xf0/0x150
[238407.584775] __schedule+0x2cc/0x718
[238407.584779] schedule+0x3c/0xb8
[238407.584783] io_schedule+0x20/0x40
[238407.584789] rq_qos_wait+0x100/0x178
[238407.584793] wbt_wait+0xb4/0xf0
[238407.584797] __rq_qos_throttle+0x38/0x50
[238407.584803] blk_mq_make_request+0x120/0x5f8
[238407.584807] generic_make_request+0xb4/0x2d8
[238407.584812] submit_bio+0x44/0x1b0
[238407.584970] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238407.585065] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.585160] zio_nowait+0xd4/0x170 [zfs]
[238407.585254] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.585348] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.585442] zio_nowait+0xd4/0x170 [zfs]
[238407.585536] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.585630] zio_vdev_io_start+0x248/0x2b8 [zfs]
[238407.585724] zio_execute+0xac/0x110 [zfs]
[238407.585742] taskq_thread+0x304/0x580 [spl]
[238407.585748] kthread+0x104/0x130
[238407.585753] ret_from_fork+0x10/0x1c
[238407.585770] INFO: task txg_sync:1802 blocked for more than 120 seconds.
[238407.592634] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.599741] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.607819] txg_sync D 0 1802 2 0x00000028
[238407.607826] Call trace:
[238407.607835] __switch_to+0xf0/0x150
[238407.607843] __schedule+0x2cc/0x718
[238407.607847] schedule+0x3c/0xb8
[238407.607852] schedule_timeout+0x9c/0x190
[238407.607856] io_schedule_timeout+0x28/0x48
[238407.607875] __cv_timedwait_common+0x1a8/0x1f8 [spl]
[238407.607889] __cv_timedwait_io+0x3c/0x50 [spl]
[238407.608041] zio_wait+0x130/0x2a0 [zfs]
[238407.608140] dsl_pool_sync+0x3fc/0x498 [zfs]
[238407.608244] spa_sync+0x530/0xe98 [zfs]
[238407.608341] txg_sync_thread+0x2d0/0x488 [zfs]
[238407.608357] thread_generic_wrapper+0x74/0xa0 [spl]
[238407.608366] kthread+0x104/0x130
[238407.608371] ret_from_fork+0x10/0x1c
[238407.608430] INFO: task dockerd:32620 blocked for more than 120 seconds.
[238407.615300] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.622415] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.630500] dockerd D 0 32620 1 0x00000008
[238407.630508] Call trace:
[238407.630519] __switch_to+0xf0/0x150
[238407.630528] __schedule+0x2cc/0x718
[238407.630532] schedule+0x3c/0xb8
[238407.630551] cv_wait_common+0x188/0x1b0 [spl]
[238407.630565] __cv_wait+0x30/0x40 [spl]
[238407.630687] zil_commit_impl+0x234/0xd68 [zfs]
[238407.630784] zil_commit+0x48/0x70 [zfs]
[238407.630882] zfs_fsync+0x84/0x108 [zfs]
[238407.630977] zpl_fsync+0x7c/0xb0 [zfs]
[238407.630984] vfs_fsync_range+0x4c/0x88
[238407.630988] do_fsync+0x48/0x88
[238407.630993] __arm64_sys_fsync+0x24/0x38
[238407.630998] el0_svc_common.constprop.0+0xe0/0x1e8
[238407.631001] el0_svc_handler+0x34/0xa0
[238407.631006] el0_svc+0x10/0x14
[238407.631047] INFO: task mongod:27428 blocked for more than 120 seconds.
[238407.637819] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.644927] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.653010] mongod D 0 27428 25240 0x00000800
[238407.653016] Call trace:
[238407.653028] __switch_to+0xf0/0x150
[238407.653036] __schedule+0x2cc/0x718
[238407.653041] schedule+0x3c/0xb8
[238407.653063] cv_wait_common+0x188/0x1b0 [spl]
[238407.653077] __cv_wait+0x30/0x40 [spl]
[238407.653205] zil_commit_impl+0x234/0xd68 [zfs]
[238407.653310] zil_commit+0x48/0x70 [zfs]
[238407.653407] zfs_fsync+0x84/0x108 [zfs]
[238407.653502] zpl_fsync+0x7c/0xb0 [zfs]
[238407.653508] vfs_fsync_range+0x4c/0x88
[238407.653513] __arm64_sys_msync+0x190/0x1f8
[238407.653518] el0_svc_common.constprop.0+0xe0/0x1e8
[238407.653522] el0_svc_handler+0x34/0xa0
[238407.653526] el0_svc+0x10/0x14
[238407.653572] INFO: task mongod:32146 blocked for more than 120 seconds.
[238407.660351] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.667463] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.675546] mongod D 0 32146 25240 0x00000800
[238407.675557] Call trace:
[238407.675565] __switch_to+0xf0/0x150
[238407.675570] __schedule+0x2cc/0x718
[238407.675574] schedule+0x3c/0xb8
[238407.675592] cv_wait_common+0x188/0x1b0 [spl]
[238407.675605] __cv_wait+0x30/0x40 [spl]
[238407.675710] zil_commit_impl+0x234/0xd68 [zfs]
[238407.675806] zil_commit+0x48/0x70 [zfs]
[238407.675900] zfs_fsync+0x84/0x108 [zfs]
[238407.675995] zpl_fsync+0x7c/0xb0 [zfs]
[238407.676001] vfs_fsync_range+0x4c/0x88
[238407.676005] do_fsync+0x48/0x88
[238407.676010] __arm64_sys_fdatasync+0x24/0x38
[238407.676015] el0_svc_common.constprop.0+0xe0/0x1e8
[238407.676018] el0_svc_handler+0x34/0xa0
[238407.676022] el0_svc+0x10/0x14
[238407.676091] INFO: task z_wr_int:15893 blocked for more than 120 seconds.
[238407.683033] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.690134] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.698212] z_wr_int D 0 15893 2 0x00000028
[238407.698219] Call trace:
[238407.698231] __switch_to+0xf0/0x150
[238407.698239] __schedule+0x2cc/0x718
[238407.698243] schedule+0x3c/0xb8
[238407.698247] io_schedule+0x20/0x40
[238407.698253] rq_qos_wait+0x100/0x178
[238407.698258] wbt_wait+0xb4/0xf0
[238407.698263] __rq_qos_throttle+0x38/0x50
[238407.698268] blk_mq_make_request+0x120/0x5f8
[238407.698274] generic_make_request+0xb4/0x2d8
[238407.698279] submit_bio+0x44/0x1b0
[238407.698402] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238407.698500] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.698601] zio_nowait+0xd4/0x170 [zfs]
[238407.698700] vdev_queue_io_done+0x1f0/0x2a0 [zfs]
[238407.698795] zio_vdev_io_done+0xec/0x220 [zfs]
[238407.698889] zio_execute+0xac/0x110 [zfs]
[238407.698906] taskq_thread+0x304/0x580 [spl]
[238407.698912] kthread+0x104/0x130
[238407.698916] ret_from_fork+0x10/0x1c
[238407.698925] INFO: task z_wr_iss_h:15990 blocked for more than 120 seconds.
[238407.706051] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.713152] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.721228] z_wr_iss_h D 0 15990 2 0x00000028
[238407.721234] Call trace:
[238407.721243] __switch_to+0xf0/0x150
[238407.721254] __schedule+0x2cc/0x718
[238407.721259] schedule+0x3c/0xb8
[238407.721263] io_schedule+0x20/0x40
[238407.721269] rq_qos_wait+0x100/0x178
[238407.721274] wbt_wait+0xb4/0xf0
[238407.721278] __rq_qos_throttle+0x38/0x50
[238407.721283] blk_mq_make_request+0x120/0x5f8
[238407.721289] generic_make_request+0xb4/0x2d8
[238407.721294] submit_bio+0x44/0x1b0
[238407.721401] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238407.721505] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.721604] zio_nowait+0xd4/0x170 [zfs]
[238407.721698] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.721793] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.721887] zio_nowait+0xd4/0x170 [zfs]
[238407.721984] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.722112] zio_vdev_io_start+0x248/0x2b8 [zfs]
[238407.722212] zio_execute+0xac/0x110 [zfs]
[238407.722229] taskq_thread+0x304/0x580 [spl]
[238407.722237] kthread+0x104/0x130
[238407.722242] ret_from_fork+0x10/0x1c
[238407.722248] INFO: task z_wr_iss_h:15991 blocked for more than 121 seconds.
[238407.729367] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238407.736471] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238407.744552] z_wr_iss_h D 0 15991 2 0x00000028
[238407.744559] Call trace:
[238407.744572] __switch_to+0xf0/0x150
[238407.744582] __schedule+0x2cc/0x718
[238407.744586] schedule+0x3c/0xb8
[238407.744589] io_schedule+0x20/0x40
[238407.744595] rq_qos_wait+0x100/0x178
[238407.744600] wbt_wait+0xb4/0xf0
[238407.744604] __rq_qos_throttle+0x38/0x50
[238407.744608] blk_mq_make_request+0x120/0x5f8
[238407.744613] generic_make_request+0xb4/0x2d8
[238407.744617] submit_bio+0x44/0x1b0
[238407.744748] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238407.744844] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.744938] zio_nowait+0xd4/0x170 [zfs]
[238407.745032] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.745126] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238407.745221] zio_nowait+0xd4/0x170 [zfs]
[238407.745315] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238407.745409] zio_vdev_io_start+0x248/0x2b8 [zfs]
[238407.745503] zio_execute+0xac/0x110 [zfs]
[238407.745520] taskq_thread+0x304/0x580 [spl]
[238407.745526] kthread+0x104/0x130
[238407.745530] ret_from_fork+0x10/0x1c
[238528.372629] INFO: task z_wr_iss:1683 blocked for more than 241 seconds.
[238528.379559] Tainted: P C OE 5.3.0-1014-raspi2 #16-Ubuntu
[238528.386729] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[238528.394820] z_wr_iss D 0 1683 2 0x00000028
[238528.394828] Call trace:
[238528.394841] __switch_to+0xf0/0x150
[238528.394848] __schedule+0x2cc/0x718
[238528.394852] schedule+0x3c/0xb8
[238528.394855] io_schedule+0x20/0x40
[238528.394861] rq_qos_wait+0x100/0x178
[238528.394866] wbt_wait+0xb4/0xf0
[238528.394871] __rq_qos_throttle+0x38/0x50
[238528.394876] blk_mq_make_request+0x120/0x5f8
[238528.394881] generic_make_request+0xb4/0x2d8
[238528.394885] submit_bio+0x44/0x1b0
[238528.395046] vdev_disk_io_start+0x668/0x9e8 [zfs]
[238528.395142] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238528.395238] zio_nowait+0xd4/0x170 [zfs]
[238528.395332] vdev_queue_io+0x24c/0x268 [zfs]
[238528.395427] zio_vdev_io_start+0x94/0x2b8 [zfs]
[238528.395521] zio_nowait+0xd4/0x170 [zfs]
[238528.395615] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238528.395709] zio_vdev_io_start+0xdc/0x2b8 [zfs]
[238528.395803] zio_nowait+0xd4/0x170 [zfs]
[238528.395897] vdev_mirror_io_start+0xa8/0x1b0 [zfs]
[238528.395991] zio_vdev_io_start+0x248/0x2b8 [zfs]
[238528.396084] zio_execute+0xac/0x110 [zfs]
[238528.396103] taskq_thread+0x304/0x580 [spl]
[238528.396109] kthread+0x104/0x130
[238528.396113] ret_from_fork+0x10/0x1c@lassebm Besides it being blocked IO, your stacktrace looks notably different.
lassebm
commented
4 years ago @Ornias1993 I wasn't quite sure what to look for. Would you think it's worth a new issue?
PrivatePuffin
commented
4 years ago @lassebm Actually, now I take a second look at it... The lower parts of the trace are actually quite similar...
kebian
commented
4 years ago | Type | Version/Name |
|---|---|
| Distribution Name | Ubuntu |
| Distribution Version | 19.10 |
| Linux Kernel | 5.3.0-24-generic |
| Architecture | NUC7i3DNHE Intel i3 / 8GB RAM. |
| ZFS Version | 0.8.1-1ubuntu14 |
| SPL Version | 0.8.1-1ubuntu14 |
I don't know if it's related but I have a similar issue on Ubuntu Eoan when attempting to rsync large amounts of NAS data from one machine to another. Transfer speeds are around 30MB/s and then suddenly they'll hit 5MB/s when these errors occur and will stay at that speed. Cancelling the rsync and waiting for the io to catch up temporarily fixes it.
[Tue Jan 7 06:06:14 2020] INFO: task txg_sync:1076 blocked for more than 120 seconds.
[Tue Jan 7 06:06:14 2020] Tainted: P O 5.3.0-24-generic #26-Ubuntu
[Tue Jan 7 06:06:14 2020] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Tue Jan 7 06:06:14 2020] txg_sync D 0 1076 2 0x80004000
[Tue Jan 7 06:06:14 2020] Call Trace:
[Tue Jan 7 06:06:14 2020] __schedule+0x2b9/0x6c0
[Tue Jan 7 06:06:14 2020] schedule+0x42/0xb0
[Tue Jan 7 06:06:14 2020] schedule_timeout+0x152/0x2f0
[Tue Jan 7 06:06:14 2020] ? spa_taskq_dispatch_ent+0x4f/0x70 [zfs]
[Tue Jan 7 06:06:14 2020] ? __next_timer_interrupt+0xe0/0xe0
[Tue Jan 7 06:06:14 2020] io_schedule_timeout+0x1e/0x50
[Tue Jan 7 06:06:14 2020] __cv_timedwait_common+0x15e/0x1c0 [spl]
[Tue Jan 7 06:06:14 2020] ? wait_woken+0x80/0x80
[Tue Jan 7 06:06:14 2020] __cv_timedwait_io+0x19/0x20 [spl]
[Tue Jan 7 06:06:14 2020] zio_wait+0x11b/0x230 [zfs]
[Tue Jan 7 06:06:14 2020] ? __raw_spin_unlock+0x9/0x10 [zfs]
[Tue Jan 7 06:06:14 2020] dsl_pool_sync+0xbc/0x410 [zfs]
[Tue Jan 7 06:06:14 2020] spa_sync_iterate_to_convergence+0xe0/0x1c0 [zfs]
[Tue Jan 7 06:06:14 2020] spa_sync+0x312/0x5b0 [zfs]
[Tue Jan 7 06:06:14 2020] txg_sync_thread+0x279/0x310 [zfs]
[Tue Jan 7 06:06:14 2020] ? txg_dispatch_callbacks+0x100/0x100 [zfs]
[Tue Jan 7 06:06:14 2020] thread_generic_wrapper+0x83/0xa0 [spl]
[Tue Jan 7 06:06:14 2020] kthread+0x104/0x140
[Tue Jan 7 06:06:14 2020] ? clear_bit+0x20/0x20 [spl]
[Tue Jan 7 06:06:14 2020] ? kthread_park+0x80/0x80
[Tue Jan 7 06:06:14 2020] ret_from_fork+0x35/0x40@kebian If you fill out the same little form thats used on the issue template (os, distro, zfsversion etc.), it would be usefull for confirmation.
kebian
commented
4 years ago @kebian If you fill out the same little form thats used on the issue template (os, distro, zfsversion etc.), it would be usefull for confirmation.
Ok, I edited my above comment and added those details. Thanks.
PrivatePuffin
commented
4 years ago @kebian Awesome...
8GB ram, you sure you aren't out of memory?
bghira
commented
4 years ago can you share the disk scheduler that is in use by the underlying storage devices?
PrivatePuffin
commented
4 years ago can you share the disk scheduler that is in use by the underlying storage devices?
Welcome to github mister bug stuff! :) Maybe it would be relevant to explain to reporters how they can find out (not everyone is as well versed in Linux) and why it might be relevant to the issue?
Dinth
commented
4 years ago Im having same issue on OpenMediaVault 5.3.10-1 with kernel 5.4.0-0-bpo.4-amd64 and ZFS v0.8.3-1~bpo10+1 although i remember having this issue for long time. It is usually triggered when im trying to delete or move some files in the console and at the same time im accessing the storage over the network.
[52320.685399] INFO: task txg_sync:856 blocked for more than 120 seconds.
[52320.685435] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52320.685465] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52320.685502] txg_sync D 0 856 2 0x80004000
[52320.685505] Call Trace:
[52320.685513] ? __schedule+0x2e6/0x6f0
[52320.685515] schedule+0x2f/0xa0
[52320.685524] taskq_wait+0x7a/0xc0 [spl]
[52320.685528] ? finish_wait+0x80/0x80
[52320.685580] dmu_objset_sync+0x357/0x560 [zfs]
[52320.685621] dsl_dataset_sync+0x6d/0x260 [zfs]
[52320.685663] dsl_pool_sync+0xe8/0x510 [zfs]
[52320.685713] spa_sync+0x5af/0xfb0 [zfs]
[52320.685764] ? spa_txg_history_init_io+0x106/0x110 [zfs]
[52320.685813] txg_sync_thread+0x294/0x460 [zfs]
[52320.685817] ? __switch_to_asm+0x34/0x70
[52320.685866] ? txg_thread_exit.isra.10+0x60/0x60 [zfs]
[52320.685871] ? __thread_exit+0x20/0x20 [spl]
[52320.685876] thread_generic_wrapper+0x6f/0x80 [spl]
[52320.685879] kthread+0x112/0x130
[52320.685881] ? kthread_park+0x80/0x80
[52320.685883] ret_from_fork+0x35/0x40
[52320.685896] INFO: task z_rd_int:17925 blocked for more than 120 seconds.
[52320.685921] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52320.685950] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52320.685977] z_rd_int D 0 17925 2 0x80004000
[52320.685978] Call Trace:
[52320.685980] ? __schedule+0x2e6/0x6f0
[52320.685981] schedule+0x2f/0xa0
[52320.685982] schedule_preempt_disabled+0xa/0x10
[52320.685984] __mutex_lock.isra.8+0x2b5/0x4a0
[52320.686034] vdev_queue_io_done+0x46/0x250 [zfs]
[52320.686036] ? _cond_resched+0x15/0x30
[52320.686084] zio_vdev_io_done+0xd3/0x1f0 [zfs]
[52320.686133] zio_execute+0x90/0xf0 [zfs]
[52320.686139] taskq_thread+0x2df/0x520 [spl]
[52320.686141] ? __switch_to_asm+0x34/0x70
[52320.686143] ? wake_up_q+0x80/0x80
[52320.686202] ? zio_taskq_member.isra.9.constprop.14+0x70/0x70 [zfs]
[52320.686207] ? taskq_thread_spawn+0x50/0x50 [spl]
[52320.686209] kthread+0x112/0x130
[52320.686210] ? kthread_park+0x80/0x80
[52320.686212] ret_from_fork+0x35/0x40
[52441.515498] INFO: task txg_sync:856 blocked for more than 241 seconds.
[52441.515549] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52441.515578] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52441.515606] txg_sync D 0 856 2 0x80004000
[52441.515609] Call Trace:
[52441.515617] ? __schedule+0x2e6/0x6f0
[52441.515618] schedule+0x2f/0xa0
[52441.515627] taskq_wait+0x7a/0xc0 [spl]
[52441.515631] ? finish_wait+0x80/0x80
[52441.515693] dmu_objset_sync+0x357/0x560 [zfs]
[52441.515734] dsl_dataset_sync+0x6d/0x260 [zfs]
[52441.515776] dsl_pool_sync+0xe8/0x510 [zfs]
[52441.515825] spa_sync+0x5af/0xfb0 [zfs]
[52441.515876] ? spa_txg_history_init_io+0x106/0x110 [zfs]
[52441.515926] txg_sync_thread+0x294/0x460 [zfs]
[52441.515929] ? __switch_to_asm+0x34/0x70
[52441.515978] ? txg_thread_exit.isra.10+0x60/0x60 [zfs]
[52441.515984] ? __thread_exit+0x20/0x20 [spl]
[52441.515988] thread_generic_wrapper+0x6f/0x80 [spl]
[52441.515992] kthread+0x112/0x130
[52441.515993] ? kthread_park+0x80/0x80
[52441.515995] ret_from_fork+0x35/0x40
[52441.516012] INFO: task z_rd_int:17925 blocked for more than 241 seconds.
[52441.516037] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52441.516081] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52441.516115] z_rd_int D 0 17925 2 0x80004000
[52441.516116] Call Trace:
[52441.516119] ? __schedule+0x2e6/0x6f0
[52441.516120] schedule+0x2f/0xa0
[52441.516121] schedule_preempt_disabled+0xa/0x10
[52441.516123] __mutex_lock.isra.8+0x2b5/0x4a0
[52441.516173] vdev_queue_io_done+0x46/0x250 [zfs]
[52441.516176] ? _cond_resched+0x15/0x30
[52441.516227] zio_vdev_io_done+0xd3/0x1f0 [zfs]
[52441.516288] zio_execute+0x90/0xf0 [zfs]
[52441.516299] taskq_thread+0x2df/0x520 [spl]
[52441.516301] ? __switch_to_asm+0x34/0x70
[52441.516302] ? wake_up_q+0x80/0x80
[52441.516350] ? zio_taskq_member.isra.9.constprop.14+0x70/0x70 [zfs]
[52441.516356] ? taskq_thread_spawn+0x50/0x50 [spl]
[52441.516357] kthread+0x112/0x130
[52441.516359] ? kthread_park+0x80/0x80
[52441.516360] ret_from_fork+0x35/0x40
[52562.345526] INFO: task txg_sync:856 blocked for more than 362 seconds.
[52562.345561] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52562.345590] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52562.345619] txg_sync D 0 856 2 0x80004000
[52562.345621] Call Trace:
[52562.345630] ? __schedule+0x2e6/0x6f0
[52562.345631] schedule+0x2f/0xa0
[52562.345640] taskq_wait+0x7a/0xc0 [spl]
[52562.345644] ? finish_wait+0x80/0x80
[52562.345698] dmu_objset_sync+0x357/0x560 [zfs]
[52562.345752] dsl_dataset_sync+0x6d/0x260 [zfs]
[52562.345792] dsl_pool_sync+0xe8/0x510 [zfs]
[52562.345840] spa_sync+0x5af/0xfb0 [zfs]
[52562.345889] ? spa_txg_history_init_io+0x106/0x110 [zfs]
[52562.345941] txg_sync_thread+0x294/0x460 [zfs]
[52562.345944] ? __switch_to_asm+0x34/0x70
[52562.346007] ? txg_thread_exit.isra.10+0x60/0x60 [zfs]
[52562.346012] ? __thread_exit+0x20/0x20 [spl]
[52562.346017] thread_generic_wrapper+0x6f/0x80 [spl]
[52562.346020] kthread+0x112/0x130
[52562.346022] ? kthread_park+0x80/0x80
[52562.346024] ret_from_fork+0x35/0x40
[52562.346042] INFO: task z_rd_int:17925 blocked for more than 362 seconds.
[52562.346067] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[52562.346096] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[52562.346123] z_rd_int D 0 17925 2 0x80004000
[52562.346124] Call Trace:
[52562.346126] ? __schedule+0x2e6/0x6f0
[52562.346128] schedule+0x2f/0xa0
[52562.346129] schedule_preempt_disabled+0xa/0x10
[52562.346130] __mutex_lock.isra.8+0x2b5/0x4a0
[52562.346181] vdev_queue_io_done+0x46/0x250 [zfs]
[52562.346183] ? _cond_resched+0x15/0x30
[52562.346231] zio_vdev_io_done+0xd3/0x1f0 [zfs]
[52562.346280] zio_execute+0x90/0xf0 [zfs]
[52562.346286] taskq_thread+0x2df/0x520 [spl]
[52562.346288] ? __switch_to_asm+0x34/0x70
[52562.346290] ? wake_up_q+0x80/0x80
[52562.346337] ? zio_taskq_member.isra.9.constprop.14+0x70/0x70 [zfs]
[52562.346343] ? taskq_thread_spawn+0x50/0x50 [spl]
[52562.346345] kthread+0x112/0x130
[52562.346346] ? kthread_park+0x80/0x80
[52562.346348] ret_from_fork+0x35/0x40
[52594.864825] systemd[1]: systemd-logind.service: Watchdog timeout (limit 3min)!
[52594.864886] systemd[1]: systemd-logind.service: Killing process 1379 (systemd-logind) with signal SIGABRT.
[52598.762708] systemd[1]: systemd-journald.service: Main process exited, code=killed, status=6/ABRT
[52598.762923] systemd[1]: systemd-journald.service: Failed with result 'watchdog'.
[52598.763820] systemd[1]: systemd-journald.service: Service has no hold-off time (RestartSec=0), scheduling restart.
[52598.764533] systemd[1]: systemd-journald.service: Scheduled restart job, restart counter is at 1.
[52598.765565] systemd[1]: systemd-journal-flush.service: Succeeded.
[52598.765650] systemd[1]: Stopped Flush Journal to Persistent Storage.
[52598.765680] systemd[1]: Stopping Flush Journal to Persistent Storage...
[52598.765752] systemd[1]: Stopped Journal Service.
[52598.982722] systemd-journald[17953]: File /run/log/journal/e4adb6ec49c44c1db846cadde006c4e4/system.journal corrupted or uncleanly shut down, renaming and replacing.
[383032.378146] INFO: task z_iput:752 blocked for more than 120 seconds.
[383032.378185] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[383032.379018] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[383032.379833] z_iput D 0 752 2 0x80004000
[383032.379837] Call Trace:
[383032.379847] ? __schedule+0x2e6/0x6f0
[383032.379849] schedule+0x2f/0xa0
[383032.379850] io_schedule+0x12/0x40
[383032.379860] cv_wait_common+0xaf/0x130 [spl]
[383032.379864] ? finish_wait+0x80/0x80
[383032.379941] txg_wait_open+0x8a/0xd0 [zfs]
[383032.379980] dmu_free_long_range+0x2fe/0x4b0 [zfs]
[383032.380035] zfs_rmnode+0x262/0x330 [zfs]
[383032.380089] ? zfs_zinactive+0xdc/0xf0 [zfs]
[383032.380141] zfs_inactive+0x84/0x210 [zfs]
[383032.380146] ? unmap_mapping_pages+0x5e/0x130
[383032.380196] zpl_evict_inode+0x3c/0x50 [zfs]
[383032.380201] evict+0xd2/0x1a0
[383032.380207] taskq_thread+0x2df/0x520 [spl]
[383032.380210] ? wake_up_q+0x80/0x80
[383032.380216] ? taskq_thread_spawn+0x50/0x50 [spl]
[383032.380219] kthread+0x112/0x130
[383032.380221] ? kthread_park+0x80/0x80
[383032.380224] ret_from_fork+0x35/0x40
[383032.380228] INFO: task txg_sync:856 blocked for more than 120 seconds.
[383032.380998] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[383032.381784] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[383032.382595] txg_sync D 0 856 2 0x80004000
[383032.382597] Call Trace:
[383032.382600] ? __schedule+0x2e6/0x6f0
[383032.382601] schedule+0x2f/0xa0
[383032.382603] schedule_timeout+0x159/0x310
[383032.382608] ? __next_timer_interrupt+0xc0/0xc0
[383032.382609] io_schedule_timeout+0x19/0x40
[383032.382617] __cv_timedwait_common+0x125/0x160 [spl]
[383032.382633] ? finish_wait+0x80/0x80
[383032.382695] zio_wait+0x13a/0x280 [zfs]
[383032.382730] ? bplist_iterate+0x126/0x140 [zfs]
[383032.382782] spa_sync+0x5f0/0xfb0 [zfs]
[383032.382837] ? spa_txg_history_init_io+0x106/0x110 [zfs]
[383032.382891] txg_sync_thread+0x294/0x460 [zfs]
[383032.382893] ? __switch_to_asm+0x34/0x70
[383032.382946] ? txg_thread_exit.isra.10+0x60/0x60 [zfs]
[383032.382952] ? __thread_exit+0x20/0x20 [spl]
[383032.382957] thread_generic_wrapper+0x6f/0x80 [spl]
[383032.382960] kthread+0x112/0x130
[383032.382961] ? kthread_park+0x80/0x80
[383032.382963] ret_from_fork+0x35/0x40
[383032.382972] INFO: task nfsd:1585 blocked for more than 120 seconds.
[383032.383754] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[383032.384579] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[383032.385414] nfsd D 0 1585 2 0x80004000
[383032.385415] Call Trace:
[383032.385417] ? __schedule+0x2e6/0x6f0
[383032.385419] ? __wake_up_common+0x7a/0x180
[383032.385420] schedule+0x2f/0xa0
[383032.385421] io_schedule+0x12/0x40
[383032.385426] cv_wait_common+0xaf/0x130 [spl]
[383032.385428] ? finish_wait+0x80/0x80
[383032.385483] txg_wait_open+0x8a/0xd0 [zfs]
[383032.385521] dmu_free_long_range+0x2fe/0x4b0 [zfs]
[383032.385573] zfs_trunc+0x77/0x1f0 [zfs]
[383032.385625] ? sa_lookup_locked+0x64/0xb0 [zfs]
[383032.385677] zfs_freesp+0x9b/0x430 [zfs]
[383032.385729] ? zfs_dirent_unlock+0xc0/0x140 [zfs]
[383032.385766] ? dmu_object_size_from_db+0x22/0x80 [zfs]
[383032.385767] ? _cond_resched+0x15/0x30
[383032.385768] ? mutex_lock+0xe/0x30
[383032.385817] ? rrw_exit+0x59/0x150 [zfs]
[383032.385869] ? zfs_lookup+0x143/0x3a0 [zfs]
[383032.385919] zpl_xattr_set_dir.isra.15+0x114/0x2a0 [zfs]
[383032.385970] zpl_xattr_set+0x144/0x360 [zfs]
[383032.386021] zpl_set_acl+0x14e/0x210 [zfs]
[383032.386071] zpl_chmod_acl+0xc9/0xe0 [zfs]
[383032.386123] zpl_setattr+0x150/0x180 [zfs]
[383032.386138] notify_change+0x339/0x4a0
[383032.386155] nfsd_setattr+0x3ff/0x470 [nfsd]
[383032.386176] ? write_bytes_to_xdr_buf+0xbc/0xe0 [sunrpc]
[383032.386187] nfsd4_setattr+0x7b/0x140 [nfsd]
[383032.386198] nfsd4_proc_compound+0x381/0x6f0 [nfsd]
[383032.386206] nfsd_dispatch+0x9e/0x210 [nfsd]
[383032.386221] svc_process_common+0x342/0x6b0 [sunrpc]
[383032.386236] ? svc_recv+0x2ff/0x980 [sunrpc]
[383032.386243] ? nfsd_svc+0x2c0/0x2c0 [nfsd]
[383032.386251] ? nfsd_destroy+0x50/0x50 [nfsd]
[383032.386264] svc_process+0xd1/0x110 [sunrpc]
[383032.386272] nfsd+0xe3/0x140 [nfsd]
[383032.386274] kthread+0x112/0x130
[383032.386275] ? kthread_park+0x80/0x80
[383032.386277] ret_from_fork+0x35/0x40
[383032.386285] INFO: task mc:7614 blocked for more than 120 seconds.
[383032.387103] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[383032.387947] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[383032.388793] mc D 0 7614 30679 0x00000000
[383032.388794] Call Trace:
[383032.388797] ? __schedule+0x2e6/0x6f0
[383032.388799] ? __wake_up_common+0x7a/0x180
[383032.388800] schedule+0x2f/0xa0
[383032.388801] io_schedule+0x12/0x40
[383032.388805] cv_wait_common+0xaf/0x130 [spl]
[383032.388807] ? finish_wait+0x80/0x80
[383032.388863] txg_wait_open+0x8a/0xd0 [zfs]
[383032.388901] dmu_free_long_range+0x2fe/0x4b0 [zfs]
[383032.388953] zfs_rmnode+0x262/0x330 [zfs]
[383032.389006] ? zfs_zinactive+0xdc/0xf0 [zfs]
[383032.389058] zfs_inactive+0x84/0x210 [zfs]
[383032.389061] ? unmap_mapping_pages+0x5e/0x130
[383032.389111] zpl_evict_inode+0x3c/0x50 [zfs]
[383032.389113] evict+0xd2/0x1a0
[383032.389116] do_unlinkat+0x263/0x300
[383032.389120] do_syscall_64+0x52/0x160
[383032.389122] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[383032.389124] RIP: 0033:0x7fe113fadfc7
[383032.389131] Code: Bad RIP value.
[383032.389131] RSP: 002b:00007ffce7809e98 EFLAGS: 00000202 ORIG_RAX: 0000000000000057
[383032.389133] RAX: ffffffffffffffda RBX: 000055cdbc571140 RCX: 00007fe113fadfc7
[383032.389134] RDX: 000055cdbc56e330 RSI: 00000000ffffffff RDI: 000055cdbc543500
[383032.389134] RBP: 000055cdbc5573a0 R08: 0000000000000000 R09: 0000000000000000
[383032.389135] R10: 0000000000000008 R11: 0000000000000202 R12: 000055cdbc52fd24
[383032.389136] R13: 00007ffce7809efc R14: 000055cdbc56bd10 R15: 000000ffff000000
AlexOwen
commented
4 years ago @Dinth, how much RAM do you have, and how big are the files you're moving (total and individual) when you see the error?
My errors went away when I increased the RAM I have (from 8GB to 32GB), but obviously that was only a workaround and not a solution. It also only happened when moving thousands of files adding to over a terabyte across a file system boundary.
Dinth
commented
4 years ago @Dinth, how much RAM do you have, and how big are the files you're moving (total and individual) when you see the error?
16GB of RAM. The files ive been deleting and moving were not big. Today when this happened i've been moving 1GB file and deleting circa 200GB of files.
Dinth
commented
4 years ago Actually since the last time, zfs started doing that constantly, even after restart on idling system in single user mode and with pool unmounted. iostat -mx doesnt show anything abnormal and short SMART tests of drives were all successful. I have tried increasing RAM amount to 24 but has not fixed the issue.
[ 1572.097836] mount.zfs D 0 3513 1 0x00004004
[ 1572.098251] Call Trace:
[ 1572.098690] ? __schedule+0x2e6/0x6f0
[ 1572.099100] schedule+0x2f/0xa0
[ 1572.099510] io_schedule+0x12/0x40
[ 1572.099925] cv_wait_common+0xaf/0x130 [spl]
[ 1572.100322] ? finish_wait+0x80/0x80
[ 1572.100810] txg_wait_synced_impl+0xc2/0x110 [zfs]
[ 1572.101264] txg_wait_synced+0xc/0x40 [zfs]
[ 1572.101737] zil_replay+0xdd/0x120 [zfs]
[ 1572.102191] zfsvfs_setup+0x164/0x1f0 [zfs]
[ 1572.102647] zfs_domount+0x38b/0x3f0 [zfs]
[ 1572.103107] zpl_mount+0x13d/0x180 [zfs]
[ 1572.103539] legacy_get_tree+0x27/0x40
[ 1572.103941] vfs_get_tree+0x25/0xb0
[ 1572.104350] do_mount+0x7ab/0x970
[ 1572.104825] ksys_mount+0xb6/0xd0
[ 1572.105248] __x64_sys_mount+0x21/0x30
[ 1572.105681] do_syscall_64+0x52/0x160
[ 1572.106122] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1572.106580] RIP: 0033:0x7f7ba673afea
[ 1572.107049] Code: Bad RIP value.
[ 1572.107522] RSP: 002b:00007ffe1e4674a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
[ 1572.108064] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7ba673afea
[ 1572.108613] RDX: 000055bd31af811f RSI: 00007ffe1e46b5f0 RDI: 00007ffe1e46df2b
[ 1572.109151] RBP: 00007ffe1e46c630 R08: 00007ffe1e4685f0 R09: 000055bd32666bf0
[ 1572.109699] R10: 0000000001000000 R11: 0000000000000246 R12: 000055bd326630e0
[ 1572.110258] R13: 00007ffe1e4675f0 R14: 00007ffe1e4685f0 R15: 0000000000000002
[ 1581.262529] systemd-system-update-generator[1823]: Offline system update overridden by runlevel "single" on the kernel command line
[ 1581.618931] systemd-system-update-generator[1847]: Offline system update overridden by runlevel "single" on the kernel command line
[ 1581.916296] systemd-system-update-generator[1870]: Offline system update overridden by runlevel "single" on the kernel command line
[ 1692.928764] INFO: task mount.zfs:3513 blocked for more than 483 seconds.
[ 1692.929912] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[ 1692.930983] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1692.932006] mount.zfs D 0 3513 1 0x00004004
[ 1692.933126] Call Trace:
[ 1692.934263] ? __schedule+0x2e6/0x6f0
[ 1692.935349] schedule+0x2f/0xa0
[ 1692.936457] io_schedule+0x12/0x40
[ 1692.937566] cv_wait_common+0xaf/0x130 [spl]
[ 1692.938587] ? finish_wait+0x80/0x80
[ 1692.939756] txg_wait_synced_impl+0xc2/0x110 [zfs]
[ 1692.941040] txg_wait_synced+0xc/0x40 [zfs]
[ 1692.942257] zil_replay+0xdd/0x120 [zfs]
[ 1692.943486] zfsvfs_setup+0x164/0x1f0 [zfs]
[ 1692.944633] zfs_domount+0x38b/0x3f0 [zfs]
[ 1692.945829] zpl_mount+0x13d/0x180 [zfs]
[ 1692.946849] legacy_get_tree+0x27/0x40
[ 1692.947852] vfs_get_tree+0x25/0xb0
[ 1692.948917] do_mount+0x7ab/0x970
[ 1692.949909] ksys_mount+0xb6/0xd0
[ 1692.950917] __x64_sys_mount+0x21/0x30
[ 1692.951919] do_syscall_64+0x52/0x160
[ 1692.952932] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1692.953822] RIP: 0033:0x7f7ba673afea
[ 1692.954743] Code: Bad RIP value.
[ 1692.955579] RSP: 002b:00007ffe1e4674a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
[ 1692.956480] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7ba673afea
[ 1692.957369] RDX: 000055bd31af811f RSI: 00007ffe1e46b5f0 RDI: 00007ffe1e46df2b
[ 1692.958246] RBP: 00007ffe1e46c630 R08: 00007ffe1e4685f0 R09: 000055bd32666bf0
[ 1692.959106] R10: 0000000001000000 R11: 0000000000000246 R12: 000055bd326630e0
[ 1692.959966] R13: 00007ffe1e4675f0 R14: 00007ffe1e4685f0 R15: 0000000000000002
[ 1813.760838] INFO: task mount.zfs:3513 blocked for more than 604 seconds.
[ 1813.760939] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[ 1813.761065] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1813.761196] mount.zfs D 0 3513 1 0x00004004
[ 1813.761347] Call Trace:
[ 1813.761491] ? __schedule+0x2e6/0x6f0
[ 1813.761641] schedule+0x2f/0xa0
[ 1813.761794] io_schedule+0x12/0x40
[ 1813.761978] cv_wait_common+0xaf/0x130 [spl]
[ 1813.762168] ? finish_wait+0x80/0x80
[ 1813.762419] txg_wait_synced_impl+0xc2/0x110 [zfs]
[ 1813.762697] txg_wait_synced+0xc/0x40 [zfs]
[ 1813.762964] zil_replay+0xdd/0x120 [zfs]
[ 1813.763228] zfsvfs_setup+0x164/0x1f0 [zfs]
[ 1813.763508] zfs_domount+0x38b/0x3f0 [zfs]
[ 1813.763780] zpl_mount+0x13d/0x180 [zfs]
[ 1813.764016] legacy_get_tree+0x27/0x40
[ 1813.764265] vfs_get_tree+0x25/0xb0
[ 1813.764537] do_mount+0x7ab/0x970
[ 1813.764828] ksys_mount+0xb6/0xd0
[ 1813.765101] __x64_sys_mount+0x21/0x30
[ 1813.765383] do_syscall_64+0x52/0x160
[ 1813.765671] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1813.765975] RIP: 0033:0x7f7ba673afea
[ 1813.766310] Code: Bad RIP value.
[ 1813.766627] RSP: 002b:00007ffe1e4674a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
[ 1813.766983] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7ba673afea
[ 1813.767346] RDX: 000055bd31af811f RSI: 00007ffe1e46b5f0 RDI: 00007ffe1e46df2b
[ 1813.767723] RBP: 00007ffe1e46c630 R08: 00007ffe1e4685f0 R09: 000055bd32666bf0
[ 1813.768109] R10: 0000000001000000 R11: 0000000000000246 R12: 000055bd326630e0
[ 1813.768506] R13: 00007ffe1e4675f0 R14: 00007ffe1e4685f0 R15: 0000000000000002
[ 1934.593065] INFO: task mount.zfs:3513 blocked for more than 724 seconds.
[ 1934.593432] Tainted: P OE 5.4.0-0.bpo.4-amd64 #1 Debian 5.4.19-1~bpo10+1
[ 1934.593791] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1934.594165] mount.zfs D 0 3513 1 0x00004004
[ 1934.594534] Call Trace:
[ 1934.594901] ? __schedule+0x2e6/0x6f0
[ 1934.595261] schedule+0x2f/0xa0
[ 1934.595624] io_schedule+0x12/0x40
[ 1934.596018] cv_wait_common+0xaf/0x130 [spl]
[ 1934.596392] ? finish_wait+0x80/0x80
[ 1934.596834] txg_wait_synced_impl+0xc2/0x110 [zfs]
[ 1934.597302] txg_wait_synced+0xc/0x40 [zfs]
[ 1934.597723] zil_replay+0xdd/0x120 [zfs]
[ 1934.598134] zfsvfs_setup+0x164/0x1f0 [zfs]
[ 1934.598554] zfs_domount+0x38b/0x3f0 [zfs]
[ 1934.598972] zpl_mount+0x13d/0x180 [zfs]
[ 1934.599349] legacy_get_tree+0x27/0x40
[ 1934.599737] vfs_get_tree+0x25/0xb0
[ 1934.600119] do_mount+0x7ab/0x970
[ 1934.600500] ksys_mount+0xb6/0xd0
[ 1934.600870] __x64_sys_mount+0x21/0x30
[ 1934.601267] do_syscall_64+0x52/0x160
[ 1934.601635] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 1934.602012] RIP: 0033:0x7f7ba673afea
[ 1934.602395] Code: Bad RIP value.
[ 1934.602788] RSP: 002b:00007ffe1e4674a8 EFLAGS: 00000246 ORIG_RAX: 00000000000000a5
[ 1934.603231] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f7ba673afea
[ 1934.603650] RDX: 000055bd31af811f RSI: 00007ffe1e46b5f0 RDI: 00007ffe1e46df2b
[ 1934.604065] RBP: 00007ffe1e46c630 R08: 00007ffe1e4685f0 R09: 000055bd32666bf0
[ 1934.604494] R10: 0000000001000000 R11: 0000000000000246 R12: 000055bd326630e0
[ 1934.604945] R13: 00007ffe1e4675f0 R14: 00007ffe1e4685f0 R15: 0000000000000002
Linux 5.4.0-0.bpo.4-amd64 (r720-omv.wickhay) 07/05/20 _x86_64_ (4 CPU)
avg-cpu: %user %nice %system %iowait %steal %idle
5.13 0.00 2.33 64.86 0.00 27.68
Device r/s w/s rMB/s wMB/s rrqm/s wrqm/s %rrqm %wrqm r_await w_await aqu-sz rareq-sz wareq-sz svctm %util
sda 5.55 12.68 0.26 0.57 2.92 18.76 34.47 59.67 0.60 4.05 0.05 48.31 45.72 0.59 1.08
sdd 35.00 0.14 0.36 0.00 0.00 0.00 0.00 0.00 26.50 0.17 0.86 10.52 10.09 6.16 21.63
sdb 81.80 0.15 0.60 0.00 0.00 0.00 0.00 0.00 64.55 0.62 5.12 7.50 10.02 3.89 31.90
sdg 58.57 0.15 0.45 0.00 0.00 0.00 0.00 0.00 37.84 0.17 2.10 7.92 10.01 5.43 31.87
sde 81.44 0.12 0.60 0.00 0.00 0.00 0.00 0.00 64.16 0.62 5.07 7.50 11.63 3.95 32.21
sdc 35.10 0.15 0.36 0.00 0.00 0.00 0.00 0.34 26.67 0.15 0.87 10.52 9.44 6.16 21.71
sdf 58.76 0.15 0.45 0.00 0.00 0.00 0.00 0.00 37.55 0.15 2.09 7.92 9.64 5.45 32.10(sda is not in a pool and on a different controller)
scineram
commented
4 years ago Does it import read only? Can you scrub then? What kind of drives?
Dinth
commented
4 years ago It actually freezes the computer when trying to mount ZFS during normal boot. Now I have managed to import the pool in single user mode:
root@r720-omv:~# zpool status -v Data
pool: Data
state: ONLINE
status: Some supported features are not enabled on the pool. The pool can
still be used, but some features are unavailable.
action: Enable all features using 'zpool upgrade'. Once this is done,
the pool may no longer be accessible by software that does not support
the features. See zpool-features(5) for details.
scan: scrub repaired 0B in 1 days 20:48:00 with 0 errors on Mon Apr 13 21:12:01 2020
config:
NAME STATE READ WRITE CKSUM
Data ONLINE 0 0 0
raidz2-0 ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PK2338P4HPDXJC ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PKA334PCG9L92N ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PK2338P4HPSVVC ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PKA334PCG9HBLN ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PK2338P4HM5K8C ONLINE 0 0 0
ata-HGST_HDS724040ALE640_PK1334PEJDE30S ONLINE 0 0 0
and i have run'd zpool upgrade as thats what zpool is suggesting and i also found some posts online asking users to update the pool when it freezes a kernel. So far the upgrade is running for 10+ mins without any feedback, im not sure if thats normal? Sorry if its going slightly OT, but had this issue with host freezing during IO for long time, on two different hosts and its the first time when actually the freeze resulted in unmountable pool
Dinth
commented
4 years ago also iotop shows that txg_sync process is reading 250-290K/s, taking 99.9% of available IO. Im still waiting for zpool upgrade to finish
AlexOwen
commented
4 years ago You may also see a difference by playing with the 'sync=' zfs property, particularly setting 'sync=always' helped me a little, although it may have been a coincidence. You should also read up on the effects of it because it may not be suitable, especially in production server.
On Thu, 7 May 2020 at 14:31, Michal notifications@github.com wrote:
also iotop shows that txg_sync process is reading 250-290K/s, taking 99.9% of available IO. Im still waiting for zpool upgrade to finish
— You are receiving this because you authored the thread. Reply to this email directly, view it on GitHub https://github.com/openzfs/zfs/issues/9130#issuecomment-625257195, or unsubscribe https://github.com/notifications/unsubscribe-auth/ABIKST6BHXAJWFF6JTEXURTRQKZ25ANCNFSM4IJY3MZA .
queenkjuul
commented
4 years ago | Type | Version/Name |
|---|---|
| Distribution Name | Ubuntu |
| Distribution Version | 20.04 |
| Linux Kernel | 5.4.0-29-generic |
| Architecture | i5-3570k / 24GB DDR3 |
zfs --version |
zfs-0.8.3-1ubuntu12 \ zfs-kmod-0.8.3-1ubuntu12 |
I seem to have hit this last night. I ran zpool remove dpool sdb which was the read cache disk. I had a little shy of 8GB of available RAM out of 24GB total. sdb is a 120GB SSD.
pool: dpool
state: ONLINE
scan: none requested
config:
NAME STATE READ WRITE CKSUM
dpool ONLINE 0 0 0
sdc ONLINE 0 0 0
sdd ONLINE 0 0 0
cache
sdb ONLINE 0 0 0
errors: No known data errors
qkj@holodeck:/m/media (=^･^=)ﾉ
➤➤➤➤➤ sudo zpool remove dpool sdb
after that command, pretty much everything stopped responding. Apps that were previously open were responding, and I could ssh in, but most programs were not responding or hung when run.
The system just hung instantly, I saw <5% CPU utilization, RAM utilization did not change, and I wasn't able to see any disk IO
dmesg:
[283203.538506] Mem-Info:
[283203.538509] active_anon:921936 inactive_anon:379250 isolated_anon:0
active_file:506522 inactive_file:537943 isolated_file:0
unevictable:23542 dirty:243 writeback:0 unstable:0
slab_reclaimable:75422 slab_unreclaimable:516165
mapped:250435 shmem:140701 pagetables:12987 bounce:0
free:286341 free_pcp:71 free_cma:0
[283203.538512] Node 0 active_anon:3687744kB inactive_anon:1517000kB active_file:2026088kB inactive_file:2151772kB unevictable:94168kB isolated(anon):0kB isolated(file):0kB mapped:1001740kB dirty:972kB writeback:0kB shmem:562804kB shmem_thp: 0kB shmem_pmdmapped: 0kB anon_thp: 0kB writeback_tmp:0kB unstable:0kB all_unreclaimable? no
[283203.538513] Node 0 DMA free:15892kB min:44kB low:56kB high:68kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB writepending:0kB present:15992kB managed:15900kB mlocked:0kB kernel_stack:0kB pagetables:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[283203.538516] lowmem_reserve[]: 0 3317 23834 23834 23834
[283203.538517] Node 0 DMA32 free:369576kB min:9400kB low:12796kB high:16192kB active_anon:78872kB inactive_anon:59576kB active_file:37008kB inactive_file:17960kB unevictable:368kB writepending:0kB present:3551800kB managed:3486056kB mlocked:0kB kernel_stack:1048kB pagetables:3300kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB
[283203.538520] lowmem_reserve[]: 0 0 20516 20516 20516
[283203.538521] Node 0 Normal free:759896kB min:58136kB low:79144kB high:100152kB active_anon:3608348kB inactive_anon:1457424kB active_file:1989308kB inactive_file:2133752kB unevictable:93956kB writepending:972kB present:21485568kB managed:21016812kB mlocked:19044kB kernel_stack:21960kB pagetables:48648kB bounce:0kB free_pcp:268kB local_pcp:68kB free_cma:0kB
[283203.538523] lowmem_reserve[]: 0 0 0 0 0
[283203.538524] Node 0 DMA: 1*4kB (U) 0*8kB 1*16kB (U) 0*32kB 2*64kB (U) 1*128kB (U) 1*256kB (U) 0*512kB 1*1024kB (U) 1*2048kB (M) 3*4096kB (M) = 15892kB
[283203.538529] Node 0 DMA32: 13708*4kB (UE) 13186*8kB (UE) 12062*16kB (UE) 516*32kB (UE) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 369824kB
[283203.538533] Node 0 Normal: 569*4kB (UME) 1506*8kB (UME) 43245*16kB (UME) 1617*32kB (UE) 0*64kB 0*128kB 0*256kB 0*512kB 0*1024kB 1*2048kB (H) 0*4096kB = 760036kB
[283203.538538] Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
[283203.538538] 1188300 total pagecache pages
[283203.538540] 4030 pages in swap cache
[283203.538541] Swap cache stats: add 1236478, delete 1232441, find 912242/1105682
[283203.538542] Free swap = 1745584kB
[283203.538542] Total swap = 2097148kB
[283203.538543] 6263340 pages RAM
[283203.538543] 0 pages HighMem/MovableOnly
[283203.538543] 133648 pages reserved
[283203.538543] 0 pages cma reserved
[283203.538544] 0 pages hwpoisoned
[287100.556647] INFO: task z_wr_iss:570 blocked for more than 120 seconds.
[287100.556650] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.556650] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.556660] z_wr_iss D 0 570 2 0x80004000
[287100.556662] Call Trace:
[287100.556667] __schedule+0x2e3/0x740
[287100.556669] schedule+0x42/0xb0
[287100.556671] rwsem_down_write_slowpath+0x244/0x4d0
[287100.556731] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.556734] down_write+0x41/0x50
[287100.556766] dbuf_write_ready+0x1d4/0x3d0 [zfs]
[287100.556795] arc_write_ready+0xa5/0x4b0 [zfs]
[287100.556837] zio_ready+0x63/0x3f0 [zfs]
[287100.556878] zio_execute+0x91/0xe0 [zfs]
[287100.556884] taskq_thread+0x245/0x430 [spl]
[287100.556886] ? wake_up_q+0x70/0x70
[287100.556936] ? zio_execute_stack_check.constprop.0+0x10/0x10 [zfs]
[287100.556937] kthread+0x104/0x140
[287100.556942] ? task_done+0x90/0x90 [spl]
[287100.556943] ? kthread_park+0x90/0x90
[287100.556945] ret_from_fork+0x35/0x40
[287100.556947] INFO: task z_wr_iss:571 blocked for more than 120 seconds.
[287100.556948] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.556949] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.556950] z_wr_iss D 0 571 2 0x80004000
[287100.556951] Call Trace:
[287100.556952] __schedule+0x2e3/0x740
[287100.556953] schedule+0x42/0xb0
[287100.556954] rwsem_down_write_slowpath+0x244/0x4d0
[287100.556990] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.556991] down_write+0x41/0x50
[287100.557018] dbuf_write_ready+0x1d4/0x3d0 [zfs]
[287100.557042] arc_write_ready+0xa5/0x4b0 [zfs]
[287100.557081] zio_ready+0x63/0x3f0 [zfs]
[287100.557120] zio_execute+0x91/0xe0 [zfs]
[287100.557124] taskq_thread+0x245/0x430 [spl]
[287100.557126] ? wake_up_q+0x70/0x70
[287100.557164] ? zio_execute_stack_check.constprop.0+0x10/0x10 [zfs]
[287100.557165] kthread+0x104/0x140
[287100.557169] ? task_done+0x90/0x90 [spl]
[287100.557170] ? kthread_park+0x90/0x90
[287100.557172] ret_from_fork+0x35/0x40
[287100.557173] INFO: task z_wr_iss:572 blocked for more than 120 seconds.
[287100.557174] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.557174] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.557175] z_wr_iss D 0 572 2 0x80004000
[287100.557176] Call Trace:
[287100.557177] __schedule+0x2e3/0x740
[287100.557179] ? sched_clock+0x9/0x10
[287100.557179] schedule+0x42/0xb0
[287100.557181] rwsem_down_write_slowpath+0x244/0x4d0
[287100.557213] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.557215] down_write+0x41/0x50
[287100.557239] dbuf_write_ready+0x1d4/0x3d0 [zfs]
[287100.557262] arc_write_ready+0xa5/0x4b0 [zfs]
[287100.557300] zio_ready+0x63/0x3f0 [zfs]
[287100.557337] zio_execute+0x91/0xe0 [zfs]
[287100.557341] taskq_thread+0x245/0x430 [spl]
[287100.557343] ? wake_up_q+0x70/0x70
[287100.557380] ? zio_execute_stack_check.constprop.0+0x10/0x10 [zfs]
[287100.557381] kthread+0x104/0x140
[287100.557385] ? task_done+0x90/0x90 [spl]
[287100.557386] ? kthread_park+0x90/0x90
[287100.557387] ret_from_fork+0x35/0x40
[287100.557392] INFO: task txg_sync:647 blocked for more than 120 seconds.
[287100.557393] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.557394] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.557394] txg_sync D 0 647 2 0x80004000
[287100.557395] Call Trace:
[287100.557396] __schedule+0x2e3/0x740
[287100.557397] schedule+0x42/0xb0
[287100.557407] schedule_timeout+0x152/0x2f0
[287100.557409] ? __next_timer_interrupt+0xe0/0xe0
[287100.557410] io_schedule_timeout+0x1e/0x50
[287100.557413] __cv_timedwait_common+0x15e/0x1c0 [spl]
[287100.557415] ? wait_woken+0x80/0x80
[287100.557418] __cv_timedwait_io+0x19/0x20 [spl]
[287100.557480] zio_wait+0x11b/0x230 [zfs]
[287100.557515] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.557545] dsl_pool_sync+0xbc/0x410 [zfs]
[287100.557579] spa_sync_iterate_to_convergence+0xe0/0x1c0 [zfs]
[287100.557612] spa_sync+0x312/0x5b0 [zfs]
[287100.557646] txg_sync_thread+0x27a/0x310 [zfs]
[287100.557680] ? txg_dispatch_callbacks+0x100/0x100 [zfs]
[287100.557684] thread_generic_wrapper+0x83/0xa0 [spl]
[287100.557685] kthread+0x104/0x140
[287100.557688] ? clear_bit+0x20/0x20 [spl]
[287100.557689] ? kthread_park+0x90/0x90
[287100.557690] ret_from_fork+0x35/0x40
[287100.557692] INFO: task systemd-journal:983 blocked for more than 120 seconds.
[287100.557693] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.557694] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.557694] systemd-journal D 0 983 1 0x00000120
[287100.557695] Call Trace:
[287100.557696] __schedule+0x2e3/0x740
[287100.557697] schedule+0x42/0xb0
[287100.557700] cv_wait_common+0x133/0x180 [spl]
[287100.557701] ? wait_woken+0x80/0x80
[287100.557704] __cv_wait+0x15/0x20 [spl]
[287100.557740] zfs_rangelock_enter_writer+0x41/0x150 [zfs]
[287100.557777] zfs_rangelock_enter+0xb6/0xf0 [zfs]
[287100.557813] zfs_trunc+0x53/0x200 [zfs]
[287100.557845] ? do_raw_spin_unlock+0x9/0x10 [zfs]
[287100.557877] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.557908] ? sa_lookup+0x7c/0x90 [zfs]
[287100.557945] zfs_freesp+0xa8/0x2b0 [zfs]
[287100.557980] ? zfs_zaccess_common+0x78/0xa0 [zfs]
[287100.558015] ? zfs_zaccess+0x24b/0x3e0 [zfs]
[287100.558051] zfs_setattr+0xd76/0x2230 [zfs]
[287100.558087] ? zpl_xattr_get_dir+0x5e/0x130 [zfs]
[287100.558090] ? atomic_dec+0xd/0x20 [spl]
[287100.558122] ? __raw_spin_unlock+0x9/0x10 [zfs]
[287100.558153] ? rrw_exit+0x67/0xc0 [zfs]
[287100.558156] ? atomic_dec_and_test+0xd/0x20 [spl]
[287100.558159] ? put_cred+0x1b/0x30 [spl]
[287100.558160] ? _cond_resched+0x19/0x30
[287100.558161] ? __kmalloc_node+0x205/0x320
[287100.558198] ? zpl_xattr_get+0xdb/0x140 [zfs]
[287100.558201] ? spl_kmem_alloc_impl+0xa8/0x100 [spl]
[287100.558237] zpl_setattr+0xf7/0x160 [zfs]
[287100.558239] notify_change+0x357/0x4e0
[287100.558241] do_truncate+0x78/0xd0
[287100.558242] do_sys_ftruncate+0x14a/0x1c0
[287100.558244] __x64_sys_ftruncate+0x1b/0x20
[287100.558246] do_syscall_64+0x57/0x190
[287100.558248] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[287100.558249] RIP: 0033:0x7f03b5813ccb
[287100.558253] Code: Bad RIP value.
[287100.558253] RSP: 002b:00007ffff85220c8 EFLAGS: 00000202 ORIG_RAX: 000000000000004d
[287100.558254] RAX: ffffffffffffffda RBX: 00007ffff8522100 RCX: 00007f03b5813ccb
[287100.558255] RDX: 0000563417553f90 RSI: 0000000004800000 RDI: 0000000000000034
[287100.558255] RBP: 0000563417611240 R08: 0000000000000001 R09: 00005634176112c4
[287100.558256] R10: 0000000000000000 R11: 0000000000000202 R12: 00007ffff85220f8
[287100.558256] R13: 0000000000000003 R14: 0000000000000000 R15: 0000000000000000
[287100.558270] INFO: task txg_sync:2005 blocked for more than 120 seconds.
[287100.558271] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.558272] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.558273] txg_sync D 0 2005 2 0x80004000
[287100.558273] Call Trace:
[287100.558275] __schedule+0x2e3/0x740
[287100.558277] ? __switch_to+0x7f/0x470
[287100.558278] schedule+0x42/0xb0
[287100.558281] cv_wait_common+0x133/0x180 [spl]
[287100.558282] ? wait_woken+0x80/0x80
[287100.558285] __cv_wait+0x15/0x20 [spl]
[287100.558318] spa_config_enter+0x101/0x110 [zfs]
[287100.558352] spa_txg_history_init_io+0x5e/0xd0 [zfs]
[287100.558385] txg_sync_thread+0x260/0x310 [zfs]
[287100.558418] ? txg_dispatch_callbacks+0x100/0x100 [zfs]
[287100.558422] thread_generic_wrapper+0x83/0xa0 [spl]
[287100.558423] kthread+0x104/0x140
[287100.558426] ? clear_bit+0x20/0x20 [spl]
[287100.558427] ? kthread_park+0x90/0x90
[287100.558429] ret_from_fork+0x35/0x40
[287100.558430] INFO: task mmp:2006 blocked for more than 120 seconds.
[287100.558431] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.558432] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.558432] mmp D 0 2006 2 0x80004000
[287100.558433] Call Trace:
[287100.558434] __schedule+0x2e3/0x740
[287100.558435] ? __wake_up_common_lock+0x8a/0xc0
[287100.558436] schedule+0x42/0xb0
[287100.558439] cv_wait_common+0x133/0x180 [spl]
[287100.558440] ? wait_woken+0x80/0x80
[287100.558443] __cv_wait+0x15/0x20 [spl]
[287100.558475] spa_config_enter+0x101/0x110 [zfs]
[287100.558509] vdev_count_leaves+0x26/0x60 [zfs]
[287100.558540] mmp_thread+0x2a4/0x5a0 [zfs]
[287100.558571] ? mmp_write_uberblock+0x550/0x550 [zfs]
[287100.558575] thread_generic_wrapper+0x83/0xa0 [spl]
[287100.558576] kthread+0x104/0x140
[287100.558580] ? clear_bit+0x20/0x20 [spl]
[287100.558580] ? kthread_park+0x90/0x90
[287100.558582] ret_from_fork+0x35/0x40
[287100.558627] INFO: task deluged:1671679 blocked for more than 120 seconds.
[287100.558627] Tainted: P O 5.4.0-29-generic #33-Ubuntu
[287100.558628] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[287100.558629] deluged D 0 1671679 1 0x00000000
[287100.558629] Call Trace:
[287100.558630] __schedule+0x2e3/0x740
[287100.558631] schedule+0x42/0xb0
[287100.558634] cv_wait_common+0x133/0x180 [spl]
[287100.558635] ? wait_woken+0x80/0x80
[287100.558638] __cv_wait+0x15/0x20 [spl]
[287100.558672] spa_config_enter+0x101/0x110 [zfs]
[287100.558708] zfs_blkptr_verify+0x267/0x440 [zfs]
[287100.558744] zio_read+0x42/0xc0 [zfs]
[287100.558766] ? arc_buf_destroy+0x100/0x100 [zfs]
[287100.558788] arc_read+0x876/0x1100 [zfs]
[287100.558810] ? dbuf_rele_and_unlock+0x4e0/0x4e0 [zfs]
[287100.558846] ? atomic_cmpxchg+0x16/0x30 [zfs]
[287100.558869] dbuf_read_impl+0x1d2/0x610 [zfs]
[287100.558905] ? zio_null+0x2f/0x40 [zfs]
[287100.558927] dbuf_read+0xcb/0x5f0 [zfs]
[287100.558931] ? spl_kmem_free_impl+0x23/0x30 [spl]
[287100.558954] dbuf_hold_impl_arg+0x47a/0x5e0 [zfs]
[287100.558976] dbuf_hold_impl+0x24/0x40 [zfs]
[287100.558998] dbuf_hold_level+0x32/0x60 [zfs]
[287100.559020] dbuf_hold+0x16/0x20 [zfs]
[287100.559044] dmu_buf_hold_array_by_dnode+0xee/0x490 [zfs]
[287100.559068] dmu_read_uio_dnode+0x49/0xf0 [zfs]
[287100.559104] ? zrl_add_impl+0x31/0xb0 [zfs]
[287100.559128] dmu_read_uio_dbuf+0x47/0x60 [zfs]
[287100.559164] zfs_read+0x117/0x300 [zfs]
[287100.559199] zpl_read_common_iovec+0x99/0xe0 [zfs]
[287100.559235] zpl_iter_read_common+0xa8/0x100 [zfs]
[287100.559271] zpl_iter_read+0x58/0x80 [zfs]
[287100.559272] do_iter_readv_writev+0x1a3/0x1d0
[287100.559273] do_iter_read+0xe2/0x1a0
[287100.559275] vfs_readv+0x6e/0xb0
[287100.559276] ? security_file_free+0x54/0x60
[287100.559278] ? call_rcu+0x10/0x20
[287100.559279] ? __fput+0x150/0x260
[287100.559280] do_preadv+0x93/0xd0
[287100.559281] __x64_sys_preadv+0x21/0x30
[287100.559283] do_syscall_64+0x57/0x190
[287100.559284] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[287100.559285] RIP: 0033:0x7f536403d548
[287100.559286] Code: Bad RIP value.
[287100.559287] RSP: 002b:00007f535b7fd4a0 EFLAGS: 00000246 ORIG_RAX: 0000000000000127
[287100.559288] RAX: ffffffffffffffda RBX: 00007f535b7fd600 RCX: 00007f536403d548
[287100.559288] RDX: 0000000000000020 RSI: 00007f535b7fd600 RDI: 0000000000000026
[287100.559289] RBP: 0000000000000000 R08: 0000000000000000 R09: 0000000000000000
[287100.559289] R10: 000000000becd2d0 R11: 0000000000000246 R12: 0000000000000020
[287100.559290] R13: 0000000000000026 R14: 0000000000000020 R15: 000000000becd2d0Had to hard reset with the power button, then after a reboot zpool showed everything healthy and when I ran the same command zpool remove dpool sdb it completed instantly.
edit: after a reboot and reloading deluged, I found that a large number of files which had been open in deluge were all missing. On me for not stopping deluged before running the operation, but I also do not believe it should have crashed. Good thing for external backups, right? :)
Dinth
commented
4 years ago It was fine for past few months (although i wasnt doing any large IO) until yesterday i needed to delete some large files. It froze after few files, i have restarted the server, it booted normally, tried to delete those files again and again it froze after few files, but now i cannot boot as it fails to mount ZFS. So exactly same situation as a couple of months ago. I have increased system memory to 24GB of RAM, but it didnt help
BrainSlayer
commented
4 years ago @Dinth is dedup enabled? deduplication can lead to very high delay times while deleting from my experience
Dinth
commented
4 years ago @Dinth is dedup enabled? deduplication can lead to very high delay times while deleting from my experience
Thanks, indeed, ive got dedup enabled.
rkorzeniewski
commented
3 years ago I'm encountering the same problem for a few days now. I simply delete or write a few GB files and my Debian with ZFS hung for a few hours. Now its load is:
top - 13:43:58 up 1 day, 10:10, 5 users, load average: 379.02, 347.86, 274.68
Tasks: 757 total, 9 running, 740 sleeping, 0 stopped, 8 zombie
%Cpu(s): 0.2 us, 63.3 sy, 0.0 ni, 33.0 id, 3.5 wa, 0.0 hi, 0.0 si, 0.0 st
KiB Mem : 16353716 total, 6877768 free, 7658356 used, 1817592 buff/cache
KiB Swap: 31248380 total, 31248380 free, 0 used. 8301568 avail Mem
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
506 root 20 0 0 0 0 R 71.3 0.0 27:27.29 arc_reclaim
503 root 20 0 0 0 0 R 51.2 0.0 20:25.39 arc_prune
499 root 20 0 0 0 0 R 50.8 0.0 20:25.52 arc_prune
498 root 20 0 0 0 0 R 50.5 0.0 20:25.63 arc_prune
500 root 20 0 0 0 0 R 50.5 0.0 20:25.19 arc_prune
502 root 20 0 0 0 0 R 50.5 0.0 20:25.16 arc_prune
504 root 20 0 0 0 0 R 50.5 0.0 20:25.29 arc_prune
505 root 20 0 0 0 0 S 50.2 0.0 20:25.23 arc_prune
501 root 20 0 0 0 0 R 49.8 0.0 20:25.19 arc_pruneand in the logs I have a repeating:
[119143.874063] INFO: task txg_sync:1858 blocked for more than 120 seconds.
[119143.876337] Tainted: P O 4.9.0-14-amd64 #1 Debian 4.9.240-2
[119143.878581] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[119143.880867] txg_sync D 0 1858 2 0x00000000
[119143.880872] 0000000000000046 ffff99d874158c00 0000000000000000 ffff99d86493c040
[119143.880876] ffff99d89f3d8980 ffff99d88cb10000 ffffb362e207bbb0 ffffffffbe01a969
[119143.880879] ffff99d65f7069f0 00ff99d6b07c19d0 ffff99d89f3d8980 ffff99d886d969b0
[119143.880882] Call Trace:
[119143.880890] [<ffffffffbe01a969>] ? __schedule+0x239/0x6f0
[119143.880893] [<ffffffffbe01ae52>] ? schedule+0x32/0x80
[119143.880896] [<ffffffffbe01e1ed>] ? schedule_timeout+0x1dd/0x380
[119143.880952] [<ffffffffc09ede30>] ? zio_taskq_member.isra.6.constprop.15+0x70/0x70 [zfs]
[119143.880961] [<ffffffffc07b5528>] ? taskq_dispatch_ent+0x58/0xf0 [spl]
[119143.881004] [<ffffffffc09ede30>] ? zio_taskq_member.isra.6.constprop.15+0x70/0x70 [zfs]
[119143.881008] [<ffffffffbda2f240>] ? recalibrate_cpu_khz+0x10/0x10
[119143.881011] [<ffffffffbe01a6cd>] ? io_schedule_timeout+0x9d/0x100
[119143.881018] [<ffffffffc07b961f>] ? cv_wait_common+0xaf/0x120 [spl]
[119143.881022] [<ffffffffbdabf000>] ? prepare_to_wait_event+0xf0/0xf0
[119143.881065] [<ffffffffc09efda2>] ? zio_wait+0xb2/0x140 [zfs]
[119143.881109] [<ffffffffc09996b8>] ? spa_sync+0x3b8/0xb10 [zfs]
[119143.881113] [<ffffffffbdabeab4>] ? __wake_up+0x34/0x50
[119143.881157] [<ffffffffc09a9928>] ? txg_sync_thread+0x3b8/0x610 [zfs]
[119143.881161] [<ffffffffbe01f825>] ? __switch_to_asm+0x35/0x70
[119143.881204] [<ffffffffc09a9570>] ? txg_delay+0x160/0x160 [zfs]
[119143.881211] [<ffffffffc07b4ba0>] ? __thread_exit+0x20/0x20 [spl]
[119143.881217] [<ffffffffc07b4c0f>] ? thread_generic_wrapper+0x6f/0x80 [spl]
[119143.881221] [<ffffffffbda9be69>] ? kthread+0xd9/0xf0
[119143.881225] [<ffffffffbe01f831>] ? __switch_to_asm+0x41/0x70
[119143.881228] [<ffffffffbda9bd90>] ? kthread_park+0x60/0x60
[119143.881231] [<ffffffffbe01f8b7>] ? ret_from_fork+0x57/0x70I'm not sure if this report apply to this issue but I saw I'm not the only one. In my opinion the problem is not related to memory size as I had exactly the same problem with my other server which has 256GB of Ram and fresh and latest Proxmox 6.3-3 with fast SAS disk drives.
seanmikhaels
commented
3 years ago the issue has actually gotten better for me after updating to 5.9 Kernel and zfs 8.5, Will need to do more testing but i am not seeing the freezes using rsync.
Blackclaws
commented
3 years ago I too am seeing this issue on both 5.4.90 and 5.10.7 kernels on archlinux with zfs 2.0.1 when I have heavy sustained io load. This has crashed my server multiple times, memory is not an issue whatsoever as most of it is available and I have 256GB. I am running multiple VMs and it might be that my processors are over comitted.
kjelderg
commented
3 years ago I'm encountering the same problem for a few days now. I simply delete or write a few GB files and my Debian with ZFS hung for a few hours. Now its load is:
top - 13:43:58 up 1 day, 10:10, 5 users, load average: 379.02, 347.86, 274.68 Tasks: 757 total, 9 running, 740 sleeping, 0 stopped, 8 zombie %Cpu(s): 0.2 us, 63.3 sy, 0.0 ni, 33.0 id, 3.5 wa, 0.0 hi, 0.0 si, 0.0 st KiB Mem : 16353716 total, 6877768 free, 7658356 used, 1817592 buff/cache KiB Swap: 31248380 total, 31248380 free, 0 used. 8301568 avail Mem PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 506 root 20 0 0 0 0 R 71.3 0.0 27:27.29 arc_reclaim 503 root 20 0 0 0 0 R 51.2 0.0 20:25.39 arc_prune 499 root 20 0 0 0 0 R 50.8 0.0 20:25.52 arc_prune 498 root 20 0 0 0 0 R 50.5 0.0 20:25.63 arc_prune 500 root 20 0 0 0 0 R 50.5 0.0 20:25.19 arc_prune 502 root 20 0 0 0 0 R 50.5 0.0 20:25.16 arc_prune 504 root 20 0 0 0 0 R 50.5 0.0 20:25.29 arc_prune 505 root 20 0 0 0 0 S 50.2 0.0 20:25.23 arc_prune 501 root 20 0 0 0 0 R 49.8 0.0 20:25.19 arc_pruneand in the logs I have a repeating:
[119143.874063] INFO: task txg_sync:1858 blocked for more than 120 seconds. [119143.876337] Tainted: P O 4.9.0-14-amd64 #1 Debian 4.9.240-2 [119143.878581] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. [119143.880867] txg_sync D 0 1858 2 0x00000000 [119143.880872] 0000000000000046 ffff99d874158c00 0000000000000000 ffff99d86493c040 [119143.880876] ffff99d89f3d8980 ffff99d88cb10000 ffffb362e207bbb0 ffffffffbe01a969 [119143.880879] ffff99d65f7069f0 00ff99d6b07c19d0 ffff99d89f3d8980 ffff99d886d969b0 [119143.880882] Call Trace: [119143.880890] [<ffffffffbe01a969>] ? __schedule+0x239/0x6f0 [119143.880893] [<ffffffffbe01ae52>] ? schedule+0x32/0x80 [119143.880896] [<ffffffffbe01e1ed>] ? schedule_timeout+0x1dd/0x380 [119143.880952] [<ffffffffc09ede30>] ? zio_taskq_member.isra.6.constprop.15+0x70/0x70 [zfs] [119143.880961] [<ffffffffc07b5528>] ? taskq_dispatch_ent+0x58/0xf0 [spl] [119143.881004] [<ffffffffc09ede30>] ? zio_taskq_member.isra.6.constprop.15+0x70/0x70 [zfs] [119143.881008] [<ffffffffbda2f240>] ? recalibrate_cpu_khz+0x10/0x10 [119143.881011] [<ffffffffbe01a6cd>] ? io_schedule_timeout+0x9d/0x100 [119143.881018] [<ffffffffc07b961f>] ? cv_wait_common+0xaf/0x120 [spl] [119143.881022] [<ffffffffbdabf000>] ? prepare_to_wait_event+0xf0/0xf0 [119143.881065] [<ffffffffc09efda2>] ? zio_wait+0xb2/0x140 [zfs] [119143.881109] [<ffffffffc09996b8>] ? spa_sync+0x3b8/0xb10 [zfs] [119143.881113] [<ffffffffbdabeab4>] ? __wake_up+0x34/0x50 [119143.881157] [<ffffffffc09a9928>] ? txg_sync_thread+0x3b8/0x610 [zfs] [119143.881161] [<ffffffffbe01f825>] ? __switch_to_asm+0x35/0x70 [119143.881204] [<ffffffffc09a9570>] ? txg_delay+0x160/0x160 [zfs] [119143.881211] [<ffffffffc07b4ba0>] ? __thread_exit+0x20/0x20 [spl] [119143.881217] [<ffffffffc07b4c0f>] ? thread_generic_wrapper+0x6f/0x80 [spl] [119143.881221] [<ffffffffbda9be69>] ? kthread+0xd9/0xf0 [119143.881225] [<ffffffffbe01f831>] ? __switch_to_asm+0x41/0x70 [119143.881228] [<ffffffffbda9bd90>] ? kthread_park+0x60/0x60 [119143.881231] [<ffffffffbe01f8b7>] ? ret_from_fork+0x57/0x70I'm not sure if this report apply to this issue but I saw I'm not the only one. In my opinion the problem is not related to memory size as I had exactly the same problem with my other server which has 256GB of Ram and fresh and latest Proxmox 6.3-3 with fast SAS disk drives.
I have had this problem recurring with almost exactly the same stack and symptoms on much lower class hardware.
Rpi4, 4GB.
Ubuntu 20.10 Kernel 5.8.0-1011-raspi zfs 0.8.4-1ubuntu11.1
In this case, I have been having it both in raidz and a single-disk zfs. All are connected over USB, so I had initially assumed it was drive response time related, but I am less confident of that as it persists after disabling APM on those drives.
Dinth
commented
3 years ago @kjelderg do you have dedup enabled? For me disabling it helped a lot (but it was not straightforward with the amount of data ive got). Remember that after disabling dedup, you need to overwrite all the files on the array.
kjelderg
commented
3 years ago @kjelderg do you have dedup enabled?
It shows disabled on both of the ZFSs. I appreciate the tip.
SpikedCola
commented
3 years ago Ubuntu 20.04, 5.4.0-64-generic #72-Ubuntu SMP Fri Jan 15 10:27:54 UTC 2021 x86_64 x86_64 x86_64 GNU/Linux ZFS version 0.8.3-1ubuntu12.5, dedupe is off.
I am also seeing this issue. Upgraded from 18.04 to 20.04 recently. Just ran a scrub, and seeing lots of log entries like this, around the same time as I was streaming from the pool:
[35525.161842] INFO: task txg_sync:3568750 blocked for more than 241 seconds.
[35525.161892] Tainted: P O 5.4.0-64-generic #72-Ubuntu
[35525.161929] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[35525.161972] txg_sync D 0 3568750 2 0x80004000
[35525.161975] Call Trace:
[35525.161984] __schedule+0x2e3/0x740
[35525.161990] ? __internal_add_timer+0x2d/0x40
[35525.161993] schedule+0x42/0xb0
[35525.161995] schedule_timeout+0x8a/0x160
[35525.161999] ? __next_timer_interrupt+0xe0/0xe0
[35525.162002] io_schedule_timeout+0x1e/0x50
[35525.162012] __cv_timedwait_common+0x15e/0x1c0 [spl]
[35525.162017] ? wait_woken+0x80/0x80
[35525.162023] __cv_timedwait_io+0x19/0x20 [spl]
[35525.162125] zio_wait+0x11b/0x230 [zfs]
[35525.162207] ? __raw_spin_unlock+0x9/0x10 [zfs]
[35525.162278] dsl_pool_sync+0xbc/0x410 [zfs]
[35525.162356] spa_sync_iterate_to_convergence+0xe0/0x1c0 [zfs]
[35525.162432] spa_sync+0x312/0x5b0 [zfs]
[35525.162512] txg_sync_thread+0x27a/0x310 [zfs]
[35525.162592] ? txg_dispatch_callbacks+0x100/0x100 [zfs]
[35525.162601] thread_generic_wrapper+0x83/0xa0 [spl]
[35525.162604] kthread+0x104/0x140
[35525.162612] ? clear_bit+0x20/0x20 [spl]
[35525.162614] ? kthread_park+0x90/0x90
[35525.162618] ret_from_fork+0x35/0x40
[35766.822880] INFO: task smbd:2685642 blocked for more than 120 seconds.
[35766.822928] Tainted: P O 5.4.0-64-generic #72-Ubuntu
[35766.822965] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[35766.823008] smbd D 0 2685642 2694480 0x00000000
[35766.823011] Call Trace:
[35766.823020] __schedule+0x2e3/0x740
[35766.823023] schedule+0x42/0xb0
[35766.823034] cv_wait_common+0x133/0x180 [spl]
[35766.823039] ? wait_woken+0x80/0x80
[35766.823045] __cv_wait+0x15/0x20 [spl]
[35766.823148] zfs_rangelock_enter_writer+0x41/0x150 [zfs]
[35766.823156] ? spl_kmem_alloc_impl+0xa8/0x100 [spl]
[35766.823232] ? do_raw_spin_unlock+0x9/0x10 [zfs]
[35766.823318] zfs_rangelock_enter+0xb6/0xf0 [zfs]
[35766.823404] zfs_write+0xa8c/0xd40 [zfs]
[35766.823492] zpl_write_common_iovec+0xad/0x120 [zfs]
[35766.823578] zpl_iter_write_common+0x8e/0xb0 [zfs]
[35766.823663] zpl_iter_write+0x56/0x90 [zfs]
[35766.823666] new_sync_write+0x125/0x1c0
[35766.823669] __vfs_write+0x29/0x40
[35766.823671] vfs_write+0xb9/0x1a0
[35766.823674] ksys_pwrite64+0x6d/0xa0
[35766.823676] __x64_sys_pwrite64+0x1e/0x20
[35766.823680] do_syscall_64+0x57/0x190
[35766.823684] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[35766.823686] RIP: 0033:0x7f6785b9dcbf
[35766.823694] Code: Bad RIP value.
[35766.823695] RSP: 002b:00007f66f8ff8b20 EFLAGS: 00000293 ORIG_RAX: 0000000000000012
[35766.823698] RAX: ffffffffffffffda RBX: 00005640386aa8a0 RCX: 00007f6785b9dcbf
[35766.823699] RDX: 00000000002bf030 RSI: 000056404871b8e0 RDI: 0000000000000021
[35766.823700] RBP: 0000564032a43530 R08: 0000000000000000 R09: 00007f66f8ff8ba8
[35766.823701] R10: 0000000013fc1000 R11: 0000000000000293 R12: 00007f66f8ff8ba0
[35766.823702] R13: 0000564032a43568 R14: 00005640386aac00 R15: 00007f678557a640The pool is still operational, but streaming often suffers. Sometimes zfs list or zpool status hang indefinitely unless I stop streaming from the pool.
HBA: 2x Dell H310 CPU: Intel(R) Core(TM) i3-3240 CPU @ 3.40GHz (no ECC) 16GB RAM:
# free -m
total used free shared buff/cache available
Mem: 15954 13184 1040 12 1729 2424
Swap: 985 15 969# zpool status
pool: storage
state: ONLINE
scan: scrub repaired 0B in 0 days 22:51:07 with 0 errors on Thu Jan 21 17:26:16 2021
config:
NAME STATE READ WRITE CKSUM
storage ONLINE 0 0 0
raidz2-0 ONLINE 0 0 0
scsi-SATA_WDC_WD40EZRX-00S_WD-WCC4E1ESZ6NA ONLINE 0 0 0
scsi-SATA_ST4000DM004-2CV1_ZFN0E4S0 ONLINE 0 0 0
scsi-SATA_WDC_WD40EZRX-00S_WD-WCC4E2PTVR39 ONLINE 0 0 0
scsi-SATA_ST3000DM001-1ER1_Z500LL29 ONLINE 0 0 0
scsi-SATA_WDC_WD40EFRX-68N_WD-WCC7K4UFJTZ1 ONLINE 0 0 0
scsi-SATA_ST3000DM001-1ER1_Z500HPYX ONLINE 0 0 0
raidz2-1 ONLINE 0 0 0
scsi-SATA_WDC_WD40EZRX-00S_WD-WCC4E52URNK6 ONLINE 0 0 0
scsi-SATA_WDC_WD40EZRX-00S_WD-WCC4E0JJXUCE ONLINE 0 0 0
scsi-SATA_ST4000DM000-1F21_Z302BF4W ONLINE 0 0 0
scsi-SATA_WDC_WD40EFRX-68N_WD-WCC7K4UFJ8EH ONLINE 0 0 0
scsi-SATA_ST4000DM000-1F21_Z302PD5X ONLINE 0 0 0
scsi-SATA_WDC_WD40EZRX-00S_WD-WCC4E0946390 ONLINE 0 0 0
errors: No known data errors# zfs list
NAME SIZE ALLOC FREE CKPOINT EXPANDSZ FRAG CAP DEDUP HEALTH ALTROOT
storage 38.1T 35.4T 2.69T - - 34% 92% 1.00x ONLINE -This problem has been hitting with incredible frequency lately. From a reboot to failure is taking about 20 minutes. I would be happy to test whatever suggestions people can think of.
An example dmesg:
[ 1451.006444] INFO: task txg_sync:87191 blocked for more than 120 seconds.
[ 1451.013305] Tainted: P WC OE 5.8.0-1011-raspi #14-Ubuntu
[ 1451.020249] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1451.028401] txg_sync D 0 87191 2 0x00000028
[ 1451.028439] Call trace:
[ 1451.028457] __switch_to+0xfc/0x12c
[ 1451.028468] __schedule+0x2a8/0x72c
[ 1451.028474] schedule+0x84/0x120
[ 1451.028482] schedule_timeout+0x88/0x100
[ 1451.028489] io_schedule_timeout+0x54/0x74
[ 1451.028528] __cv_timedwait_common+0xe0/0x210 [spl]
[ 1451.028552] __cv_timedwait_io+0x24/0x30 [spl]
[ 1451.028762] zio_wait+0x138/0x260 [zfs]
[ 1451.028955] dsl_pool_sync+0xe4/0x470 [zfs]
[ 1451.029099] spa_sync+0x534/0xe1c [zfs]
[ 1451.029239] txg_sync_thread+0x2c4/0x450 [zfs]
[ 1451.029264] thread_generic_wrapper+0x6c/0x84 [spl]
[ 1451.029275] kthread+0x138/0x14c
[ 1451.029283] ret_from_fork+0x10/0x34
[ 1692.675160] INFO: task txg_sync:87191 blocked for more than 120 seconds.
[ 1692.682015] Tainted: P WC OE 5.8.0-1011-raspi #14-Ubuntu
[ 1692.688970] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1692.697026] txg_sync D 0 87191 2 0x00000028
[ 1692.697041] Call trace:
[ 1692.697057] __switch_to+0xfc/0x12c
[ 1692.697092] __schedule+0x2a8/0x72c
[ 1692.697099] schedule+0x84/0x120
[ 1692.697107] schedule_timeout+0x88/0x100
[ 1692.697114] io_schedule_timeout+0x54/0x74
[ 1692.697148] __cv_timedwait_common+0xe0/0x210 [spl]
[ 1692.697174] __cv_timedwait_io+0x24/0x30 [spl]
[ 1692.697349] zio_wait+0x138/0x260 [zfs]
[ 1692.697520] dsl_pool_sync+0xe4/0x470 [zfs]
[ 1692.697662] spa_sync+0x534/0xe1c [zfs]
[ 1692.697802] txg_sync_thread+0x2c4/0x450 [zfs]
[ 1692.697829] thread_generic_wrapper+0x6c/0x84 [spl]
[ 1692.697839] kthread+0x138/0x14c
[ 1692.697847] ret_from_fork+0x10/0x34
[ 2417.682362] INFO: task txg_sync:87191 blocked for more than 120 seconds.In looking through syslog, I do see something potentially damning. Note that which drive "goes bad' differs from reboot to reboot.
Jan 25 03:10:14 ubuntu kernel: [23533.059295] xhci_hcd 0000:01:00.0: WARN Cannot submit Set TR Deq Ptr
Jan 25 03:10:14 ubuntu kernel: [23533.059308] xhci_hcd 0000:01:00.0: A Set TR Deq Ptr command is pending.
Jan 25 03:10:14 ubuntu kernel: [23533.140002] usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jan 25 03:10:14 ubuntu smartd[10719]: Device: /dev/sda [SAT], is in SLEEP mode, suspending checks
Jan 25 03:10:15 ubuntu smartd[10719]: Device: /dev/sdb [SAT], SMART Usage Attribute: 7 Seek_Error_Rate changed from 200 to 100
Jan 25 03:10:20 ubuntu smartd[10719]: Device: /dev/sdc [SAT], SMART Usage Attribute: 194 Temperature_Celsius changed from 116 to 115
Jan 25 03:10:45 ubuntu kernel: [23563.780001] xhci_hcd 0000:01:00.0: WARN Cannot submit Set TR Deq Ptr
Jan 25 03:10:45 ubuntu kernel: [23563.780008] xhci_hcd 0000:01:00.0: A Set TR Deq Ptr command is pending.
Jan 25 03:10:45 ubuntu kernel: [23563.860518] usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jan 25 03:10:45 ubuntu kernel: [23563.882530] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=30s
Jan 25 03:10:45 ubuntu kernel: [23563.882542] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 2e 2d 82 20 00 00 02 00 00 00
Jan 25 03:10:45 ubuntu kernel: [23563.882551] blk_update_request: I/O error, dev sda, sector 774734368 op 0x0:(READ) flags 0x4700 phys_seg 4 prio class 0
Jan 25 03:11:15 ubuntu kernel: [23594.500724] xhci_hcd 0000:01:00.0: WARN Cannot submit Set TR Deq Ptr
Jan 25 03:11:15 ubuntu kernel: [23594.500737] xhci_hcd 0000:01:00.0: A Set TR Deq Ptr command is pending.
Jan 25 03:11:15 ubuntu kernel: [23594.581340] usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jan 25 03:11:15 ubuntu kernel: [23594.603283] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=30s
Jan 25 03:11:15 ubuntu kernel: [23594.603305] sd 0:0:0:0: [sda] tag#0 CDB: Read(16) 88 00 00 00 00 00 2e 2d 84 20 00 00 02 00 00 00
Jan 25 03:11:15 ubuntu kernel: [23594.603324] blk_update_request: I/O error, dev sda, sector 774734880 op 0x0:(READ) flags 0x700 phys_seg 4 prio class 0
**Jan 25 03:11:15 ubuntu kernel: [23594.614340] zio pool=m vdev=/dev/disk/by-id/usb-WD_easystore_2647_575846324532303538324453-0:0-part1 error=5 type=1 offset=396662423552 size=1048576 flags=40080cb0**
Jan 25 03:11:46 ubuntu kernel: [23625.221388] xhci_hcd 0000:01:00.0: WARN Cannot submit Set TR Deq Ptr
Jan 25 03:11:46 ubuntu kernel: [23625.221401] xhci_hcd 0000:01:00.0: A Set TR Deq Ptr command is pending.
Jan 25 03:11:46 ubuntu kernel: [23625.302048] usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jan 25 03:11:46 ubuntu kernel: [23625.323859] sd 0:0:0:0: [sda] tag#0 FAILED Result: hostbyte=DID_TIME_OUT driverbyte=DRIVER_OK cmd_age=30s
Jan 25 03:11:46 ubuntu kernel: [23625.323874] sd 0:0:0:0: [sda] tag#0 CDB: Write(16) 8a 00 00 00 00 01 fe bd d7 28 00 00 00 20 00 00
Jan 25 03:11:46 ubuntu kernel: [23625.323887] blk_update_request: I/O error, dev sda, sector 8568821544 op 0x1:(WRITE) flags 0x700 phys_seg 4 prio class 0
Jan 25 03:11:46 ubuntu kernel: [23625.334987] zio pool=m vdev=/dev/disk/by-id/usb-WD_easystore_2647_575846324532303538324453-0:0-part1 error=5 type=2 offset=4387235581952 size=16384 flags=180880
Jan 25 03:12:17 ubuntu kernel: [23655.942074] xhci_hcd 0000:01:00.0: WARN Cannot submit Set TR Deq Ptr
Jan 25 03:12:17 ubuntu kernel: [23655.942086] xhci_hcd 0000:01:00.0: A Set TR Deq Ptr command is pending.
Jan 25 03:12:17 ubuntu kernel: [23656.022716] usb 2-1.2: reset SuperSpeed Gen 1 USB device number 4 using xhci_hcd
Jan 25 03:12:45 ubuntu kernel: [23684.602611] INFO: task txg_sync:2311 blocked for more than 120 seconds.
Jan 25 03:12:45 ubuntu kernel: [23684.609376] Tainted: P WC OE 5.8.0-1011-raspi #14-Ubuntu
Jan 25 03:12:45 ubuntu kernel: [23684.616381] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 25 03:12:45 ubuntu kernel: [23684.624361] txg_sync D 0 2311 2 0x00000028
Jan 25 03:12:45 ubuntu kernel: [23684.624370] Call trace:
Jan 25 03:12:45 ubuntu kernel: [23684.624383] __switch_to+0xfc/0x12c
Jan 25 03:12:45 ubuntu kernel: [23684.624392] __schedule+0x2a8/0x72c
Jan 25 03:12:45 ubuntu kernel: [23684.624396] schedule+0x84/0x120
Jan 25 03:12:45 ubuntu kernel: [23684.624401] schedule_timeout+0x88/0x100
Jan 25 03:12:45 ubuntu kernel: [23684.624405] io_schedule_timeout+0x54/0x74
Jan 25 03:12:45 ubuntu kernel: [23684.624433] __cv_timedwait_common+0xe0/0x210 [spl]
Jan 25 03:12:45 ubuntu kernel: [23684.624449] __cv_timedwait_io+0x24/0x30 [spl]
Jan 25 03:12:45 ubuntu kernel: [23684.624594] zio_wait+0x138/0x260 [zfs]
Jan 25 03:12:45 ubuntu kernel: [23684.624688] dsl_scan_sync+0xc20/0x1120 [zfs]
Jan 25 03:12:45 ubuntu kernel: [23684.624782] spa_sync+0x59c/0xe1c [zfs]
Jan 25 03:12:45 ubuntu kernel: [23684.624877] txg_sync_thread+0x2c4/0x450 [zfs]
Jan 25 03:12:45 ubuntu kernel: [23684.624896] thread_generic_wrapper+0x6c/0x84 [spl]
Jan 25 03:12:45 ubuntu kernel: [23684.624902] kthread+0x138/0x14c
Jan 25 03:12:45 ubuntu kernel: [23684.624907] ret_from_fork+0x10/0x34
Jan 25 03:12:45 ubuntu kernel: [23684.631944] Tainted: P WC OE 5.8.0-1011-raspi #14-Ubuntu
Jan 25 03:12:45 ubuntu kernel: [23684.638867] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.So it looks like I am having a drive timeout and then the zpool stops working appropriately. Reads hang indefinitely, the zpool is quite unusable. Despite that, introspection thinks everything is A-OK.
➜ ~ sudo zpool status
pool: m
state: ONLINE
status: One or more devices has experienced an error resulting in data
corruption. Applications may be affected.
action: Restore the file in question if possible. Otherwise restore the
entire pool from backup.
see: http://zfsonlinux.org/msg/ZFS-8000-8A
scan: scrub in progress since Fri Jan 22 18:05:47 2021
6.58T scanned at 716K/s, 6.11T issued at 402K/s, 6.84T total
0B repaired, 89.21% done, no estimated completion time
config:
NAME STATE READ WRITE CKSUM
m ONLINE 0 0 0
raidz1-0 ONLINE 0 0 0
usb-WD_easystore_2647_575846324532303432583054-0:0 ONLINE 0 0 0
usb-WD_easystore_2647_575846324532303538324453-0:0 ONLINE 0 0 0
usb-WD_My_Passport_260D_5758523245363030485A4458-0:0 ONLINE 0 0 0
thulle
commented
3 years ago @kjelderg Your issue seem unrelated to ZFS i think, you just get a trace what ZFS was doing when the HDD randomly freezes.
https://github.com/raspberrypi/linux/issues/3981 suggests trying an older kernel.
kirscheGIT
commented
3 years ago | Type | Version/Name |
|---|---|
| Distribution Name | Proxmox |
| Distribution Version | 6.3.3 |
| Linux Kernel | 5.4.78-2-pve |
| Architecture | CPU: Intel Xeon E2146G Memory: 64 GB Kingston ECC Mainboard: Fujitsu (now Kontron): D3644-B |
| ZFS Version | 0.8.5-pve1 |
| SPL Version | 0.8.5-pve1 |
| Network | 1x 1 Gbe Intel I219-LM onboard for maintenance and webinterface 1x 10 Gbe Intel X550T (second port not used) |
| Drives | HDD: 4x Seagate ST4000VN008 (Ironwolf) Configured as ZFS RAID-10 (2x2) for bind mounts (name: hdd_zfs_guests) SSD: 2x Crucial CT2000MX500 - Configured as ZFS RAID-1 for VMs and CTs (name: hdd_zfs_ssd) NVME: 1x Samsung 970 EVO 250Gb as Boot device and Proxmox installation drive |
| Server Build date | Spring 2019 - Upgrade with 2x SSDs for the second pool early November 2020 |
Hello togehter,
not 100% sure but I seem to run into the same problem. Beforehand: The problem seems only happens when accessing the HDD Pool not the SSD Pool.
This is post is related and in parts a duplication to my post on the Proxmox forum. However I tried to condense the informations from the other thread here. First thought it might be due to my migration to Proxmox 6.3-3
[In short] After upgrading from Proxmox 6.2 to 6.3 mid of December I noticed a massive performance drop on my HDD based ZFS-pool. Performance dropped in my SAMBA use case from 110 MByte/s Network copy speed to below 1 MByte/s. Copy jobs from the HDD pool to the SSD based ZFS pool and vice versa see similar performance hits.
[Symptoms in detail] I create - on a regular basis - full images of my workstation to be fast back on track in case of a hard drive defect. Images are first stored on a local USB-drive and in a second step copied over to the SAMBA server running on my Proxmox server via robocopy. Before the upgrade to Proxmox 6.3 the robocopy process to the SAMBA server was finished in roughly 80 - 90 Minutes for an image of 490 Gbyte in size. Since the upgrade, the copy process now takes forever. In the Windows task manager you'll see that the data is first copied with full line speed at a rate of 110 MByte/s. After a few seconds the performance drops to below 1 MByte/s and stays there for roughly a minute. In the same time the IO delay on the servers shoots to over 60% - sometimes 80%. Then performance comes back for a few seconds before it drops again. This looks like a saw tooth function. To pin point the problem I made some tests with copy processes from my SSD-Pool to the HDD-Pool and vice versa without running CTs and VMs. The effect looks the same. First it starts with high copy rates and after a few seconds the performance drops down to unusable speeds below 1 MByte/s.
Copy with pv
root@proxmox02:/hdd_zfs_guests# head -c 100G </dev/urandom > /hdd_zfs_ssd/random_data.ran
root@proxmox02:/hdd_zfs_guests# pv -pra /hdd_zfs_ssd/random_data.ran > ./random_data.ran
[1.42MiB/s] [33.5MiB/s] [===========> I find in the syslog the following:
Jan 27 17:22:42 proxmox02 pvesh[1591]: Starting CT 302
Jan 27 17:22:42 proxmox02 pve-guests[1592]: <root@pam> starting task UPID:proxmox02:00000629:00004C15:60119352:vzstart:302:root@pam:
Jan 27 17:22:42 proxmox02 pve-guests[1577]: starting CT 302: UPID:proxmox02:00000629:00004C15:60119352:vzstart:302:root@pam:
Jan 27 17:23:00 proxmox02 systemd[1]: Starting Proxmox VE replication runner...
Jan 27 17:23:00 proxmox02 systemd[1]: pvesr.service: Succeeded.
Jan 27 17:23:00 proxmox02 systemd[1]: Started Proxmox VE replication runner.
Jan 27 17:23:30 proxmox02 kernel: INFO: task zpool:3524 blocked for more than 120 seconds.
Jan 27 17:23:30 proxmox02 kernel: Tainted: P O 5.4.78-2-pve #1
Jan 27 17:23:30 proxmox02 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 27 17:23:30 proxmox02 kernel: zpool D 0 3524 1546 0x80004006
Jan 27 17:23:30 proxmox02 kernel: Call Trace:
Jan 27 17:23:30 proxmox02 kernel: __schedule+0x2e6/0x6f0
Jan 27 17:23:30 proxmox02 kernel: schedule+0x33/0xa0
Jan 27 17:23:30 proxmox02 kernel: io_schedule+0x16/0x40
Jan 27 17:23:30 proxmox02 kernel: cv_wait_common+0xb5/0x130 [spl]
Jan 27 17:23:30 proxmox02 kernel: ? wait_woken+0x80/0x80
Jan 27 17:23:30 proxmox02 kernel: __cv_wait_io+0x18/0x20 [spl]
Jan 27 17:23:30 proxmox02 kernel: txg_wait_synced_impl+0xc9/0x110 [zfs]
Jan 27 17:23:30 proxmox02 kernel: txg_wait_synced+0x10/0x40 [zfs]
Jan 27 17:23:30 proxmox02 kernel: spa_config_update+0x139/0x180 [zfs]
Jan 27 17:23:30 proxmox02 kernel: spa_import+0x5ed/0x7f0 [zfs]
Jan 27 17:23:30 proxmox02 kernel: ? nvpair_value_common.part.13+0x14d/0x170 [znvpair]
Jan 27 17:23:30 proxmox02 kernel: zfs_ioc_pool_import+0x12d/0x150 [zfs]
Jan 27 17:23:30 proxmox02 kernel: zfsdev_ioctl+0x6db/0x8f0 [zfs]
Jan 27 17:23:30 proxmox02 kernel: ? lru_cache_add_active_or_unevictable+0x39/0xb0
Jan 27 17:23:30 proxmox02 kernel: do_vfs_ioctl+0xa9/0x640
Jan 27 17:23:30 proxmox02 kernel: ? handle_mm_fault+0xc9/0x1f0
Jan 27 17:23:30 proxmox02 kernel: ksys_ioctl+0x67/0x90
Jan 27 17:23:30 proxmox02 kernel: __x64_sys_ioctl+0x1a/0x20
Jan 27 17:23:30 proxmox02 kernel: do_syscall_64+0x57/0x190
Jan 27 17:23:30 proxmox02 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jan 27 17:23:30 proxmox02 kernel: RIP: 0033:0x7f6138f19427
Jan 27 17:23:30 proxmox02 kernel: Code: Bad RIP value.
Jan 27 17:23:30 proxmox02 kernel: RSP: 002b:00007ffd7d737c18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jan 27 17:23:30 proxmox02 kernel: RAX: ffffffffffffffda RBX: 00007ffd7d737c90 RCX: 00007f6138f19427
Jan 27 17:23:30 proxmox02 kernel: RDX: 00007ffd7d737c90 RSI: 0000000000005a02 RDI: 0000000000000003
Jan 27 17:23:30 proxmox02 kernel: RBP: 00007ffd7d73bb80 R08: 000055db03e51430 R09: 000000000000007a
Jan 27 17:23:30 proxmox02 kernel: R10: 000055db03e16010 R11: 0000000000000246 R12: 000055db03e162e0
Jan 27 17:23:30 proxmox02 kernel: R13: 000055db03e31078 R14: 0000000000000000 R15: 0000000000000000
Jan 27 17:24:00 proxmox02 systemd[1]: Starting Proxmox VE replication runner...
Jan 27 17:24:00 proxmox02 systemd[1]: pvesr.service: Succeeded.
Jan 27 17:24:00 proxmox02 systemd[1]: Started Proxmox VE replication runner.
Jan 27 17:24:49 proxmox02 pvedaemon[1574]: <root@pam> successful auth for user 'root@pam'
Jan 27 17:25:00 proxmox02 systemd[1]: Starting Proxmox VE replication runner...
Jan 27 17:25:00 proxmox02 systemd[1]: pvesr.service: Succeeded.
Jan 27 17:25:00 proxmox02 systemd[1]: Started Proxmox VE replication runner.
Jan 27 17:25:31 proxmox02 kernel: INFO: task zpool:3524 blocked for more than 241 seconds.
Jan 27 17:25:31 proxmox02 kernel: Tainted: P O 5.4.78-2-pve #1
Jan 27 17:25:31 proxmox02 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 27 17:25:31 proxmox02 kernel: zpool D 0 3524 1546 0x80004006
Jan 27 17:25:31 proxmox02 kernel: Call Trace:
Jan 27 17:25:31 proxmox02 kernel: __schedule+0x2e6/0x6f0
Jan 27 17:25:31 proxmox02 kernel: schedule+0x33/0xa0
Jan 27 17:25:31 proxmox02 kernel: io_schedule+0x16/0x40
Jan 27 17:25:31 proxmox02 kernel: cv_wait_common+0xb5/0x130 [spl]
Jan 27 17:25:31 proxmox02 kernel: ? wait_woken+0x80/0x80
Jan 27 17:25:31 proxmox02 kernel: __cv_wait_io+0x18/0x20 [spl]
Jan 27 17:25:31 proxmox02 kernel: txg_wait_synced_impl+0xc9/0x110 [zfs]
Jan 27 17:25:31 proxmox02 kernel: txg_wait_synced+0x10/0x40 [zfs]
Jan 27 17:25:31 proxmox02 kernel: spa_config_update+0x139/0x180 [zfs]
Jan 27 17:25:31 proxmox02 kernel: spa_import+0x5ed/0x7f0 [zfs]
Jan 27 17:25:31 proxmox02 kernel: ? nvpair_value_common.part.13+0x14d/0x170 [znvpair]
Jan 27 17:25:31 proxmox02 kernel: zfs_ioc_pool_import+0x12d/0x150 [zfs]
Jan 27 17:25:31 proxmox02 kernel: zfsdev_ioctl+0x6db/0x8f0 [zfs]
Jan 27 17:25:31 proxmox02 kernel: ? lru_cache_add_active_or_unevictable+0x39/0xb0
Jan 27 17:25:31 proxmox02 kernel: do_vfs_ioctl+0xa9/0x640
Jan 27 17:25:31 proxmox02 kernel: ? handle_mm_fault+0xc9/0x1f0
Jan 27 17:25:31 proxmox02 kernel: ksys_ioctl+0x67/0x90
Jan 27 17:25:31 proxmox02 kernel: __x64_sys_ioctl+0x1a/0x20
Jan 27 17:25:31 proxmox02 kernel: do_syscall_64+0x57/0x190
Jan 27 17:25:31 proxmox02 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jan 27 17:25:31 proxmox02 kernel: RIP: 0033:0x7f6138f19427
Jan 27 17:25:31 proxmox02 kernel: Code: Bad RIP value.
Jan 27 17:25:31 proxmox02 kernel: RSP: 002b:00007ffd7d737c18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jan 27 17:25:31 proxmox02 kernel: RAX: ffffffffffffffda RBX: 00007ffd7d737c90 RCX: 00007f6138f19427
Jan 27 17:25:31 proxmox02 kernel: RDX: 00007ffd7d737c90 RSI: 0000000000005a02 RDI: 0000000000000003
Jan 27 17:25:31 proxmox02 kernel: RBP: 00007ffd7d73bb80 R08: 000055db03e51430 R09: 000000000000007a
Jan 27 17:25:31 proxmox02 kernel: R10: 000055db03e16010 R11: 0000000000000246 R12: 000055db03e162e0
Jan 27 17:25:31 proxmox02 kernel: R13: 000055db03e31078 R14: 0000000000000000 R15: 0000000000000000
Jan 27 17:25:31 proxmox02 kernel: INFO: task zpool:1586 blocked for more than 120 seconds.
Jan 27 17:25:31 proxmox02 kernel: Tainted: P O 5.4.78-2-pve #1
Jan 27 17:25:31 proxmox02 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 27 17:25:31 proxmox02 kernel: zpool D 0 1586 1577 0x00000000
Jan 27 17:25:31 proxmox02 kernel: Call Trace:
Jan 27 17:25:31 proxmox02 kernel: __schedule+0x2e6/0x6f0
Jan 27 17:25:31 proxmox02 kernel: schedule+0x33/0xa0
Jan 27 17:25:31 proxmox02 kernel: schedule_preempt_disabled+0xe/0x10
Jan 27 17:25:31 proxmox02 kernel: __mutex_lock.isra.10+0x2c9/0x4c0
Jan 27 17:25:31 proxmox02 kernel: __mutex_lock_slowpath+0x13/0x20
Jan 27 17:25:31 proxmox02 kernel: mutex_lock+0x2c/0x30
Jan 27 17:25:31 proxmox02 kernel: spa_open_common+0x62/0x4d0 [zfs]
Jan 27 17:25:31 proxmox02 kernel: spa_get_stats+0x57/0x570 [zfs]
Jan 27 17:25:31 proxmox02 kernel: ? kmalloc_large_node+0x86/0x90
Jan 27 17:25:31 proxmox02 kernel: ? __kmalloc_node+0x267/0x330
Jan 27 17:25:31 proxmox02 kernel: zfs_ioc_pool_stats+0x39/0x90 [zfs]
Jan 27 17:25:31 proxmox02 kernel: zfsdev_ioctl+0x6db/0x8f0 [zfs]
Jan 27 17:25:31 proxmox02 kernel: ? lru_cache_add_active_or_unevictable+0x39/0xb0
Jan 27 17:25:31 proxmox02 kernel: do_vfs_ioctl+0xa9/0x640
Jan 27 17:25:31 proxmox02 kernel: ? handle_mm_fault+0xc9/0x1f0
Jan 27 17:25:31 proxmox02 kernel: ksys_ioctl+0x67/0x90
Jan 27 17:25:31 proxmox02 kernel: __x64_sys_ioctl+0x1a/0x20
Jan 27 17:25:31 proxmox02 kernel: do_syscall_64+0x57/0x190
Jan 27 17:25:31 proxmox02 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jan 27 17:25:31 proxmox02 kernel: RIP: 0033:0x7f1a2d89f427
Jan 27 17:25:31 proxmox02 kernel: Code: Bad RIP value.
Jan 27 17:25:31 proxmox02 kernel: RSP: 002b:00007fff9dd2e5e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jan 27 17:25:31 proxmox02 kernel: RAX: ffffffffffffffda RBX: 00007fff9dd2e610 RCX: 00007f1a2d89f427
Jan 27 17:25:31 proxmox02 kernel: RDX: 00007fff9dd2e610 RSI: 0000000000005a05 RDI: 0000000000000003
Jan 27 17:25:31 proxmox02 kernel: RBP: 00007fff9dd31bf0 R08: 000055ac0421c680 R09: 00007f1a2d96ade0
Jan 27 17:25:31 proxmox02 kernel: R10: 000055ac0421a010 R11: 0000000000000246 R12: 000055ac0421c530
Jan 27 17:25:31 proxmox02 kernel: R13: 000055ac0421a2e0 R14: 0000000000000000 R15: 00007fff9dd31c04
Jan 27 17:26:00 proxmox02 systemd[1]: Starting Proxmox VE replication runner...
Jan 27 17:26:00 proxmox02 systemd[1]: pvesr.service: Succeeded.
Jan 27 17:26:00 proxmox02 systemd[1]: Started Proxmox VE replication runner.
Jan 27 17:27:00 proxmox02 systemd[1]: Starting Proxmox VE replication runner...
Jan 27 17:27:00 proxmox02 systemd[1]: pvesr.service: Succeeded.
Jan 27 17:27:00 proxmox02 systemd[1]: Started Proxmox VE replication runner.
Jan 27 17:27:32 proxmox02 kernel: INFO: task zpool:3524 blocked for more than 362 seconds.
Jan 27 17:27:32 proxmox02 kernel: Tainted: P O 5.4.78-2-pve #1
Jan 27 17:27:32 proxmox02 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 27 17:27:32 proxmox02 kernel: zpool D 0 3524 1546 0x80004006
Jan 27 17:27:32 proxmox02 kernel: Call Trace:
Jan 27 17:27:32 proxmox02 kernel: __schedule+0x2e6/0x6f0
Jan 27 17:27:32 proxmox02 kernel: schedule+0x33/0xa0
Jan 27 17:27:32 proxmox02 kernel: io_schedule+0x16/0x40
Jan 27 17:27:32 proxmox02 kernel: cv_wait_common+0xb5/0x130 [spl]
Jan 27 17:27:32 proxmox02 kernel: ? wait_woken+0x80/0x80
Jan 27 17:27:32 proxmox02 kernel: __cv_wait_io+0x18/0x20 [spl]
Jan 27 17:27:32 proxmox02 kernel: txg_wait_synced_impl+0xc9/0x110 [zfs]
Jan 27 17:27:32 proxmox02 kernel: txg_wait_synced+0x10/0x40 [zfs]
Jan 27 17:27:32 proxmox02 kernel: spa_config_update+0x139/0x180 [zfs]
Jan 27 17:27:32 proxmox02 kernel: spa_import+0x5ed/0x7f0 [zfs]
Jan 27 17:27:32 proxmox02 kernel: ? nvpair_value_common.part.13+0x14d/0x170 [znvpair]
Jan 27 17:27:32 proxmox02 kernel: zfs_ioc_pool_import+0x12d/0x150 [zfs]
Jan 27 17:27:32 proxmox02 kernel: zfsdev_ioctl+0x6db/0x8f0 [zfs]
Jan 27 17:27:32 proxmox02 kernel: ? lru_cache_add_active_or_unevictable+0x39/0xb0
Jan 27 17:27:32 proxmox02 kernel: do_vfs_ioctl+0xa9/0x640
Jan 27 17:27:32 proxmox02 kernel: ? handle_mm_fault+0xc9/0x1f0
Jan 27 17:27:32 proxmox02 kernel: ksys_ioctl+0x67/0x90
Jan 27 17:27:32 proxmox02 kernel: __x64_sys_ioctl+0x1a/0x20
Jan 27 17:27:32 proxmox02 kernel: do_syscall_64+0x57/0x190
Jan 27 17:27:32 proxmox02 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jan 27 17:27:32 proxmox02 kernel: RIP: 0033:0x7f6138f19427
Jan 27 17:27:32 proxmox02 kernel: Code: Bad RIP value.
Jan 27 17:27:32 proxmox02 kernel: RSP: 002b:00007ffd7d737c18 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jan 27 17:27:32 proxmox02 kernel: RAX: ffffffffffffffda RBX: 00007ffd7d737c90 RCX: 00007f6138f19427
Jan 27 17:27:32 proxmox02 kernel: RDX: 00007ffd7d737c90 RSI: 0000000000005a02 RDI: 0000000000000003
Jan 27 17:27:32 proxmox02 kernel: RBP: 00007ffd7d73bb80 R08: 000055db03e51430 R09: 000000000000007a
Jan 27 17:27:32 proxmox02 kernel: R10: 000055db03e16010 R11: 0000000000000246 R12: 000055db03e162e0
Jan 27 17:27:32 proxmox02 kernel: R13: 000055db03e31078 R14: 0000000000000000 R15: 0000000000000000
Jan 27 17:27:32 proxmox02 kernel: INFO: task zpool:1586 blocked for more than 241 seconds.
Jan 27 17:27:32 proxmox02 kernel: Tainted: P O 5.4.78-2-pve #1
Jan 27 17:27:32 proxmox02 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jan 27 17:27:32 proxmox02 kernel: zpool D 0 1586 1577 0x00000000
Jan 27 17:27:32 proxmox02 kernel: Call Trace:
Jan 27 17:27:32 proxmox02 kernel: __schedule+0x2e6/0x6f0
Jan 27 17:27:32 proxmox02 kernel: schedule+0x33/0xa0
Jan 27 17:27:32 proxmox02 kernel: schedule_preempt_disabled+0xe/0x10
Jan 27 17:27:32 proxmox02 kernel: __mutex_lock.isra.10+0x2c9/0x4c0
Jan 27 17:27:32 proxmox02 kernel: __mutex_lock_slowpath+0x13/0x20
Jan 27 17:27:32 proxmox02 kernel: mutex_lock+0x2c/0x30
Jan 27 17:27:32 proxmox02 kernel: spa_open_common+0x62/0x4d0 [zfs]
Jan 27 17:27:32 proxmox02 kernel: spa_get_stats+0x57/0x570 [zfs]
Jan 27 17:27:32 proxmox02 kernel: ? kmalloc_large_node+0x86/0x90
Jan 27 17:27:32 proxmox02 kernel: ? __kmalloc_node+0x267/0x330
Jan 27 17:27:32 proxmox02 kernel: zfs_ioc_pool_stats+0x39/0x90 [zfs]
Jan 27 17:27:32 proxmox02 kernel: zfsdev_ioctl+0x6db/0x8f0 [zfs]
Jan 27 17:27:32 proxmox02 kernel: ? lru_cache_add_active_or_unevictable+0x39/0xb0
Jan 27 17:27:32 proxmox02 kernel: do_vfs_ioctl+0xa9/0x640
Jan 27 17:27:32 proxmox02 kernel: ? handle_mm_fault+0xc9/0x1f0
Jan 27 17:27:32 proxmox02 kernel: ksys_ioctl+0x67/0x90
Jan 27 17:27:32 proxmox02 kernel: __x64_sys_ioctl+0x1a/0x20
Jan 27 17:27:32 proxmox02 kernel: do_syscall_64+0x57/0x190
Jan 27 17:27:32 proxmox02 kernel: entry_SYSCALL_64_after_hwframe+0x44/0xa9
Jan 27 17:27:32 proxmox02 kernel: RIP: 0033:0x7f1a2d89f427
Jan 27 17:27:32 proxmox02 kernel: Code: Bad RIP value.
Jan 27 17:27:32 proxmox02 kernel: RSP: 002b:00007fff9dd2e5e8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
Jan 27 17:27:32 proxmox02 kernel: RAX: ffffffffffffffda RBX: 00007fff9dd2e610 RCX: 00007f1a2d89f427
Jan 27 17:27:32 proxmox02 kernel: RDX: 00007fff9dd2e610 RSI: 0000000000005a05 RDI: 0000000000000003
Jan 27 17:27:32 proxmox02 kernel: RBP: 00007fff9dd31bf0 R08: 000055ac0421c680 R09: 00007f1a2d96ade0
Jan 27 17:27:32 proxmox02 kernel: R10: 000055ac0421a010 R11: 0000000000000246 R12: 000055ac0421c530
Jan 27 17:27:32 proxmox02 kernel: R13: 000055ac0421a2e0 R14: 0000000000000000 R15: 00007fff9dd31c04Neither SMART values nor the seachest tools from Seagate show a hardware issue with the drives.
zpool status:
pool: hdd_zfs_guests
state: ONLINE
scan: scrub repaired 0B in 0 days 06:14:17 with 0 errors on Sun Jan 3 00:50:29 2021
config:
NAME STATE READ WRITE CKSUM
hdd_zfs_guests ONLINE 0 0 0
mirror-0 ONLINE 0 0 0
wwn-0x5000c500b3a2d8c4 ONLINE 0 0 0
wwn-0x5000c500b3a2edef ONLINE 0 0 0
mirror-1 ONLINE 0 0 0
wwn-0x5000c500b38ee3ed ONLINE 0 0 0
wwn-0x5000c500b3a2e636 ONLINE 0 0 0
errors: No known data errors
pool: hdd_zfs_ssd
state: ONLINE
scan: scrub repaired 0B in 0 days 00:14:13 with 0 errors on Sat Jan 2 18:50:52 2021
config:
NAME STATE READ WRITE CKSUM
hdd_zfs_ssd ONLINE 0 0 0
mirror-0 ONLINE 0 0 0
wwn-0x500a0751e4a94a86 ONLINE 0 0 0
wwn-0x500a0751e4a94af8 ONLINE 0 0 0
errors: No known data errorsZFS list:
NAME USED AVAIL REFER MOUNTPOINT
hdd_zfs_guests 4.49T 2.91T 176K /hdd_zfs_guests
hdd_zfs_guests/home 12.1G 2.91T 12.1G /hdd_zfs_guests/home
hdd_zfs_guests/shares 112K 2.91T 112K /hdd_zfs_guests/shares
hdd_zfs_guests/shares-client_backups 2.33T 2.91T 937G /hdd_zfs_guests/shares-client_backups
hdd_zfs_guests/shares-incoming 897G 2.91T 897G /hdd_zfs_guests/shares-incoming
hdd_zfs_guests/shares-install 104K 2.91T 104K /hdd_zfs_guests/shares-install
hdd_zfs_guests/shares-iso-images 9.76G 2.91T 9.76G /hdd_zfs_guests/shares-iso-images
hdd_zfs_guests/shares-lost-n-found 75.3G 2.91T 75.3G /hdd_zfs_guests/shares-lost-n-found
hdd_zfs_guests/shares-maintenance 96K 2.91T 96K /hdd_zfs_guests/shares-maintenance
hdd_zfs_guests/shares-media 129G 2.91T 129G /hdd_zfs_guests/shares-media
hdd_zfs_guests/shares-nextcloud 206G 2.91T 206G /hdd_zfs_guests/shares-nextcloud
hdd_zfs_guests/shares-photos 112K 2.91T 112K /hdd_zfs_guests/shares-photos
hdd_zfs_guests/shares-plex-library 11.6G 2.91T 9.65G /hdd_zfs_guests/shares-plex-library
hdd_zfs_guests/shares-server_backup 925M 2.91T 925M /hdd_zfs_guests/shares-server_backup
hdd_zfs_guests/timemachine 856G 2.91T 765G /hdd_zfs_guests/timemachine
hdd_zfs_ssd 349G 1.42T 144K /hdd_zfs_ssd
hdd_zfs_ssd/subvol-301-disk-0 677M 19.3G 677M /hdd_zfs_ssd/subvol-301-disk-0
hdd_zfs_ssd/subvol-302-disk-0 735M 7.28G 735M /hdd_zfs_ssd/subvol-302-disk-0
hdd_zfs_ssd/subvol-401-disk-0 643M 7.37G 643M /hdd_zfs_ssd/subvol-401-disk-0
hdd_zfs_ssd/subvol-404-disk-0 1.09G 28.9G 1.09G /hdd_zfs_ssd/subvol-404-disk-0
hdd_zfs_ssd/subvol-406-disk-0 1.36G 6.64G 1.36G /hdd_zfs_ssd/subvol-406-disk-0
hdd_zfs_ssd/subvol-407-disk-0 1.40G 149G 1.40G /hdd_zfs_ssd/subvol-407-disk-0
hdd_zfs_ssd/subvol-408-disk-0 1.13G 18.9G 1.13G /hdd_zfs_ssd/subvol-408-disk-0
hdd_zfs_ssd/subvol-409-disk-0 3.04G 6.96G 3.04G /hdd_zfs_ssd/subvol-409-disk-0
hdd_zfs_ssd/subvol-410-disk-0 1.33G 6.67G 1.33G /hdd_zfs_ssd/subvol-410-disk-0
hdd_zfs_ssd/subvol-501-disk-0 3.10G 12.9G 3.10G /hdd_zfs_ssd/subvol-501-disk-0
hdd_zfs_ssd/vm-100-disk-0 33.0G 1.44T 10.3G -
hdd_zfs_ssd/vm-1001-disk-0 33.0G 1.45T 1.37G -
hdd_zfs_ssd/vm-1001-disk-1 103G 1.51T 11.2G -
hdd_zfs_ssd/vm-1002-disk-0 33.0G 1.45T 1.86G -
hdd_zfs_ssd/vm-114-disk-0 132G 1.46T 89.1G -If this is not the right place to ask, not the same issue or any information is missing, please let me know.
Thanks!
Chris
Blackclaws
commented
3 years ago I have the same thing happen to me when the system is under high i/o load.
Happens on multiple openzfs versions (tested include 2.0.0, 2.0.1 and the most recent 2.0.2 and kernel versions 5.4 and 5.10 were both tested. Running on low CPU load and with 256GB of RAM.
Feb 01 22:47:48 homeserver kernel: INFO: task txg_sync:2951 blocked for more than 122 seconds.
Feb 01 22:47:48 homeserver kernel: Tainted: P OE 5.10.11-arch1-1 #1
Feb 01 22:47:48 homeserver kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Feb 01 22:47:48 homeserver kernel: task:txg_sync state:D stack: 0 pid: 2951 ppid: 2 flags:0x00004000
Feb 01 22:47:48 homeserver kernel: Call Trace:
Feb 01 22:47:48 homeserver kernel: __schedule+0x295/0x810
Feb 01 22:47:48 homeserver kernel: schedule+0x5b/0xc0
Feb 01 22:47:48 homeserver kernel: schedule_timeout+0x98/0x160
Feb 01 22:47:48 homeserver kernel: ? __next_timer_interrupt+0x100/0x100
Feb 01 22:47:48 homeserver kernel: io_schedule_timeout+0x4c/0x80
Feb 01 22:47:48 homeserver kernel: __cv_timedwait_common+0x129/0x160 [spl]
Feb 01 22:47:48 homeserver kernel: ? wait_woken+0x80/0x80
Feb 01 22:47:48 homeserver kernel: __cv_timedwait_io+0x15/0x20 [spl]
Feb 01 22:47:48 homeserver kernel: zio_wait+0x13b/0x2d0 [zfs]
Feb 01 22:47:48 homeserver kernel: dsl_pool_sync+0xd0/0x4c0 [zfs]
Feb 01 22:47:48 homeserver kernel: spa_sync+0x56d/0xfc0 [zfs]
Feb 01 22:47:48 homeserver kernel: ? spa_txg_history_init_io+0x112/0x120 [zfs]
Feb 01 22:47:48 homeserver kernel: txg_sync_thread+0x2dc/0x4a0 [zfs]
Feb 01 22:47:48 homeserver kernel: ? txg_register_callbacks+0xa0/0xa0 [zfs]
Feb 01 22:47:48 homeserver kernel: thread_generic_wrapper+0x6f/0x80 [spl]
Feb 01 22:47:48 homeserver kernel: ? __thread_exit+0x20/0x20 [spl]
Feb 01 22:47:48 homeserver kernel: kthread+0x133/0x150
Feb 01 22:47:48 homeserver kernel: ? __kthread_bind_mask+0x60/0x60
Feb 01 22:47:48 homeserver kernel: ret_from_fork+0x22/0x30I can reliably reproduce this issue by qemu-img converting a zvol to a qcow file within the same zpool. Any help in tracking down the source of this issue is much appreciated.
mnbf9rca
commented
3 years ago I found that i had a failing SSD which wasnt showing up as failing when examining SMART attributes, but which was blocking on read/write. Replacing the SSD fixed the problem.
seanmikhaels
commented
3 years ago Can confirm i am still having this issue with ZFS 2.0.3 on Kernel 5.10
lukaszaoralek
commented
3 years ago | Type | Version/Name |
|---|---|
| Distribution Name | Ubuntu |
| Distribution Version | 20.04 (Ubuntu 20.04.2 LTS) |
| Linux Kernel | 5.4.0-1032-raspi |
| Architecture | CPU: Broadcom BCM2711, Quad core Cortex-A72 (ARM v8) 64-bit SoC @ 1.5GHz (with 8GB LPDDR4-3200 SDRAM) |
| ZFS Version | 2.0.4-0york2~20.04 |
| SPL Version | 2.0.4-0york2~20.04 |
| Drives | 3x My Book 25EE (ID_MODEL=My_Book_25EE) |
I can confirm I'm also still having this issue with ZFS 2.0.4 when I locally send and receive snapshots between two pools:
[225234.641270] INFO: task txg_sync:350658 blocked for more than 120 seconds.
[225234.648526] Tainted: P C OE 5.4.0-1032-raspi #35-Ubuntu
[225234.655688] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[225234.663880] txg_sync D 0 350658 2 0x00000028
[225234.663892] Call trace:
[225234.663908] __switch_to+0x144/0x1a0
[225234.663916] __schedule+0x328/0x830
[225234.663920] schedule+0x4c/0xe8
[225234.663946] cv_wait_common+0x174/0x198 [spl]
[225234.663961] __cv_wait+0x34/0x40 [spl]
[225234.664144] arc_read+0x188/0x1020 [zfs]
[225234.664250] dsl_scan_visitbp+0x1dc/0x9d0 [zfs]
[225234.664353] dsl_scan_visitbp+0x49c/0x9d0 [zfs]
[225234.664457] dsl_scan_visitbp+0x250/0x9d0 [zfs]
[225234.664565] dsl_scan_visitbp+0x250/0x9d0 [zfs]
[225234.664675] dsl_scan_visitbp+0x250/0x9d0 [zfs]
[225234.664792] dsl_scan_visitbp+0x250/0x9d0 [zfs]
[225234.664914] dsl_scan_visitbp+0x250/0x9d0 [zfs]
[225234.665028] dsl_scan_visitbp+0x6b4/0x9d0 [zfs]
[225234.665190] dsl_scan_visit_rootbp+0xcc/0x118 [zfs]
[225234.665302] dsl_scan_visitds+0x130/0x460 [zfs]
[225234.665418] dsl_scan_sync+0x75c/0x1160 [zfs]
[225234.665526] spa_sync+0x588/0xe38 [zfs]
[225234.665632] txg_sync_thread+0x2cc/0x438 [zfs]
[225234.665651] thread_generic_wrapper+0x78/0xa8 [spl]
[225234.665664] kthread+0x150/0x170
[225234.665672] ret_from_fork+0x10/0x18
0x3333
commented
3 years ago Same here.
| Type | Version/Name |
|---|---|
| Distribution Name | Debian GNU/Linux 10 (buster) |
| Distribution Version | 10 |
| Linux Kernel | 5.10.13-1~bpo10+1 |
| Architecture | 64-bit Intel |
| ZFS Version | zfs-2.0.3-1~bpo10+1 |
[267039.141392] INFO: task zpool:3827986 blocked for more than 241 seconds.
[267039.142368] Tainted: P IOE 5.10.0-0.bpo.3-amd64 #1 Debian 5.10.13-1~bpo10+1
[267039.143319] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[267039.144257] task:zpool state:D stack: 0 pid:3827986 ppid: 1779 flags:0x00000000
[267039.145213] Call Trace:
[267039.146197] __schedule+0x2be/0x770
[267039.146994] schedule+0x3c/0xa0
[267039.147918] schedule_preempt_disabled+0xa/0x10
[267039.148842] __mutex_lock.isra.9+0x2bf/0x4b0
[267039.149936] spa_open_common+0x5f/0x4c0 [zfs]
[267039.150876] spa_get_stats+0x4d/0x520 [zfs]
[267039.151758] ? __kmalloc_node+0x15d/0x330
[267039.152638] ? spl_kmem_alloc+0xb6/0x100 [spl]
[267039.153635] zfs_ioc_pool_stats+0x34/0x80 [zfs]
[267039.154532] zfsdev_ioctl_common+0x5b6/0x830 [zfs]
[267039.155395] ? __kmalloc_node+0x274/0x330
[267039.156346] zfsdev_ioctl+0x4f/0xe0 [zfs]
[267039.157213] __x64_sys_ioctl+0x84/0xc0
[267039.158130] do_syscall_64+0x33/0x80
[267039.158953] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[267039.159811] RIP: 0033:0x7f20838f2427
[267039.160653] RSP: 002b:00007ffcf9ac40b8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[267039.161552] RAX: ffffffffffffffda RBX: 00007ffcf9ac40e0 RCX: 00007f20838f2427
[267039.162351] RDX: 00007ffcf9ac40e0 RSI: 0000000000005a05 RDI: 0000000000000003
[267039.163187] RBP: 00007ffcf9ac76d0 R08: 0000560a54d7d930 R09: 00007f20839bdd90
[267039.164012] R10: 0000560a54d76010 R11: 0000000000000246 R12: 0000560a54d7b1c0
[267039.164845] R13: 0000560a54d77530 R14: 0000000000000000 R15: 00007ffcf9ac76e4| Type | Version/Name |
|---|---|
| Distribution Name | Proxmox |
| Distribution Version | 6.4-5 |
| Linux Kernel | 5.4.106-1-pve |
| ZFS Version | zfs-2.0.4-pve1 |
| SPL Version | zfs-2.0.4-pve1 |
After upgrade to zfs-2.0.4-pve1 the problem mentioned here https://github.com/openzfs/zfs/issues/9130#issuecomment-770207396 disappeared.
dm17
commented
3 years ago I got this too. Latest openzfs 2.0.4, zfs-kmod 2.0.4, kernel 5.11.22 - reproduced twice trying to send snapshots to a flash drive. Snapshots of a few K sent no problem. But trying to send a snapshot of a few GB to the zfs pool on the USB flash drive gives this in dmesg consistently (after about 10m):
INFO: task txg_sync: 10000 blocked for more than 122 seconds.
Tainted: P O 5.11.22
task:txg_sync state:D stack: 0 ....
Call Trace:
...Is there a proven way to backup a ZFS volume to a flash drive?
foxx
commented
3 years ago I was able to reproduce this issue by removing a ZIL device. Immediately after issuing the zpool remove command, it locked up.
The ZFS volumes were being rsync'd to at the time this happened, around 10MB/sec usage, and they use compression=zstd-10 and encryption=on.
[114800.377667] zpool D 0 31288 45027 0x00000000
[114800.383604] Call Trace:
[114800.386502] __schedule+0x29f/0x840
[114800.390452] ? __slab_free+0x2d6/0x380
[114800.394653] schedule+0x28/0x80
[114800.398244] schedule_preempt_disabled+0xa/0x10
[114800.403233] __mutex_lock.isra.8+0x2b5/0x4a0
[114800.407972] l2arc_evict+0x4c1/0x560 [zfs]
[114800.412534] l2arc_remove_vdev+0x11a/0x240 [zfs]
[114800.417618] spa_load_l2cache+0x3a5/0x4d0 [zfs]
[114800.422614] ? spa_vdev_remove_aux+0x9b/0x1b0 [zfs]
[114800.427955] spa_vdev_remove+0x621/0x830 [zfs]
[114800.432838] ? __kmalloc_node+0x1ea/0x2c0
[114800.437319] zfs_ioc_vdev_remove+0x4f/0x90 [zfs]
[114800.442377] ? strlcpy+0x2d/0x40
[114800.446070] zfsdev_ioctl_common+0x5b5/0x830 [zfs]
[114800.451301] ? kmalloc_large_node+0x37/0x60
[114800.455920] ? __kmalloc_node+0x213/0x2c0
[114800.460396] zfsdev_ioctl+0x4f/0xe0 [zfs]
[114800.464848] do_vfs_ioctl+0xa4/0x630
[114800.468857] ? do_munmap+0x33c/0x430
[114800.472869] ksys_ioctl+0x60/0x90
[114800.476616] __x64_sys_ioctl+0x16/0x20
[114800.480794] do_syscall_64+0x53/0x110
[114800.484884] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[114800.490361] RIP: 0033:0x7f028e220427
[114800.494363] Code: Bad RIP value.
[114800.498016] RSP: 002b:00007ffe6ce638f8 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[114800.506013] RAX: ffffffffffffffda RBX: 000055ecdfac5720 RCX: 00007f028e220427
[114800.513583] RDX: 00007ffe6ce63910 RSI: 0000000000005a0c RDI: 0000000000000003
[114800.521154] RBP: 00007ffe6ce67300 R08: 0000000000000100 R09: 0000000000000000
[114800.528725] R10: 0000000000000000 R11: 0000000000000246 R12: 00007ffe6ce63910
[114800.536311] R13: 000055ecdfac1530 R14: 00007ffe6ce66ec0 R15: 000055ecdfaed058
rejsmont
commented
3 years ago Hello,
I am having a similar issue with 2 homemade NAS machines: one using multiple USB drives, the other using a USB-RAID controller (in a direct access mode).
| Type | Version/Name |
|---|---|
| Distribution Name | Ubuntu |
| Distribution Version | 20.04 |
| Linux Kernel | 5.4.0-1038-raspi |
| Architecture | aarch64 |
| ZFS Version | 0.8.3-1ubuntu12.9 |
| SPL Version | 0.8.3-1ubuntu12.9 |
During TimeMachine backups to samba hosted on these machines, iowait shoots up and the load creeps up until the system freezes. Usually, the following is found in the logs, though sometimes the logs around freeze time are empty.
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.388268] INFO: task z_rd_int:11058 blocked for more than 120 seconds.
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.395118] Tainted: P C OE 5.4.0-1038-raspi #41-Ubuntu
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.402223] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410297] z_rd_int D 0 11058 2 0x00000028
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410315] Call trace:
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410337] __switch_to+0x144/0x1a0
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410352] __schedule+0x334/0x838
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410364] schedule+0x4c/0xe8
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410375] io_schedule+0x24/0x90
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410386] rq_qos_wait+0x108/0x180
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410397] wbt_wait+0xbc/0xf8
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410406] __rq_qos_throttle+0x38/0x50
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410416] blk_mq_make_request+0x130/0x708
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410427] generic_make_request+0xbc/0x350
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410436] submit_bio+0x4c/0x280
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410712] vdev_submit_bio_impl+0xc/0x18 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.410971] vdev_submit_bio+0x1c/0x30 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.411226] __vdev_disk_physio.constprop.0+0x280/0x368 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.411481] vdev_disk_io_start+0x88/0x330 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.411739] zio_vdev_io_start+0xb8/0x270 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.411991] zio_nowait+0xbc/0x168 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412212] vdev_queue_io_done+0xf0/0x128 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412578] zio_vdev_io_done+0xc8/0x1d0 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412803] zio_execute+0xac/0x118 [zfs]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412844] taskq_thread+0x20c/0x3b0 [spl]
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412868] kthread+0x150/0x170
Jun 28 17:36:01 rpi-srv-2 kernel: [71534.412879] ret_from_fork+0x10/0x18
System information
The pool is 40TB raw (8 x 5TB) in RAIDZ2. De-duplication is off. Drives are new and verified working with badblocks (4 passes) and smart tests. Compression is set to lz4. This has been verified with native encryption on and off on the same hardware. The drives are in 2 x external thunderbolt enclosures, which would be a red flag had they not run for > 1 year on another system with different (same model) drives without fault.
Describe the problem you're observing
The IO hangs during long rsync jobs (e.g. 1TB+) over the network, or shorter ones locally (one pool to another) (1GB+).
This causes rsync to hang and any other programs that use the pool will also go unresponsive if started (as would be expected if the IO is hung. E.g. the console is responsive over SSH, but
lson the root of the pool hangs.When this happened on ZFS 0.7.x it kernel panicked and crashed the computer, but since 0.8.1 it only causes pool IO related tasks to hang but the server remains responsive otherwise.
This seems related to #2934, #7946, #4361, #2611 and #4011.
The system only has 8GB RAM, which may or may not be an issue, but I wouldn't expect a kernel panic regardless. Other users on the related issues report increasing the RAM, or higher RAM initially with the same error.
CPU usage is generally high (>80%) and write speeds are low throughout the transfer when the pool is encrypted, but this is expected as I believe the missing kernel symbols patch is not in this release (scheduled for 0.8.2?).
Describe how to reproduce the problem
Any long rsync job seems to crash it after a few hours, a fast, large local rsync job (1GB+ pool to pool) will crash it almost immediately.
Include any warning/errors/backtraces from the system logs
Initially:
Then periodically: