[Users] CT live migration stages duration

Sun Jan 22 23:56:42 PST 2017

Hello all!

I'd like to do some research on how long each stage of OpenVZ CT live migration takes.
I wonder if there is any single source of such information with particular timestamps? So far as I 
understood "-v" flag in vzmigrate command can't help me much with what I'd like to achieve. "-t" 
flag show some suspend statistics. The most relevant source is servers log both on source and 
destination ones. But it looks like I have to parse both of them to get the complete picture of the 
CT migration process.
I've tried different values for LOG_LEVEL in /etc/vz/vz.conf (1, 5, 10 with following 'service vz 
restart') but it seems like an amount of details appearing in the log is not changed despite of what 
is written in 'man vz.conf':
LOG_LEVEL=number
               Set the logging level for the log file (does not affect console output).  The greater 
the number is, the more information will be logged to the LOGFILE. Default is 0, which means to log 
normal messages and errors. If set to -1, only errors will be logged.
 From that description it's not clear what the maximum reasonable value for that parameter is).

Part of the /var/log/vzctl.log on source:
2017-01-23T10:28:23+0300 vzctl : CT 100 : Setting up checkpoint...
2017-01-23T10:28:23+0300 vzctl : CT 100 :       set CPU flags..
2017-01-23T02:28:23-0500 vzctl : CT 100 :       suspend...
2017-01-23T02:28:23-0500 vzctl : CT 100 :       get context...
2017-01-23T10:28:23+0300 vzctl : CT 100 : Checkpointing completed successfully
2017-01-23T10:28:23+0300 vzctl : CT 100 : Setting up checkpoint...
2017-01-23T10:28:23+0300 vzctl : CT 100 :       join context..
2017-01-23T02:28:23-0500 vzctl : CT 100 :       dump...
2017-01-23T10:28:23+0300 vzctl : CT 100 : Checkpointing completed successfully
2017-01-23T10:28:24+0300 vzctl : CT 100 : Killing...
2017-01-23T10:28:24+0300 vzctl : CT 100 :       put context
2017-01-23T10:28:24+0300 vzctl : CT 100 : The ploop library has been loaded successfully
2017-01-23T10:28:24+0300 : Unmounting file system at /vz/root/100
2017-01-23T10:28:24+0300 : Unmounting device /dev/ploop39934
2017-01-23T10:28:25+0300 vzctl : CT 100 : Container is unmounted
2017-01-23T10:28:25+0300 vzctl : CT 100 : Destroying container private area: /vz/private/100
2017-01-23T10:28:26+0300 vzctl : CT 100 : Container private area was destroyed
2017-01-23T10:28:45+0300 vzctl : CT 100 : stat(/vz/root/100): No such file or directory
2017-01-23T10:28:46+0300 vzctl : CT 100 : CT configuration saved to /etc/vz/conf/100.conf
2017-01-23T10:28:46+0300 vzctl : CT 100 : CT configuration saved to /etc/vz/conf/100.conf
2017-01-23T10:29:01+0300 vzctl : CT 100 : Restoring container ...
2017-01-23T10:29:01+0300 vzctl : CT 100 : The ploop library has been loaded successfully
2017-01-23T10:29:01+0300 : Opening delta /vz/private/100/root.hdd/root.hdd
2017-01-23T10:29:01+0300 : Adding delta dev=/dev/ploop39934 img=/vz/private/100/root.hdd/root.hdd (rw)
2017-01-23T10:29:01+0300 : Running: fsck.ext4 -p /dev/ploop39934p1
2017-01-23T10:29:01+0300 : Mounting /dev/ploop39934p1 at /vz/root/100 fstype=ext4 
data='balloon_ino=12,'
2017-01-23T10:29:01+0300 vzctl : CT 100 : Container is mounted
2017-01-23T10:29:01+0300 vzctl : CT 100 : Running: /usr/libexec/vzctl/scripts/vps-prestart
2017-01-23T10:29:01+0300 vzctl : CT 100 : Setting CPU units: 1000
2017-01-23T10:29:01+0300 vzctl : CT 100 : Setting CPUs: 2
2017-01-23T10:29:01+0300 vzctl : CT 100 : Setting devices
2017-01-23T10:29:01+0300 vzctl : CT 100 : Container start in progress...
2017-01-23T10:29:01+0300 vzctl : CT 100 : Restoring completed successfully
2017-01-23T10:29:01+0300 vzctl : CT 100 : Resuming...
2017-01-23T10:29:01+0300 vzctl : CT 100 :       put context

