]> 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 435c1f7cd11bc19c94021689777d27a0c32e019b..6be0bf903dd404cc333f3f2b9bcc855dbac3a955 100644 (file)
@@ -8,6 +8,7 @@ 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_boolean_ne safe_string_ne);
 use PVE::INotify;
@@ -957,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 = {};
@@ -977,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});
@@ -999,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");
@@ -1035,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;
@@ -1043,96 +1040,115 @@ 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 ($stat->{status} ne 'active') {
-               $self->log('info', "migration status: $stat->{status}");
-               last;
-           }
+       if ($status eq 'failed' || $status eq 'cancelled') {
+           $self->log('info', "migration status error: $status");
+           die "aborting\n"
+       }
 
-           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}");
-               }
+       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 (($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 $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";
            }
 
+           $self->log('info', "migration $status, $progress");
 
-           $lstat = $stat->{ram}->{transferred};
+           my $xbzrle = $stat->{"xbzrle-cache"} || {};
+           my ($xbzrlebytes, $xbzrlepages) = $xbzrle->@{'bytes', 'pages'};
+           if ($xbzrlebytes || $xbzrlepages) {
+               my $bytes_h = render_bytes($xbzrlebytes, 1);
 
-       } else {
-           die $merr if $merr;
-           die "unable to parse migration status '$stat->{status}' - aborting\n";
+               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 $@;
+           }
        }
+
+       $last_mem_transferred = $memstat->{transferred};
     }
 
     if ($self->{storage_migration}) {