KVM resumed before backup finished

ppo

Renowned Member
Aug 6, 2012
49
0
71
What this line mean?
125: Jul 31 02:30:20 INFO: resume VM
Code:
Detailed backup logs:

vzdump 125 --mailnotification always --quiet 1 --mailto [EMAIL="ppo@ektos.net"]my@email.addr[/EMAIL] --mode stop --node pve3 --compress gzip --storage sdb

125: Jul 31 02:30:02 INFO: Starting Backup of VM 125 (qemu)
125: Jul 31 02:30:02 INFO: status = running
125: Jul 31 02:30:02 INFO: update VM 125: -lock backup
125: Jul 31 02:30:02 INFO: backup mode: stop
125: Jul 31 02:30:02 INFO: ionice priority: 7
125: Jul 31 02:30:03 INFO: stopping vm
125: Jul 31 02:30:19 INFO: creating archive '/mnt/sdb/dump/vzdump-qemu-125-2015_07_31-02_30_01.vma.gz'
125: Jul 31 02:30:19 INFO: starting kvm to execute backup task
125: Jul 31 02:30:20 INFO: started backup task 'c6218ce4-613d-4b05-9114-89ba7ae99530'
125: Jul 31 02:30:20 INFO: resume VM
125: Jul 31 02:30:23 INFO: status: 0% (581500928/107374182400), sparse 0% (517718016), duration 3, 193/21 MB/s
125: Jul 31 02:30:49 INFO: status: 1% (1075707904/107374182400), sparse 0% (608739328), duration 29, 19/15 MB/s
125: Jul 31 02:31:30 INFO: status: 2% (2174222336/107374182400), sparse 0% (646520832), duration 70, 26/25 MB/s
125: Jul 31 02:32:07 INFO: status: 3% (3228762112/107374182400), sparse 0% (833675264), duration 107, 28/23 MB/s
125: Jul 31 02:33:00 INFO: status: 4% (4302438400/107374182400), sparse 0% (855830528), duration 160, 20/19 MB/s
125: Jul 31 02:33:48 INFO: status: 5% (5374738432/107374182400), sparse 0% (975114240), duration 208, 22/19 MB/s
125: Jul 31 02:34:41 INFO: status: 6% (6442844160/107374182400), sparse 0% (1013919744), duration 261, 20/19 MB/s
125: Jul 31 02:35:26 INFO: status: 7% (7533035520/107374182400), sparse 1% (1152880640), duration 306, 24/21 MB/s
125: Jul 31 02:36:18 INFO: status: 8% (8594259968/107374182400), sparse 1% (1156784128), duration 358, 20/20 MB/s
125: Jul 31 02:37:05 INFO: status: 9% (9673768960/107374182400), sparse 1% (1287643136), duration 405, 22/20 MB/s
125: Jul 31 02:37:57 INFO: status: 10% (10753277952/107374182400), sparse 1% (1300844544), duration 457, 20/20 MB/s
125: Jul 31 02:38:42 INFO: status: 11% (11826692096/107374182400), sparse 1% (1474121728), duration 502, 23/20 MB/s
125: Jul 31 02:39:01 INFO: status: 14% (15702294528/107374182400), sparse 4% (4971638784), duration 521, 203/19 MB/s
125: Jul 31 02:39:11 INFO: status: 15% (16354770944/107374182400), sparse 5% (5467996160), duration 531, 65/15 MB/s
125: Jul 31 02:39:14 INFO: status: 16% (17887920128/107374182400), sparse 6% (6957932544), duration 534, 511/14 MB/s
125: Jul 31 02:39:19 INFO: status: 18% (20180893696/107374182400), sparse 8% (9179623424), duration 539, 458/14 MB/s
125: Jul 31 02:39:22 INFO: status: 20% (22173450240/107374182400), sparse 10% (11136811008), duration 542, 664/11 MB/s
125: Jul 31 02:39:44 INFO: status: 21% (22559457280/107374182400), sparse 10% (11142332416), duration 564, 17/17 MB/s
125: Jul 31 02:40:39 INFO: status: 22% (23638966272/107374182400), sparse 10% (11149910016), duration 619, 19/19 MB/s
125: Jul 31 02:41:27 INFO: status: 23% (24707072000/107374182400), sparse 10% (11311689728), duration 667, 22/18 MB/s
125: Jul 31 02:42:19 INFO: status: 24% (25782321152/107374182400), sparse 10% (11320074240), duration 719, 20/20 MB/s
125: Jul 31 02:43:02 INFO: status: 25% (26847084544/107374182400), sparse 10% (11452350464), duration 762, 24/21 MB/s
125: Jul 31 02:43:54 INFO: status: 26% (27918991360/107374182400), sparse 10% (11452350464), duration 814, 20/20 MB/s
125: Jul 31 02:44:23 INFO: status: 28% (30066606080/107374182400), sparse 12% (13037068288), duration 843, 74/19 MB/s
125: Jul 31 02:44:35 INFO: status: 30% (32879411200/107374182400), sparse 14% (15630589952), duration 855, 234/18 MB/s
125: Jul 31 02:44:44 INFO: status: 32% (35030827008/107374182400), sparse 16% (17620021248), duration 864, 239/17 MB/s
125: Jul 31 02:44:57 INFO: status: 34% (37170839552/107374182400), sparse 18% (19512086528), duration 877, 164/19 MB/s
125: Jul 31 02:45:11 INFO: status: 35% (38221512704/107374182400), sparse 18% (20311449600), duration 891, 75/17 MB/s
125: Jul 31 02:45:14 INFO: status: 36% (39371669504/107374182400), sparse 19% (21402886144), duration 894, 383/19 MB/s
125: Jul 31 02:45:25 INFO: status: 41% (44252594176/107374182400), sparse 24% (26082091008), duration 905, 443/18 MB/s
125: Jul 31 02:45:28 INFO: status: 42% (45799309312/107374182400), sparse 25% (27586351104), duration 908, 515/14 MB/s
125: Jul 31 02:45:31 INFO: status: 58% (63161434112/107374182400), sparse 41% (44938428416), duration 911, 5787/3 MB/s
125: Jul 31 02:45:34 INFO: status: 72% (78046560256/107374182400), sparse 55% (59747000320), duration 914, 4961/25 MB/s
125: Jul 31 02:45:37 INFO: status: 87% (94169923584/107374182400), sparse 70% (75812605952), duration 917, 5374/19 MB/s
125: Jul 31 02:45:40 INFO: status: 96% (103229292544/107374182400), sparse 79% (84859731968), duration 920, 3019/4 MB/s
125: Jul 31 02:46:01 INFO: status: 98% (106259415040/107374182400), sparse 81% (87592587264), duration 941, 144/14 MB/s
125: Jul 31 02:46:02 INFO: status: 100% (107374182400/107374182400), sparse 82% (88707354624), duration 942, 1114/0 MB/s
125: Jul 31 02:46:02 INFO: transferred 107374 MB in 942 seconds (113 MB/s)
125: Jul 31 02:46:02 INFO: archive file size: 13.93GB
125: Jul 31 02:46:04 INFO: vm is online again after 961 seconds
125: Jul 31 02:46:04 INFO: Finished Backup of VM 125 (00:16:03)
 