A part of the /var/log/vzctl.log on destination (lines with ' Executing command: /bin/cat 
/proc/net/dev' and 'Executing command: free -k ' are removed):
2017-01-23T10:28:08+0300 vzctl : CT 100 : stat(/vz/root/100): No such file or directory
2017-01-23T10:28:09+0300 vzctl : CT 100 : CT configuration saved to /etc/vz/conf/100.conf
2017-01-23T10:28:09+0300 vzctl : CT 100 : CT configuration saved to /etc/vz/conf/100.conf
2017-01-23T10:28:24+0300 vzctl : CT 100 : Restoring container ...
2017-01-23T10:28:24+0300 vzctl : CT 100 : The ploop library has been loaded successfully
2017-01-23T10:28:24+0300 : Opening delta /vz/private/100/root.hdd/root.hdd
2017-01-23T10:28:24+0300 : Adding delta dev=/dev/ploop38224 img=/vz/private/100/root.hdd/root.hdd (rw)
2017-01-23T10:28:24+0300 : Running: fsck.ext4 -p /dev/ploop38224p1
2017-01-23T10:28:24+0300 : Mounting /dev/ploop38224p1 at /vz/root/100 fstype=ext4 
data='balloon_ino=12,'
2017-01-23T10:28:24+0300 vzctl : CT 100 : Container is mounted
2017-01-23T10:28:24+0300 vzctl : CT 100 : Running: /usr/libexec/vzctl/scripts/vps-prestart
2017-01-23T10:28:24+0300 vzctl : CT 100 : Setting CPU units: 1000
2017-01-23T10:28:24+0300 vzctl : CT 100 : Setting CPUs: 2
2017-01-23T10:28:24+0300 vzctl : CT 100 : Setting devices
2017-01-23T10:28:24+0300 vzctl : CT 100 : Container start in progress...
2017-01-23T10:28:24+0300 vzctl : CT 100 : Restoring completed successfully
2017-01-23T10:28:24+0300 vzctl : CT 100 : Resuming...
2017-01-23T10:28:24+0300 vzctl : CT 100 :       put context
<....skipped....>
2017-01-23T10:29:00+0300 vzctl : CT 100 : Setting up checkpoint...
2017-01-23T10:29:00+0300 vzctl : CT 100 :       set CPU flags..
2017-01-23T02:29:00-0500 vzctl : CT 100 :       suspend...
2017-01-23T02:29:00-0500 vzctl : CT 100 :       get context...
2017-01-23T10:29:00+0300 vzctl : CT 100 : Checkpointing completed successfully
2017-01-23T10:29:00+0300 vzctl : CT 100 : Setting up checkpoint...
2017-01-23T10:29:00+0300 vzctl : CT 100 :       join context..
2017-01-23T02:29:00-0500 vzctl : CT 100 :       dump...
2017-01-23T10:29:00+0300 vzctl : CT 100 : Checkpointing completed successfully
2017-01-23T10:29:01+0300 vzctl : CT 100 : Killing...
2017-01-23T10:29:02+0300 vzctl : CT 100 :       put context
2017-01-23T10:29:02+0300 vzctl : CT 100 : The ploop library has been loaded successfully
2017-01-23T10:29:02+0300 : Unmounting file system at /vz/root/100
2017-01-23T10:29:02+0300 : Unmounting device /dev/ploop38224
2017-01-23T10:29:02+0300 vzctl : CT 100 : Container is unmounted
2017-01-23T10:29:02+0300 vzctl : CT 100 : Destroying container private area: /vz/private/100
2017-01-23T10:29:03+0300 vzctl : CT 100 : Container private area was destroyed

So as far as I understand in order to evaluate a duration of each live migration stage I have to 
parse logs on both source and destination servers. But before I will try to write some script doing 
that I'd like to make sure there is no another way of extracting such info unless to parse logs of 
both servers.

I have installed the following versions of vz* packages on both servers:
vzctl-4.9.4-1.x86_64
vzctl-core-4.9.4-1.x86_64
vzkernel-2.6.32-042stab120.16.x86_64
vzquota-3.1-1.x86_64
vzstats-0.5.3-1.noarch

Best regards,
Nikolay.