]> git.proxmox.com Git - qemu-server.git/blobdiff - PVE/QemuMigrate.pm
migration: rework logging to more humand friendly, less spammy
[qemu-server.git] / PVE / QemuMigrate.pm
index 09289a5f4503e123de64151fdcfb7127ab2443d7..6be0bf903dd404cc333f3f2b9bcc855dbac3a955 100644 (file)
@@ -8,8 +8,9 @@ use IPC::Open2;
 use POSIX qw( WNOHANG );
 use Time::HiRes qw( usleep );
 
+use PVE::Format qw(render_bytes);
 use PVE::Cluster;
-use PVE::GuestHelpers qw(safe_string_ne);
+use PVE::GuestHelpers qw(safe_boolean_ne safe_string_ne);
 use PVE::INotify;
 use PVE::RPCEnvironment;
 use PVE::Replication;
@@ -434,6 +435,9 @@ sub scan_local_volumes {
 
        my $replicatable_volumes = !$self->{replication_jobcfg} ? {}
            : PVE::QemuConfig->get_replicatable_volumes($storecfg, $vmid, $conf, 0, 1);
+       foreach my $volid (keys %{$replicatable_volumes}) {
+           $local_volumes->{$volid}->{replicated} = 1;
+       }
 
        my $test_volid = sub {
            my ($volid, $attr) = @_;
@@ -473,6 +477,9 @@ sub scan_local_volumes {
 
            $local_volumes->{$volid}->{is_vmstate} = $attr->{is_vmstate} ? 1 : 0;
 
+           $local_volumes->{$volid}->{drivename} = $attr->{drivename}
+               if $attr->{drivename};
+
            if ($attr->{cdrom}) {
                if ($volid =~ /vm-\d+-cloudinit/) {
                    $local_volumes->{$volid}->{ref} = 'generated';
@@ -557,43 +564,6 @@ sub scan_local_volumes {
            }
        }
 
-       if ($self->{replication_jobcfg}) {
-           if ($self->{running}) {
-
-               my $version = PVE::QemuServer::kvm_user_version();
-               if (!min_version($version, 4, 2)) {
-                   die "can't live migrate VM with replicated volumes, pve-qemu to old (< 4.2)!\n"
-               }
-
-               my $live_replicatable_volumes = {};
-               PVE::QemuConfig->foreach_volume($conf, sub {
-                   my ($ds, $drive) = @_;
-
-                   my $volid = $drive->{file};
-                   $live_replicatable_volumes->{$ds} = $volid
-                       if defined($replicatable_volumes->{$volid});
-               });
-               foreach my $drive (keys %$live_replicatable_volumes) {
-                   my $volid = $live_replicatable_volumes->{$drive};
-
-                   my $bitmap = "repl_$drive";
-
-                   # start tracking before replication to get full delta + a few duplicates
-                   $self->log('info', "$drive: start tracking writes using block-dirty-bitmap '$bitmap'");
-                   mon_cmd($vmid, 'block-dirty-bitmap-add', node => "drive-$drive", name => $bitmap);
-
-                   # other info comes from target node in phase 2
-                   $self->{target_drive}->{$drive}->{bitmap} = $bitmap;
-               }
-           }
-           $self->log('info', "replicating disk images");
-
-           my $start_time = time();
-           my $logfunc = sub { $self->log('info', shift) };
-           $self->{replicated_volumes} = PVE::Replication::run_replication(
-              'PVE::QemuConfig', $self->{replication_jobcfg}, $start_time, $start_time, $logfunc);
-       }
-
        foreach my $volid (sort keys %$local_volumes) {
            my $ref = $local_volumes->{$volid}->{ref};
            if ($self->{running} && $ref eq 'config') {
@@ -601,7 +571,6 @@ sub scan_local_volumes {
            } elsif ($self->{running} && $ref eq 'generated') {
                die "can't live migrate VM with local cloudinit disk. use a shared storage instead\n";
            } else {
-               next if $self->{replicated_volumes}->{$volid};
                $local_volumes->{$volid}->{migration_mode} = 'offline';
            }
        }
@@ -609,6 +578,50 @@ sub scan_local_volumes {
     die "Problem found while scanning volumes - $@" if $@;
 }
 
+sub handle_replication {
+    my ($self, $vmid) = @_;
+
+    my $conf = $self->{vmconf};
+    my $local_volumes = $self->{local_volumes};
+
+    return if !$self->{replication_jobcfg};
+    if ($self->{running}) {
+
+       my $version = PVE::QemuServer::kvm_user_version();
+       if (!min_version($version, 4, 2)) {
+           die "can't live migrate VM with replicated volumes, pve-qemu to old (< 4.2)!\n"
+       }
+
+       my @live_replicatable_volumes = $self->filter_local_volumes('online', 1);
+       foreach my $volid (@live_replicatable_volumes) {
+           my $drive = $local_volumes->{$volid}->{drivename};
+           die "internal error - no drive for '$volid'\n" if !defined($drive);
+
+           my $bitmap = "repl_$drive";
+
+           # start tracking before replication to get full delta + a few duplicates
+           $self->log('info', "$drive: start tracking writes using block-dirty-bitmap '$bitmap'");
+           mon_cmd($vmid, 'block-dirty-bitmap-add', node => "drive-$drive", name => $bitmap);
+
+           # other info comes from target node in phase 2
+           $self->{target_drive}->{$drive}->{bitmap} = $bitmap;
+       }
+    }
+    $self->log('info', "replicating disk images");
+
+    my $start_time = time();
+    my $logfunc = sub { $self->log('info', shift) };
+    my $actual_replicated_volumes = PVE::Replication::run_replication(
+       'PVE::QemuConfig', $self->{replication_jobcfg}, $start_time, $start_time, $logfunc);
+
+    # extra safety check
+    my @replicated_volumes = $self->filter_local_volumes(undef, 1);
+    foreach my $volid (@replicated_volumes) {
+       die "expected volume '$volid' to get replicated, but it wasn't\n"
+           if !$actual_replicated_volumes->{$volid};
+    }
+}
+
 sub config_update_local_disksizes {
     my ($self) = @_;
 
@@ -637,13 +650,14 @@ sub config_update_local_disksizes {
 }
 
 sub filter_local_volumes {
-    my ($self, $migration_mode) = @_;
+    my ($self, $migration_mode, $replicated) = @_;
 
     my $volumes = $self->{local_volumes};
     my @filtered_volids;
 
     foreach my $volid (sort keys %{$volumes}) {
        next if defined($migration_mode) && safe_string_ne($volumes->{$volid}->{migration_mode}, $migration_mode);
+       next if defined($replicated) && safe_boolean_ne($volumes->{$volid}->{replicated}, $replicated);
        push @filtered_volids, $volid;
     }
 
@@ -654,7 +668,7 @@ sub sync_offline_local_volumes {
     my ($self) = @_;
 
     my $local_volumes = $self->{local_volumes};
-    my @volids = $self->filter_local_volumes('offline');
+    my @volids = $self->filter_local_volumes('offline', 0);
 
     my $storecfg = $self->{storecfg};
     my $opts = $self->{opts};
@@ -695,9 +709,11 @@ sub sync_offline_local_volumes {
 sub cleanup_remotedisks {
     my ($self) = @_;
 
+    my $local_volumes = $self->{local_volumes};
+
     foreach my $volid (values %{$self->{volume_map}}) {
        # don't clean up replicated disks!
-       next if defined($self->{replicated_volumes}->{$volid});
+       next if $local_volumes->{$volid}->{replicated};
 
        my ($storeid, $volname) = PVE::Storage::parse_volume_id($volid);
 
@@ -739,6 +755,8 @@ sub phase1 {
     $self->config_update_local_disksizes();
     PVE::QemuConfig->write_config($vmid, $conf);
 
+    $self->handle_replication($vmid);
+
     $self->sync_offline_local_volumes();
 };
 
@@ -825,10 +843,8 @@ sub phase2 {
     my $input = $spice_ticket ? "$spice_ticket\n" : "\n";
     $input .= "nbd_protocol_version: $nbd_protocol_version\n";
 
-    my $number_of_online_replicated_volumes = 0;
-    foreach my $volid (@online_local_volumes) {
-       next if !$self->{replicated_volumes}->{$volid};
-       $number_of_online_replicated_volumes++;
+    my @online_replicated_volumes = $self->filter_local_volumes('online', 1);
+    foreach my $volid (@online_replicated_volumes) {
        $input .= "replicated_volume: $volid\n";
     }
 
@@ -906,7 +922,7 @@ sub phase2 {
 
     die "unable to detect remote migration address\n" if !$raddr;
 
-    if (scalar(keys %$target_replicated_volumes) != $number_of_online_replicated_volumes) {
+    if (scalar(keys %$target_replicated_volumes) != scalar(@online_replicated_volumes)) {
        die "number of replicated disks on source and target node do not match - target node too old?\n"
     }
 
@@ -942,10 +958,8 @@ sub phase2 {
     # load_defaults
     my $defaults = PVE::QemuServer::load_defaults();
 
-    $self->log('info', "set migration_caps");
-    eval {
-       PVE::QemuServer::set_migration_caps($vmid);
-    };
+    $self->log('info', "set migration capabilities");
+    eval { PVE::QemuServer::set_migration_caps($vmid) };
     warn $@ if $@;
 
     my $qemu_migrate_params = {};
@@ -962,15 +976,13 @@ sub phase2 {
     } else {
        $migrate_speed ||= $bwlimit;
     }
+    $migrate_speed ||= ($defaults->{migrate_speed} || 0) * 1024;
 
-    # always set migrate speed (overwrite kvm default of 32m) we set a very high
-    # default of 8192m which is basically unlimited
-    $migrate_speed ||= ($defaults->{migrate_speed} || 8192) * 1024;
-
-    # qmp takes migrate_speed in B/s.
-    $migrate_speed *= 1024;
-    $self->log('info', "migration speed limit: $migrate_speed B/s");
-    $qemu_migrate_params->{'max-bandwidth'} = int($migrate_speed);
+    if ($migrate_speed) {
+       $migrate_speed *= 1024; # qmp takes migrate_speed in B/s.
+       $self->log('info', "migration speed limit: ". render_bytes($migrate_speed, 1) ."/s");
+       $qemu_migrate_params->{'max-bandwidth'} = int($migrate_speed);
+    }
 
     my $migrate_downtime = $defaults->{migrate_downtime};
     $migrate_downtime = $conf->{migrate_downtime} if defined($conf->{migrate_downtime});
@@ -984,7 +996,7 @@ sub phase2 {
     my $cachesize = int($memory * 1048576 / 10);
     $cachesize = round_powerof2($cachesize);
 
-    $self->log('info', "migration cachesize: $cachesize B");
+    $self->log('info', "migration cachesize: " . render_bytes($cachesize, 1));
     $qemu_migrate_params->{'xbzrle-cache-size'} = int($cachesize);
 
     $self->log('info', "set migration parameters");
@@ -1020,7 +1032,7 @@ sub phase2 {
     my $merr = $@;
     $self->log('info', "migrate uri => $ruri failed: $merr") if $merr;
 
-    my $lstat = 0;
+    my $last_mem_transferred = 0;
     my $usleep = 1000000;
     my $i = 0;
     my $err_count = 0;
@@ -1028,95 +1040,124 @@ sub phase2 {
     my $downtimecounter = 0;
     while (1) {
        $i++;
-       my $avglstat = $lstat ? $lstat / $i : 0;
+       my $avglstat = $last_mem_transferred ? $last_mem_transferred / $i : 0;
 
        usleep($usleep);
-       my $stat;
-       eval {
-           $stat = mon_cmd($vmid, "query-migrate");
-       };
+
+       my $stat = eval { mon_cmd($vmid, "query-migrate") };
        if (my $err = $@) {
            $err_count++;
            warn "query migrate failed: $err\n";
            $self->log('info', "query migrate failed: $err");
            if ($err_count <= 5) {
-               usleep(1000000);
+               usleep(1_000_000);
                next;
            }
            die "too many query migrate failures - aborting\n";
        }
 
-        if (defined($stat->{status}) && $stat->{status} =~ m/^(setup)$/im) {
-            sleep(1);
-            next;
-        }
-
-       if (defined($stat->{status}) && $stat->{status} =~ m/^(active|completed|failed|cancelled)$/im) {
-           $merr = undef;
-           $err_count = 0;
-           if ($stat->{status} eq 'completed') {
-               my $delay = time() - $start;
-               if ($delay > 0) {
-                   my $mbps = sprintf "%.2f", $memory / $delay;
-                   my $downtime = $stat->{downtime} || 0;
-                   $self->log('info', "migration speed: $mbps MB/s - downtime $downtime ms");
-               }
-           }
+       my $status = $stat->{status};
+       if (defined($status) && $status =~ m/^(setup)$/im) {
+           sleep(1);
+           next;
+       }
 
-           if ($stat->{status} eq 'failed' || $stat->{status} eq 'cancelled') {
-               $self->log('info', "migration status error: $stat->{status}");
-               die "aborting\n"
+       if (!defined($status) || $status !~ m/^(active|completed|failed|cancelled)$/im) {
+           die $merr if $merr;
+           die "unable to parse migration status '$status' - aborting\n";
+       }
+       $merr = undef;
+       $err_count = 0;
+
+       my $memstat = $stat->{ram};
+
+       if ($status eq 'completed') {
+           my $delay = time() - $start;
+           if ($delay > 0) {
+               my $total = $memstat->{total} || 0;
+               my $avg_speed = render_bytes($total / $delay, 1);
+               my $downtime = $stat->{downtime} || 0;
+               $self->log('info', "average migration speed: $avg_speed/s - downtime $downtime ms");
            }
+       }
+
+       if ($status eq 'failed' || $status eq 'cancelled') {
+           $self->log('info', "migration status error: $status");
+           die "aborting\n"
+       }
+
+       if ($status ne 'active') {
+           $self->log('info', "migration status: $status");
+           last;
+       }
+
+       if ($memstat->{transferred} ne $last_mem_transferred) {
+           my $trans = $memstat->{transferred} || 0;
+           my $rem = $memstat->{remaining} || 0;
+           my $total = $memstat->{total} || 0;
+           my $speed = ($memstat->{'pages-per-second'} // 0) * ($memstat->{'page-size'} // 0);
+           my $dirty_rate = ($memstat->{'dirty-pages-rate'} // 0) * ($memstat->{'page-size'} // 0);
+
+           # reduce sleep if remainig memory is lower than the average transfer speed
+           $usleep = 100_000 if $avglstat && $rem < $avglstat;
+
 
-           if ($stat->{status} ne 'active') {
-               $self->log('info', "migration status: $stat->{status}");
-               last;
+           my $total_h = render_bytes($total, 1);
+           my $transferred_h = render_bytes($trans, 1);
+           my $speed_h = render_bytes($speed, 1);
+
+           my $progress = "transferred $transferred_h of $total_h VM-state, ${speed_h}/s";
+
+           if ($dirty_rate > $speed) {
+               my $dirty_rate_h = render_bytes($dirty_rate, 1);
+               $progress .= ", VM dirties lots of memory: $dirty_rate_h/s";
            }
 
-           if ($stat->{ram}->{transferred} ne $lstat) {
-               my $trans = $stat->{ram}->{transferred} || 0;
-               my $rem = $stat->{ram}->{remaining} || 0;
-               my $total = $stat->{ram}->{total} || 0;
-               my $xbzrlecachesize = $stat->{"xbzrle-cache"}->{"cache-size"} || 0;
-               my $xbzrlebytes = $stat->{"xbzrle-cache"}->{"bytes"} || 0;
-               my $xbzrlepages = $stat->{"xbzrle-cache"}->{"pages"} || 0;
-               my $xbzrlecachemiss = $stat->{"xbzrle-cache"}->{"cache-miss"} || 0;
-               my $xbzrleoverflow = $stat->{"xbzrle-cache"}->{"overflow"} || 0;
-               # reduce sleep if remainig memory is lower than the average transfer speed
-               $usleep = 100000 if $avglstat && $rem < $avglstat;
-
-               $self->log('info', "migration status: $stat->{status} (transferred ${trans}, " .
-                          "remaining ${rem}), total ${total})");
-
-               if (${xbzrlecachesize}) {
-                   $self->log('info', "migration xbzrle cachesize: ${xbzrlecachesize} transferred ${xbzrlebytes} pages ${xbzrlepages} cachemiss ${xbzrlecachemiss} overflow ${xbzrleoverflow}");
-               }
+           $self->log('info', "migration $status, $progress");
 
-               if (($lastrem  && $rem > $lastrem ) || ($rem == 0)) {
-                   $downtimecounter++;
-               }
-               $lastrem = $rem;
-
-               if ($downtimecounter > 5) {
-                   $downtimecounter = 0;
-                   $migrate_downtime *= 2;
-                   $self->log('info', "auto-increased downtime to continue migration: $migrate_downtime ms");
-                   eval {
-                       # migrate-set-parameters does not touch values not
-                       # specified, so this only changes downtime-limit
-                       mon_cmd($vmid, "migrate-set-parameters", 'downtime-limit' => int($migrate_downtime));
-                   };
-                   $self->log('info', "migrate-set-parameters error: $@") if $@;
-               }
+           my $xbzrle = $stat->{"xbzrle-cache"} || {};
+           my ($xbzrlebytes, $xbzrlepages) = $xbzrle->@{'bytes', 'pages'};
+           if ($xbzrlebytes || $xbzrlepages) {
+               my $bytes_h = render_bytes($xbzrlebytes, 1);
+
+               my $msg = "send updates to $xbzrlepages pages in $bytes_h encoded memory";
+
+               $msg .= sprintf(", cache-miss %.2f%%", $xbzrle->{'cache-miss-rate'} * 100)
+                   if $xbzrle->{'cache-miss-rate'};
 
+               $msg .= ", overflow $xbzrle->{overflow}" if $xbzrle->{overflow};
+
+               $self->log('info', "xbzrle: $msg");
            }
 
+           if (($lastrem && $rem > $lastrem) || ($rem == 0)) {
+               $downtimecounter++;
+           }
+           $lastrem = $rem;
+
+           if ($downtimecounter > 5) {
+               $downtimecounter = 0;
+               $migrate_downtime *= 2;
+               $self->log('info', "auto-increased downtime to continue migration: $migrate_downtime ms");
+               eval {
+                   # migrate-set-parameters does not touch values not
+                   # specified, so this only changes downtime-limit
+                   mon_cmd($vmid, "migrate-set-parameters", 'downtime-limit' => int($migrate_downtime));
+               };
+               $self->log('info', "migrate-set-parameters error: $@") if $@;
+           }
+       }
 
-           $lstat = $stat->{ram}->{transferred};
+       $last_mem_transferred = $memstat->{transferred};
+    }
 
-       } else {
-           die $merr if $merr;
-           die "unable to parse migration status '$stat->{status}' - aborting\n";
+    if ($self->{storage_migration}) {
+       # finish block-job with block-job-cancel, to disconnect source VM from NBD
+       # to avoid it trying to re-establish it. We are in blockjob ready state,
+       # thus, this command changes to it to blockjob complete (see qapi docs)
+       eval { PVE::QemuServer::qemu_drive_mirror_monitor($vmid, undef, $self->{storage_migration_jobs}, 'cancel'); };
+       if (my $err = $@) {
+           die "Failed to complete storage migration: $err\n";
        }
     }
 }
@@ -1194,19 +1235,6 @@ sub phase3_cleanup {
 
     my $tunnel = $self->{tunnel};
 
-    if ($self->{storage_migration}) {
-       # finish block-job with block-job-cancel, to disconnect source VM from NBD
-       # to avoid it trying to re-establish it. We are in blockjob ready state,
-       # thus, this command changes to it to blockjob complete (see qapi docs)
-       eval { PVE::QemuServer::qemu_drive_mirror_monitor($vmid, undef, $self->{storage_migration_jobs}, 'cancel'); };
-
-       if (my $err = $@) {
-           eval { PVE::QemuServer::qemu_blockjobs_cancel($vmid, $self->{storage_migration_jobs}) };
-           eval { PVE::QemuMigrate::cleanup_remotedisks($self) };
-           die "Failed to complete storage migration: $err\n";
-       }
-    }
-
     if ($self->{volume_map}) {
        my $target_drives = $self->{target_drive};
 
@@ -1308,11 +1336,10 @@ sub phase3_cleanup {
        $self->{errors} = 1;
     }
 
-    # destroy local copies
-    foreach my $volid (keys %{$self->{local_volumes}}) {
-       # keep replicated volumes!
-       next if $self->{replicated_volumes}->{$volid};
+    my @not_replicated_volumes = $self->filter_local_volumes(undef, 0);
 
+    # destroy local copies
+    foreach my $volid (@not_replicated_volumes) {
        eval { PVE::Storage::vdisk_free($self->{storecfg}, $volid); };
        if (my $err = $@) {
            $self->log('err', "removing local copy of '$volid' failed - $err");