Yor run backup in 'stop' mode, so the VM is stopped before backup starts. When the VM is stopped, we start backup and then restart (resume) the VM.
 
Yes, it's clear, but I expect this line should appears after image creation, after these lines:
125: Jul 31 02:46:02 INFO: transferred 107374 MB in 942 seconds (113 MB/s)
125: Jul 31 02:46:02 INFO: archive file size: 13.93GB

i.e. after 942 seconds, instead it appears immediately after stop:

125: Jul 31 02:30:03 INFO: stopping vm
125: Jul 31 02:30:19 INFO: creating archive '/mnt/sdb/dump/vzdump-qemu-125-2015_07_31-02_30_01.vma.gz'
125: Jul 31 02:30:19 INFO: starting kvm to execute backup task
125: Jul 31 02:30:20 INFO: started backup task 'c6218ce4-613d-4b05-9114-89ba7ae99530'
125: Jul 31 02:30:20 INFO: resume VM

This is a bit confusing.
 

About

The Proxmox community has been around for many years and offers help and support for Proxmox VE, Proxmox Backup Server, and Proxmox Mail Gateway.
We think our community is one of the best thanks to people like you!

Get your subscription!

The Proxmox team works very hard to make sure you are running the best software and getting stable updates and security enhancements, as well as quick enterprise support. Tens of thousands of happy customers have a Proxmox subscription. Get yours easily in our online shop.

Buy now!