I recently updated my proxmox host to the newest version 7.3-3. Before updating (7.2), the system was operating without any problems. After the update a portable external hard drive (usb3 connection, permanently connected with proxmox) is not working properly. I have created a ZFS disk on the portable hard drive and mounted the ZFS drive on my linux guest (qemu). It is used as a backup medium, so performance is not so important.
As soon as the backup process (amanda) starts and is using the disk I can find the following error in syslog:
Later errors of the following kind can be found repeatedly in the syslog file:
IO delay on proxmox host is very high during the backup, approximately between 60% to 80%.
Can anyone give me hint how I can solve this problem? Could I somehow switch back to the previous promox version?
As soon as the backup process (amanda) starts and is using the disk I can find the following error in syslog:
Bash:
Dec 7 22:39:05 proxmox kernel: [32263.227584] INFO: task txg_sync:1740 blocked for more than 120 seconds.
Dec 7 22:39:05 proxmox kernel: [32263.227589] Tainted: P O 5.19.17-1-pve #1
Dec 7 22:39:05 proxmox kernel: [32263.227591] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 7 22:39:05 proxmox kernel: [32263.227592] task:txg_sync state:D stack: 0 pid: 1740 ppid: 2 flags:0x00004000
Dec 7 22:39:05 proxmox kernel: [32263.227595] Call Trace:
Dec 7 22:39:05 proxmox kernel: [32263.227596] <TASK>
Dec 7 22:39:05 proxmox kernel: [32263.227598] __schedule+0x32b/0x13d0
Dec 7 22:39:05 proxmox kernel: [32263.227602] ? __mod_timer+0x26f/0x440
Dec 7 22:39:05 proxmox kernel: [32263.227606] schedule+0x68/0x100
Dec 7 22:39:05 proxmox kernel: [32263.227607] schedule_timeout+0x87/0x160
Dec 7 22:39:05 proxmox kernel: [32263.227609] ? timer_migration_handler+0xa0/0xa0
Dec 7 22:39:05 proxmox kernel: [32263.227610] io_schedule_timeout+0x51/0x80
Dec 7 22:39:05 proxmox kernel: [32263.227612] __cv_timedwait_common+0x136/0x170 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227617] ? destroy_sched_domains_rcu+0x30/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227620] __cv_timedwait_io+0x19/0x20 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227623] zio_wait+0x137/0x300 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227679] ? dsl_dataset_sync+0x8a/0x500 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227717] dsl_pool_sync+0xcc/0x4f0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227763] ? spa_suspend_async_destroy+0x60/0x60 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227806] ? add_timer+0x20/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227809] spa_sync+0x558/0x1020 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227848] ? spa_txg_history_init_io+0x10a/0x120 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227887] txg_sync_thread+0x274/0x3f0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227925] ? txg_register_callbacks+0xb0/0xb0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227959] ? __thread_exit+0x20/0x20 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227963] thread_generic_wrapper+0x64/0x80 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227967] kthread+0xf0/0x120
Dec 7 22:39:05 proxmox kernel: [32263.227969] ? kthread_complete_and_exit+0x20/0x20
Dec 7 22:39:05 proxmox kernel: [32263.227971] ret_from_fork+0x22/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227974] </TASK>
Dec 7 22:39:05 proxmox kernel: [32263.227584] INFO: task txg_sync:1740 blocked for more than 120 seconds.
Dec 7 22:39:05 proxmox kernel: [32263.227589] Tainted: P O 5.19.17-1-pve #1
Dec 7 22:39:05 proxmox kernel: [32263.227591] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 7 22:39:05 proxmox kernel: [32263.227592] task:txg_sync state:D stack: 0 pid: 1740 ppid: 2 flags:0x00004000
Dec 7 22:39:05 proxmox kernel: [32263.227595] Call Trace:
Dec 7 22:39:05 proxmox kernel: [32263.227596] <TASK>
Dec 7 22:39:05 proxmox kernel: [32263.227598] __schedule+0x32b/0x13d0
Dec 7 22:39:05 proxmox kernel: [32263.227602] ? __mod_timer+0x26f/0x440
Dec 7 22:39:05 proxmox kernel: [32263.227606] schedule+0x68/0x100
Dec 7 22:39:05 proxmox kernel: [32263.227607] schedule_timeout+0x87/0x160
Dec 7 22:39:05 proxmox kernel: [32263.227609] ? timer_migration_handler+0xa0/0xa0
Dec 7 22:39:05 proxmox kernel: [32263.227610] io_schedule_timeout+0x51/0x80
Dec 7 22:39:05 proxmox kernel: [32263.227612] __cv_timedwait_common+0x136/0x170 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227617] ? destroy_sched_domains_rcu+0x30/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227620] __cv_timedwait_io+0x19/0x20 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227623] zio_wait+0x137/0x300 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227679] ? dsl_dataset_sync+0x8a/0x500 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227717] dsl_pool_sync+0xcc/0x4f0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227763] ? spa_suspend_async_destroy+0x60/0x60 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227806] ? add_timer+0x20/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227809] spa_sync+0x558/0x1020 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227848] ? spa_txg_history_init_io+0x10a/0x120 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227887] txg_sync_thread+0x274/0x3f0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227925] ? txg_register_callbacks+0xb0/0xb0 [zfs]
Dec 7 22:39:05 proxmox kernel: [32263.227959] ? __thread_exit+0x20/0x20 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227963] thread_generic_wrapper+0x64/0x80 [spl]
Dec 7 22:39:05 proxmox kernel: [32263.227967] kthread+0xf0/0x120
Dec 7 22:39:05 proxmox kernel: [32263.227969] ? kthread_complete_and_exit+0x20/0x20
Dec 7 22:39:05 proxmox kernel: [32263.227971] ret_from_fork+0x22/0x30
Dec 7 22:39:05 proxmox kernel: [32263.227974] </TASK>Later errors of the following kind can be found repeatedly in the syslog file:
Bash:
Dec 08 04:56:30 proxmox zed[2827]: Missed 17 events
Dec 08 04:56:30 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:56:30 proxmox zed[2827]: Missed 67 events
Dec 08 04:56:30 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:56:30 proxmox zed[2827]: Missed 73 events
Dec 08 04:56:30 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:56:30 proxmox zed[2827]: Missed 15 events
Dec 08 04:56:30 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:56:30 proxmox zed[3423767]: eid=3643 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308894720 priority=3 err=0 flags=0x184880 delay=54906832ms bookmark=261:1:0:323404549
Dec 08 04:56:30 proxmox zed[3423766]: eid=3644 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308886528 priority=3 err=0 flags=0x184880 delay=54906832ms bookmark=261:1:0:323404548
Dec 08 04:56:30 proxmox zed[3423770]: eid=3645 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308878336 priority=3 err=0 flags=0x184880 delay=54906832ms bookmark=261:1:0:323404547
Dec 08 04:56:30 proxmox zed[3423774]: eid=3646 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308870144 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404546
Dec 08 04:56:30 proxmox zed[3423775]: eid=3647 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=16384 offset=274308861952 priority=3 err=0 flags=0x40080c80 delay=54906831ms
Dec 08 04:56:30 proxmox zed[3423779]: eid=3648 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308861952 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404545
Dec 08 04:56:30 proxmox zed[3423781]: eid=3649 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=16384 offset=274308861952 priority=3 err=0 flags=0x40080c80 delay=54906831ms
Dec 08 04:56:30 proxmox zed[3423786]: eid=3650 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308853760 priority=3 err=0 flags=0x184880 delay=54906831ms bookmark=261:1:0:323404544
Dec 08 04:56:30 proxmox zed[3423787]: eid=3651 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308845568 priority=3 err=0 flags=0x184880 delay=54906830ms bookmark=261:1:0:323404543
Dec 08 04:56:30 proxmox zed[3423793]: eid=3653 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=155648 offset=274308689920 priority=3 err=0 flags=0x40080c80 delay=54906830ms
Dec 08 04:56:30 proxmox zed[3423792]: eid=3652 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308837376 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404542
Dec 08 04:56:30 proxmox zed[3423797]: eid=3654 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308829184 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404541
Dec 08 04:56:30 proxmox zed[3423799]: eid=3655 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=155648 offset=274308689920 priority=3 err=0 flags=0x40080c80 delay=54906830ms
Dec 08 04:56:30 proxmox zed[3423803]: eid=3656 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308820992 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404540
Dec 08 04:56:30 proxmox zed[3423805]: eid=3657 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=155648 offset=274308689920 priority=3 err=0 flags=0x40080c80 delay=54906830ms
Dec 08 04:56:30 proxmox zed[3423808]: eid=3658 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308812800 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404539
Dec 08 04:56:30 proxmox zed[3423813]: eid=3659 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=155648 offset=274308689920 priority=3 err=0 flags=0x40080c80 delay=54906830ms
Dec 08 04:56:30 proxmox zed[3423814]: eid=3660 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308804608 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404538
Dec 08 04:56:30 proxmox zed[3423816]: eid=3661 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=155648 offset=274308689920 priority=3 err=0 flags=0x40080c80 delay=54906830ms
Dec 08 04:56:30 proxmox zed[3423818]: eid=3662 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274308796416 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323404537
Dec 08 04:57:31 proxmox zed[2827]: Missed 5 events
Dec 08 04:57:31 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:57:31 proxmox zed[2827]: Missed 65 events
Dec 08 04:57:31 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:57:31 proxmox zed[2827]: Missed 63 events
Dec 08 04:57:31 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:57:31 proxmox zed[2827]: Missed 36 events
Dec 08 04:57:31 proxmox zed[2827]: Bumping queue length to 2147483647
Dec 08 04:57:31 proxmox zed[3428274]: eid=3664 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544861184 priority=3 err=0 flags=0x184880 bookmark=261:1:0:323433372
Dec 08 04:57:31 proxmox zed[3428272]: eid=3663 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544869376 priority=3 err=0 flags=0x184880 bookmark=261:1:0:323433373
Dec 08 04:57:31 proxmox zed[3428277]: eid=3665 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544852992 priority=3 err=0 flags=0x184880 delay=54967933ms bookmark=261:1:0:323433371
Dec 08 04:57:31 proxmox zed[3428281]: eid=3666 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544844800 priority=3 err=0 flags=0x184880 delay=54967933ms bookmark=261:1:0:323433370
Dec 08 04:57:31 proxmox zed[3428282]: eid=3667 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544836608 priority=3 err=0 flags=0x184880 delay=54967933ms bookmark=261:1:0:323433369
Dec 08 04:57:31 proxmox zed[3428286]: eid=3668 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544828416 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433368
Dec 08 04:57:31 proxmox zed[3428288]: eid=3669 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428292]: eid=3670 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544820224 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433367
Dec 08 04:57:31 proxmox zed[3428295]: eid=3671 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428298]: eid=3672 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544812032 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433366
Dec 08 04:57:31 proxmox zed[3428301]: eid=3673 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428304]: eid=3674 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544803840 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433365
Dec 08 04:57:31 proxmox zed[3428308]: eid=3675 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428309]: eid=3676 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544795648 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433364
Dec 08 04:57:31 proxmox zed[3428312]: eid=3677 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428315]: eid=3678 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544787456 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433363
Dec 08 04:57:31 proxmox zed[3428320]: eid=3679 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428321]: eid=3680 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544779264 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433362
Dec 08 04:57:31 proxmox zed[3428323]: eid=3681 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=417792 offset=274544418816 priority=3 err=0 flags=0x40080c80 delay=54967933ms
Dec 08 04:57:31 proxmox zed[3428325]: eid=3682 class=deadman pool='amanda' vdev=usb-Intenso_SCSI_2021A11316722-0:0-part1 size=8192 offset=274544771072 priority=3 err=0 flags=0x384880 bookmark=261:1:0:323433361IO delay on proxmox host is very high during the backup, approximately between 60% to 80%.
Can anyone give me hint how I can solve this problem? Could I somehow switch back to the previous promox version?