Hello
restoring a VM with a different ID to have a dev-env of the vm host machine. But it just hung at the end stage and my original running machine starting acting funny and some services starting crashing. The proxmox host also had problems in the messages.
dmesg from proxmox host:
[Fri Jun 18 14:10:47 2021] INFO: task kvm:5416 blocked for more than 120 seconds.
[Fri Jun 18 14:10:47 2021] Tainted: P O 5.4.78-2-pve #1
[Fri Jun 18 14:10:47 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Jun 18 14:10:47 2021] kvm D 0 5416 1 0x00000000
[Fri Jun 18 14:10:47 2021] Call Trace:
[Fri Jun 18 14:10:47 2021] __schedule+0x2e6/0x6f0
[Fri Jun 18 14:10:47 2021] ? mutex_lock+0x12/0x30
[Fri Jun 18 14:10:47 2021] schedule+0x33/0xa0
[Fri Jun 18 14:10:47 2021] cv_wait_common+0x104/0x130 [spl]
[Fri Jun 18 14:10:47 2021] ? wait_woken+0x80/0x80
[Fri Jun 18 14:10:47 2021] __cv_wait+0x15/0x20 [spl]
[Fri Jun 18 14:10:47 2021] zfs_rangelock_enter+0x127/0x580 [zfs]
[Fri Jun 18 14:10:47 2021] ? spl_kmem_zalloc+0xe9/0x140 [spl]
[Fri Jun 18 14:10:47 2021] zvol_get_data+0x81/0x170 [zfs]
[Fri Jun 18 14:10:47 2021] zil_commit_impl+0x9ad/0xd90 [zfs]
[Fri Jun 18 14:10:47 2021] zil_commit+0x3d/0x60 [zfs]
[Fri Jun 18 14:10:47 2021] zvol_request+0x233/0x3c0 [zfs]
[Fri Jun 18 14:10:47 2021] generic_make_request+0xcf/0x310
[Fri Jun 18 14:10:47 2021] submit_bio+0x46/0x1c0
[Fri Jun 18 14:10:47 2021] ? radix_tree_lookup+0xd/0x10
[Fri Jun 18 14:10:47 2021] ? blkg_lookup_slowpath+0x27/0x50
[Fri Jun 18 14:10:47 2021] submit_bio_wait+0x59/0x90
[Fri Jun 18 14:10:47 2021] blkdev_issue_flush+0x8e/0xc0
[Fri Jun 18 14:10:47 2021] blkdev_fsync+0x35/0x50
[Fri Jun 18 14:10:47 2021] vfs_fsync_range+0x48/0x80
[Fri Jun 18 14:10:47 2021] ? __fget_light+0x59/0x70
[Fri Jun 18 14:10:47 2021] do_fsync+0x3d/0x70
[Fri Jun 18 14:10:47 2021] __x64_sys_fdatasync+0x17/0x20
[Fri Jun 18 14:10:47 2021] do_syscall_64+0x57/0x190
[Fri Jun 18 14:10:47 2021] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Fri Jun 18 14:10:47 2021] RIP: 0033:0x7f8c80ba62e7
[Fri Jun 18 14:10:47 2021] Code: Bad RIP value.
[Fri Jun 18 14:10:47 2021] RSP: 002b:00007f7729a56cc0 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[Fri Jun 18 14:10:47 2021] RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f8c80ba62e7
[Fri Jun 18 14:10:47 2021] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000000000000000f
[Fri Jun 18 14:10:47 2021] RBP: 000055ae008627f0 R08: 0000000000000000 R09: 00007f7729a56c40
[Fri Jun 18 14:10:47 2021] R10: 0000000060cc8c7c R11: 0000000000000293 R12: 000055adff3957da
[Fri Jun 18 14:10:47 2021] R13: 000055ae00862858 R14: 000055ae023080c0 R15: 000055ae013cbfb0
[Fri Jun 18 14:10:47 2021] INFO: task kvm:5371 blocked for more than 120 seconds.
[Fri Jun 18 14:10:47 2021] Tainted: P O 5.4.78-2-pve #1
[Fri Jun 18 14:10:47 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
this was repeating.........
restore log:
restore vma archive: zstd -q -d -c /USB/backups/dump/vzdump-qemu-200-2021_06_12-00_03_51.vma.zst | vma extract -v -r /var/tmp/vzdumptmp30693.fifo - /var/tmp/vzdumptmp30693
CFG: size: 827 name: qemu-server.conf
DEV: dev_id=1 size: 34359738368 devname: drive-scsi0
DEV: dev_id=2 size: 107374182400 devname: drive-scsi1
DEV: dev_id=3 size: 107374182400 devname: drive-scsi2
DEV: dev_id=4 size: 107374182400 devname: drive-scsi3
CTIME: Sat Jun 12 00:03:51 2021
new volume ID is 'data:vm-201-disk-0'
new volume ID is 'data:vm-201-disk-1'
new volume ID is 'data:vm-201-disk-2'
new volume ID is 'data:vm-201-disk-3'
map 'drive-scsi0' to '/dev/zvol/data/vm-201-disk-0' (write zeros = 0)
map 'drive-scsi1' to '/dev/zvol/data/vm-201-disk-1' (write zeros = 0)
map 'drive-scsi2' to '/dev/zvol/data/vm-201-disk-2' (write zeros = 0)
map 'drive-scsi3' to '/dev/zvol/data/vm-201-disk-3' (write zeros = 0)
progress 1% (read 3564830720 bytes, duration 6 sec)
progress 2% (read 7129661440 bytes, duration 11 sec)
progress 3% (read 10694492160 bytes, duration 18 sec)
progress 4% (read 14259322880 bytes, duration 26 sec)
progress 5% (read 17824153600 bytes, duration 34 sec)
progress 6% (read 21388984320 bytes, duration 43 sec)
progress 7% (read 24953815040 bytes, duration 51 sec)
progress 8% (read 28518645760 bytes, duration 58 sec)
progress 9% (read 32083410944 bytes, duration 63 sec)
progress 10% (read 35648241664 bytes, duration 70 sec)
progress 11% (read 39213072384 bytes, duration 78 sec)
progress 12% (read 42777903104 bytes, duration 85 sec)
progress 13% (read 46342733824 bytes, duration 93 sec)
progress 14% (read 49907564544 bytes, duration 100 sec)
progress 15% (read 53472395264 bytes, duration 107 sec)
progress 16% (read 57037225984 bytes, duration 115 sec)
progress 17% (read 60601991168 bytes, duration 122 sec)
progress 18% (read 64166821888 bytes, duration 128 sec)
progress 19% (read 67731652608 bytes, duration 131 sec)
progress 20% (read 71296483328 bytes, duration 132 sec)
progress 21% (read 74861314048 bytes, duration 134 sec)
progress 22% (read 78426144768 bytes, duration 134 sec)
progress 23% (read 81990975488 bytes, duration 137 sec)
progress 24% (read 85555806208 bytes, duration 138 sec)
progress 25% (read 89120571392 bytes, duration 140 sec)
progress 26% (read 92685402112 bytes, duration 144 sec)
progress 27% (read 96250232832 bytes, duration 144 sec)
progress 28% (read 99815063552 bytes, duration 151 sec)
progress 29% (read 103379894272 bytes, duration 155 sec)
progress 30% (read 106944724992 bytes, duration 160 sec)
progress 31% (read 110509555712 bytes, duration 165 sec)
progress 32% (read 114074386432 bytes, duration 171 sec)
progress 33% (read 117639217152 bytes, duration 179 sec)
progress 34% (read 121203982336 bytes, duration 186 sec)
progress 35% (read 124768813056 bytes, duration 194 sec)
progress 36% (read 128333643776 bytes, duration 202 sec)
progress 37% (read 131898474496 bytes, duration 209 sec)
progress 38% (read 135463305216 bytes, duration 217 sec)
progress 39% (read 139028135936 bytes, duration 225 sec)
progress 40% (read 142592966656 bytes, duration 233 sec)
progress 41% (read 146157797376 bytes, duration 240 sec)
progress 42% (read 149722562560 bytes, duration 246 sec)
progress 43% (read 153287393280 bytes, duration 254 sec)
progress 44% (read 156852224000 bytes, duration 261 sec)
progress 45% (read 160417054720 bytes, duration 269 sec)
progress 46% (read 163981885440 bytes, duration 276 sec)
progress 47% (read 167546716160 bytes, duration 284 sec)
progress 48% (read 171111546880 bytes, duration 290 sec)
progress 49% (read 174676377600 bytes, duration 298 sec)
progress 50% (read 178241142784 bytes, duration 306 sec)
progress 51% (read 181805973504 bytes, duration 314 sec)
progress 52% (read 185370804224 bytes, duration 322 sec)
progress 53% (read 188935634944 bytes, duration 330 sec)
progress 54% (read 192500465664 bytes, duration 338 sec)
progress 55% (read 196065296384 bytes, duration 347 sec)
progress 56% (read 199630127104 bytes, duration 355 sec)
progress 57% (read 203194957824 bytes, duration 362 sec)
progress 58% (read 206759788544 bytes, duration 371 sec)
progress 59% (read 210324553728 bytes, duration 380 sec)
progress 60% (read 213889384448 bytes, duration 387 sec)
progress 61% (read 217454215168 bytes, duration 397 sec)
progress 62% (read 221019045888 bytes, duration 406 sec)
progress 63% (read 224583876608 bytes, duration 417 sec)
progress 64% (read 228148707328 bytes, duration 428 sec)
progress 65% (read 231713538048 bytes, duration 438 sec)
progress 66% (read 235278368768 bytes, duration 447 sec)
progress 67% (read 238843133952 bytes, duration 459 sec)
progress 68% (read 242407964672 bytes, duration 469 sec)
progress 69% (read 245972795392 bytes, duration 480 sec)
progress 70% (read 249537626112 bytes, duration 491 sec)
progress 71% (read 253102456832 bytes, duration 502 sec)
progress 72% (read 256667287552 bytes, duration 513 sec)
progress 73% (read 260232118272 bytes, duration 523 sec)
progress 74% (read 263796948992 bytes, duration 533 sec)
progress 75% (read 267361714176 bytes, duration 545 sec)
progress 76% (read 270926544896 bytes, duration 556 sec)
progress 77% (read 274491375616 bytes, duration 565 sec)
progress 78% (read 278056206336 bytes, duration 575 sec)
progress 79% (read 281621037056 bytes, duration 585 sec)
progress 80% (read 285185867776 bytes, duration 594 sec)
progress 81% (read 288750698496 bytes, duration 605 sec)
progress 82% (read 292315529216 bytes, duration 615 sec)
progress 83% (read 295880359936 bytes, duration 625 sec)
progress 84% (read 299445125120 bytes, duration 633 sec)
progress 85% (read 303009955840 bytes, duration 642 sec)
progress 86% (read 306574786560 bytes, duration 654 sec)
progress 87% (read 310139617280 bytes, duration 664 sec)
progress 88% (read 313704448000 bytes, duration 673 sec)
progress 89% (read 317269278720 bytes, duration 683 sec)
progress 90% (read 320834109440 bytes, duration 694 sec)
progress 91% (read 324398940160 bytes, duration 702 sec)
progress 92% (read 327963705344 bytes, duration 712 sec)
progress 93% (read 331528536064 bytes, duration 721 sec)
progress 94% (read 335093366784 bytes, duration 730 sec)
progress 95% (read 338658197504 bytes, duration 741 sec)
progress 96% (read 342223028224 bytes, duration 750 sec)
progress 97% (read 345787858944 bytes, duration 759 sec)
progress 98% (read 349352689664 bytes, duration 768 sec)
progress 99% (read 352917520384 bytes, duration 778 sec)
progress 100% (read 356482285568 bytes, duration 787 sec)
I stopped it here, as it just sat there and things starting going wrong.
Original VM:
restoring a VM with a different ID to have a dev-env of the vm host machine. But it just hung at the end stage and my original running machine starting acting funny and some services starting crashing. The proxmox host also had problems in the messages.
dmesg from proxmox host:
[Fri Jun 18 14:10:47 2021] INFO: task kvm:5416 blocked for more than 120 seconds.
[Fri Jun 18 14:10:47 2021] Tainted: P O 5.4.78-2-pve #1
[Fri Jun 18 14:10:47 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[Fri Jun 18 14:10:47 2021] kvm D 0 5416 1 0x00000000
[Fri Jun 18 14:10:47 2021] Call Trace:
[Fri Jun 18 14:10:47 2021] __schedule+0x2e6/0x6f0
[Fri Jun 18 14:10:47 2021] ? mutex_lock+0x12/0x30
[Fri Jun 18 14:10:47 2021] schedule+0x33/0xa0
[Fri Jun 18 14:10:47 2021] cv_wait_common+0x104/0x130 [spl]
[Fri Jun 18 14:10:47 2021] ? wait_woken+0x80/0x80
[Fri Jun 18 14:10:47 2021] __cv_wait+0x15/0x20 [spl]
[Fri Jun 18 14:10:47 2021] zfs_rangelock_enter+0x127/0x580 [zfs]
[Fri Jun 18 14:10:47 2021] ? spl_kmem_zalloc+0xe9/0x140 [spl]
[Fri Jun 18 14:10:47 2021] zvol_get_data+0x81/0x170 [zfs]
[Fri Jun 18 14:10:47 2021] zil_commit_impl+0x9ad/0xd90 [zfs]
[Fri Jun 18 14:10:47 2021] zil_commit+0x3d/0x60 [zfs]
[Fri Jun 18 14:10:47 2021] zvol_request+0x233/0x3c0 [zfs]
[Fri Jun 18 14:10:47 2021] generic_make_request+0xcf/0x310
[Fri Jun 18 14:10:47 2021] submit_bio+0x46/0x1c0
[Fri Jun 18 14:10:47 2021] ? radix_tree_lookup+0xd/0x10
[Fri Jun 18 14:10:47 2021] ? blkg_lookup_slowpath+0x27/0x50
[Fri Jun 18 14:10:47 2021] submit_bio_wait+0x59/0x90
[Fri Jun 18 14:10:47 2021] blkdev_issue_flush+0x8e/0xc0
[Fri Jun 18 14:10:47 2021] blkdev_fsync+0x35/0x50
[Fri Jun 18 14:10:47 2021] vfs_fsync_range+0x48/0x80
[Fri Jun 18 14:10:47 2021] ? __fget_light+0x59/0x70
[Fri Jun 18 14:10:47 2021] do_fsync+0x3d/0x70
[Fri Jun 18 14:10:47 2021] __x64_sys_fdatasync+0x17/0x20
[Fri Jun 18 14:10:47 2021] do_syscall_64+0x57/0x190
[Fri Jun 18 14:10:47 2021] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[Fri Jun 18 14:10:47 2021] RIP: 0033:0x7f8c80ba62e7
[Fri Jun 18 14:10:47 2021] Code: Bad RIP value.
[Fri Jun 18 14:10:47 2021] RSP: 002b:00007f7729a56cc0 EFLAGS: 00000293 ORIG_RAX: 000000000000004b
[Fri Jun 18 14:10:47 2021] RAX: ffffffffffffffda RBX: 000000000000000f RCX: 00007f8c80ba62e7
[Fri Jun 18 14:10:47 2021] RDX: 0000000000000000 RSI: 0000000000000000 RDI: 000000000000000f
[Fri Jun 18 14:10:47 2021] RBP: 000055ae008627f0 R08: 0000000000000000 R09: 00007f7729a56c40
[Fri Jun 18 14:10:47 2021] R10: 0000000060cc8c7c R11: 0000000000000293 R12: 000055adff3957da
[Fri Jun 18 14:10:47 2021] R13: 000055ae00862858 R14: 000055ae023080c0 R15: 000055ae013cbfb0
[Fri Jun 18 14:10:47 2021] INFO: task kvm:5371 blocked for more than 120 seconds.
[Fri Jun 18 14:10:47 2021] Tainted: P O 5.4.78-2-pve #1
[Fri Jun 18 14:10:47 2021] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
this was repeating.........
restore log:
restore vma archive: zstd -q -d -c /USB/backups/dump/vzdump-qemu-200-2021_06_12-00_03_51.vma.zst | vma extract -v -r /var/tmp/vzdumptmp30693.fifo - /var/tmp/vzdumptmp30693
CFG: size: 827 name: qemu-server.conf
DEV: dev_id=1 size: 34359738368 devname: drive-scsi0
DEV: dev_id=2 size: 107374182400 devname: drive-scsi1
DEV: dev_id=3 size: 107374182400 devname: drive-scsi2
DEV: dev_id=4 size: 107374182400 devname: drive-scsi3
CTIME: Sat Jun 12 00:03:51 2021
new volume ID is 'data:vm-201-disk-0'
new volume ID is 'data:vm-201-disk-1'
new volume ID is 'data:vm-201-disk-2'
new volume ID is 'data:vm-201-disk-3'
map 'drive-scsi0' to '/dev/zvol/data/vm-201-disk-0' (write zeros = 0)
map 'drive-scsi1' to '/dev/zvol/data/vm-201-disk-1' (write zeros = 0)
map 'drive-scsi2' to '/dev/zvol/data/vm-201-disk-2' (write zeros = 0)
map 'drive-scsi3' to '/dev/zvol/data/vm-201-disk-3' (write zeros = 0)
progress 1% (read 3564830720 bytes, duration 6 sec)
progress 2% (read 7129661440 bytes, duration 11 sec)
progress 3% (read 10694492160 bytes, duration 18 sec)
progress 4% (read 14259322880 bytes, duration 26 sec)
progress 5% (read 17824153600 bytes, duration 34 sec)
progress 6% (read 21388984320 bytes, duration 43 sec)
progress 7% (read 24953815040 bytes, duration 51 sec)
progress 8% (read 28518645760 bytes, duration 58 sec)
progress 9% (read 32083410944 bytes, duration 63 sec)
progress 10% (read 35648241664 bytes, duration 70 sec)
progress 11% (read 39213072384 bytes, duration 78 sec)
progress 12% (read 42777903104 bytes, duration 85 sec)
progress 13% (read 46342733824 bytes, duration 93 sec)
progress 14% (read 49907564544 bytes, duration 100 sec)
progress 15% (read 53472395264 bytes, duration 107 sec)
progress 16% (read 57037225984 bytes, duration 115 sec)
progress 17% (read 60601991168 bytes, duration 122 sec)
progress 18% (read 64166821888 bytes, duration 128 sec)
progress 19% (read 67731652608 bytes, duration 131 sec)
progress 20% (read 71296483328 bytes, duration 132 sec)
progress 21% (read 74861314048 bytes, duration 134 sec)
progress 22% (read 78426144768 bytes, duration 134 sec)
progress 23% (read 81990975488 bytes, duration 137 sec)
progress 24% (read 85555806208 bytes, duration 138 sec)
progress 25% (read 89120571392 bytes, duration 140 sec)
progress 26% (read 92685402112 bytes, duration 144 sec)
progress 27% (read 96250232832 bytes, duration 144 sec)
progress 28% (read 99815063552 bytes, duration 151 sec)
progress 29% (read 103379894272 bytes, duration 155 sec)
progress 30% (read 106944724992 bytes, duration 160 sec)
progress 31% (read 110509555712 bytes, duration 165 sec)
progress 32% (read 114074386432 bytes, duration 171 sec)
progress 33% (read 117639217152 bytes, duration 179 sec)
progress 34% (read 121203982336 bytes, duration 186 sec)
progress 35% (read 124768813056 bytes, duration 194 sec)
progress 36% (read 128333643776 bytes, duration 202 sec)
progress 37% (read 131898474496 bytes, duration 209 sec)
progress 38% (read 135463305216 bytes, duration 217 sec)
progress 39% (read 139028135936 bytes, duration 225 sec)
progress 40% (read 142592966656 bytes, duration 233 sec)
progress 41% (read 146157797376 bytes, duration 240 sec)
progress 42% (read 149722562560 bytes, duration 246 sec)
progress 43% (read 153287393280 bytes, duration 254 sec)
progress 44% (read 156852224000 bytes, duration 261 sec)
progress 45% (read 160417054720 bytes, duration 269 sec)
progress 46% (read 163981885440 bytes, duration 276 sec)
progress 47% (read 167546716160 bytes, duration 284 sec)
progress 48% (read 171111546880 bytes, duration 290 sec)
progress 49% (read 174676377600 bytes, duration 298 sec)
progress 50% (read 178241142784 bytes, duration 306 sec)
progress 51% (read 181805973504 bytes, duration 314 sec)
progress 52% (read 185370804224 bytes, duration 322 sec)
progress 53% (read 188935634944 bytes, duration 330 sec)
progress 54% (read 192500465664 bytes, duration 338 sec)
progress 55% (read 196065296384 bytes, duration 347 sec)
progress 56% (read 199630127104 bytes, duration 355 sec)
progress 57% (read 203194957824 bytes, duration 362 sec)
progress 58% (read 206759788544 bytes, duration 371 sec)
progress 59% (read 210324553728 bytes, duration 380 sec)
progress 60% (read 213889384448 bytes, duration 387 sec)
progress 61% (read 217454215168 bytes, duration 397 sec)
progress 62% (read 221019045888 bytes, duration 406 sec)
progress 63% (read 224583876608 bytes, duration 417 sec)
progress 64% (read 228148707328 bytes, duration 428 sec)
progress 65% (read 231713538048 bytes, duration 438 sec)
progress 66% (read 235278368768 bytes, duration 447 sec)
progress 67% (read 238843133952 bytes, duration 459 sec)
progress 68% (read 242407964672 bytes, duration 469 sec)
progress 69% (read 245972795392 bytes, duration 480 sec)
progress 70% (read 249537626112 bytes, duration 491 sec)
progress 71% (read 253102456832 bytes, duration 502 sec)
progress 72% (read 256667287552 bytes, duration 513 sec)
progress 73% (read 260232118272 bytes, duration 523 sec)
progress 74% (read 263796948992 bytes, duration 533 sec)
progress 75% (read 267361714176 bytes, duration 545 sec)
progress 76% (read 270926544896 bytes, duration 556 sec)
progress 77% (read 274491375616 bytes, duration 565 sec)
progress 78% (read 278056206336 bytes, duration 575 sec)
progress 79% (read 281621037056 bytes, duration 585 sec)
progress 80% (read 285185867776 bytes, duration 594 sec)
progress 81% (read 288750698496 bytes, duration 605 sec)
progress 82% (read 292315529216 bytes, duration 615 sec)
progress 83% (read 295880359936 bytes, duration 625 sec)
progress 84% (read 299445125120 bytes, duration 633 sec)
progress 85% (read 303009955840 bytes, duration 642 sec)
progress 86% (read 306574786560 bytes, duration 654 sec)
progress 87% (read 310139617280 bytes, duration 664 sec)
progress 88% (read 313704448000 bytes, duration 673 sec)
progress 89% (read 317269278720 bytes, duration 683 sec)
progress 90% (read 320834109440 bytes, duration 694 sec)
progress 91% (read 324398940160 bytes, duration 702 sec)
progress 92% (read 327963705344 bytes, duration 712 sec)
progress 93% (read 331528536064 bytes, duration 721 sec)
progress 94% (read 335093366784 bytes, duration 730 sec)
progress 95% (read 338658197504 bytes, duration 741 sec)
progress 96% (read 342223028224 bytes, duration 750 sec)
progress 97% (read 345787858944 bytes, duration 759 sec)
progress 98% (read 349352689664 bytes, duration 768 sec)
progress 99% (read 352917520384 bytes, duration 778 sec)
progress 100% (read 356482285568 bytes, duration 787 sec)
I stopped it here, as it just sat there and things starting going wrong.
Original VM: