Libguestfs - Nov 2016 - Re: [ovirt-users] OVA import of FC21 VM hangs during virt-v2v conversion?

Hi,

On Wed, November 16, 2016 11:10 am, Richard W.M. Jones
wrote:
>
>> It eventually did complete, after several hours.  But I don't
understand
>> why this particular VM took so long when others (with similar disk
>> sizes/usages/configurations) completed in only 1-2 minutes.  Each VM is
>> effectively exactly the same (it's a build slave), so it's just
the
>> basic installation of the particular Fedora release, the build tools,
>> and the build slave configuration.  Beyond the underlying fedora
release
>> version, the systems are configured exactly the same.
>>
>> I migrated four similar VMs.  Three of them completed almost
>> immediately.  The last too much longer.  The ONLY thing different about
>> the one that took longer was that I decided to pack the disk first, so
I
>> ran:
>>
>>   vmware-toolbox-cmd disk shrink /
>
> I'm not familiar with this command.  In general terms, conversions
> take a time proportional to the amount of disk space in use by the
> guest.
This command is a disk defragment + shrink inside VMware.  Basically, the
.vmdk was about 36G even though the system was only using about 3G. 
Running this command released all that free space and then reduced the
VMDK file.

I figured the time should be proportional to disk usage, which is why I
was so surprised that it took orders of magnitude longer than other
systems with similar disk usage (and indeed, in some cases the other
systems that completed in minutes had MORE disk usage).
> Running `virt-v2v -v -x ...' and observing the output will give you a
> good idea of what precisely it was doing for those hours.
Well, as I said in my original email, it was hanging at running setfiles:

commandrvf: stdout=n stderr=y flags=0x0
commandrvf: setfiles -F -e /sysroot/dev -e /sysroot/proc -e
/sysroot/selinux -e /sysroot/sys -r /sysroot -q
/sysroot/etc/selinux/targeted/contexts/files/file_contexts /sysroot/
Can't stat exclude path "/sysroot/selinux", No such file or
directory
- ignoring.

There's no timestamp in the output or logs so it's hard to tell exactly
what happens when or how long each step takes.  For example, I wouldn't
know how long the setfiles step takes unless I sit there for hours
watching to see when it completes.  Is there some way to add timestamps to
each output line?

FWIW, here's the disk usage from within that VM:

Filesystem      Size  Used Avail Use% Mounted on
/dev/vda3        44G  4.6G   37G  12% /
devtmpfs        487M     0  487M   0% /dev
tmpfs           497M     0  497M   0% /dev/shm
tmpfs           497M  348K  496M   1% /run
tmpfs           497M     0  497M   0% /sys/fs/cgroup
tmpfs           497M  4.0K  496M   1% /tmp
/dev/vda1       969M  130M  773M  15% /boot
tmpfs           100M     0  100M   0% /run/user/1000
tmpfs           100M     0  100M   0% /run/user/0

For the record, Fedora 23, which imported in 2 minutes, has the following
disk usage:

Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        486M     0  486M   0% /dev
tmpfs           496M     0  496M   0% /dev/shm
tmpfs           496M  536K  496M   1% /run
tmpfs           496M     0  496M   0% /sys/fs/cgroup
/dev/vda3        45G  7.9G   37G  18% /
tmpfs           496M  4.0K  496M   1% /tmp
/dev/vda1       969M  136M  767M  15% /boot
tmpfs           100M     0  100M   0% /run/user/1000
tmpfs           100M     0  100M   0% /run/user/0

> Rich.
-derek
>
>> in the VM prior to packaging it up as an OVA.  All the OVA files are
>> relatively small and similar in size:
>>
>> -rw------- 1 warlord warlord  1959553024 Nov  7 10:40 fc20-64.ova
>> -rw------- 1 warlord warlord  1794907648 Nov  7 12:27 fc21-64.ova
>> -rw------- 1 warlord warlord  2023595520 Nov  6 10:04 fc22-64.ova
>> -rw------- 1 warlord warlord  3381622272 Nov  5 16:18 fc23-64.ova
>>
>> The FC23 and FC22 migrations took the least amount of time, even though
>> they were the largest.
>>
>> > Rich.
>>
>> -derek
>>
>> --
>>        Derek Atkins                 617-623-3745
>>        derek@ihtfp.com             www.ihtfp.com
>>        Computer and Internet Security Consultant
>
> --
> Richard Jones, Virtualization Group, Red Hat
> http://people.redhat.com/~rjones
> Read my programming and virtualization blog: http://rwmj.wordpress.com
> virt-builder quickly builds VMs from scratch
> http://libguestfs.org/virt-builder.1.html
>

-- 
       Derek Atkins                 617-623-3745
       derek@ihtfp.com             www.ihtfp.com
       Computer and Internet Security Consultant

On Wed, Nov 16, 2016 at 11:31:40AM -0500, Derek Atkins
wrote:
> > Running `virt-v2v -v -x ...' and observing the output will give
you a
> > good idea of what precisely it was doing for those hours.
> 
> Well, as I said in my original email, it was hanging at running setfiles:
>
> commandrvf: stdout=n stderr=y flags=0x0
> commandrvf: setfiles -F -e /sysroot/dev -e /sysroot/proc -e
> /sysroot/selinux -e /sysroot/sys -r /sysroot -q
> /sysroot/etc/selinux/targeted/contexts/files/file_contexts /sysroot/
> Can't stat exclude path "/sysroot/selinux", No such file or
directory
> - ignoring.
OK that's interesting.  setfiles is doing SELinux labelling of the
filesystem.  The time taken should be approximately proportional to
the number of files in the filesystem.

What it precisely does is to run the host's /usr/sbin/setfiles command
over the whole guest filesystem, using the guest's
/etc/selinux/targeted/contexts/files/file_contexts to control the
labelling.  So if either of the guest filesystem or the guest's
file_contexts is particularly large, or setfiles has a bug, then it
might take a long time.
> There's no timestamp in the output or logs so it's hard to tell
exactly
> what happens when or how long each step takes.  For example, I wouldn't
> know how long the setfiles step takes unless I sit there for hours
> watching to see when it completes.  Is there some way to add timestamps to
> each output line?
Run it through the annotate-output program.
https://linux.die.net/man/1/annotate-output

Rich.

-- 
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-p2v converts physical machines to virtual machines.  Boot with a
live CD or over the network (PXE) and turn machines into KVM guests.
http://libguestfs.org/virt-v2v

Hi Rich,

On Wed, November 16, 2016 1:34 pm, Richard W.M. Jones
wrote:
> On Wed, Nov 16, 2016 at 11:31:40AM -0500, Derek Atkins wrote:
>> > Running `virt-v2v -v -x ...' and observing the output will
give you a
>> > good idea of what precisely it was doing for those hours.
>>
>> Well, as I said in my original email, it was hanging at running
>> setfiles:
>>
>> commandrvf: stdout=n stderr=y flags=0x0
>> commandrvf: setfiles -F -e /sysroot/dev -e /sysroot/proc -e
>> /sysroot/selinux -e /sysroot/sys -r /sysroot -q
>> /sysroot/etc/selinux/targeted/contexts/files/file_contexts /sysroot/
>> Can't stat exclude path "/sysroot/selinux", No such file
or directory
>> - ignoring.
>
> OK that's interesting.  setfiles is doing SELinux labelling of the
> filesystem.  The time taken should be approximately proportional to
> the number of files in the filesystem.
>
> What it precisely does is to run the host's /usr/sbin/setfiles command
> over the whole guest filesystem, using the guest's
> /etc/selinux/targeted/contexts/files/file_contexts to control the
> labelling.  So if either of the guest filesystem or the guest's
> file_contexts is particularly large, or setfiles has a bug, then it
> might take a long time.
I suppose there could be a bug.  I just verified that it's absolutely
setfiles:

14:06:20 I: Started virt-v2v -v -x -i ova /ovirt/import/fc21-64.ova -of
raw -o null
14:06:20 O: [   0.0] Opening the source -i ova /ovirt/import/fc21-64.ova
[snip]
14:07:25 E: libguestfs: trace: v2v: aug_get = "targeted"
14:07:25 E: libguestfs: trace: v2v: aug_close
14:07:25 E: guestfsd: main_loop: new request, len 0x28
14:07:25 E: guestfsd: main_loop: proc 26 (aug_close) took 0.03 seconds
14:07:25 E: libguestfs: trace: v2v: aug_close = 0
14:07:25 E: libguestfs: trace: v2v: selinux_relabel
"/etc/selinux/targeted/contexts/files/file_contexts" "/"
"force:true"
14:07:25 E: guestfsd: main_loop: new request, len 0x6c
14:07:25 E: commandrvf: stdout=n stderr=y flags=0x0
14:07:25 E: commandrvf: setfiles -F -e /sysroot/dev -e /sysroot/proc -e
/sysroot/selinux -e /sysroot/sys -r /sysroot -q
/sysroot/etc/selinux/targeted/contexts/files/file_contexts /sysroot/
14:07:25 E: Can't stat exclude path "/sysroot/selinux", No such
file or
directory - ignoring.

[ Spacing Emphasis Mine -- there is no break (except time) here ]

16:00:42 E: libguestfs: trace: v2v: selinux_relabel = 0
16:00:42 O: virt-v2v: This guest has virtio drivers installed.
16:00:42 E: libguestfs: trace: v2v: rm_f "/.autorelabel"
16:00:42 E: guestfsd: main_loop: proc 467 (selinux_relabel) took 6797.01
seconds
16:00:42 E: guestfsd: main_loop: new request, len 0x3c
[SNIP]
16:01:13 I: Finished with exitcode 0

So it looks like it took almost two hours to run the setfiles on a 4GB
filesystem.  The rest of the import was only a minute or three.

I'm happy to help debug this however I can in order to fix any potential
bugs.  However I admit it probably wont affect me any more -- I don't
expect to migrate many more VMs.  Still, I'm happy to work towards the
common good.  :)
> Rich.
>
> --
> Richard Jones, Virtualization Group, Red Hat
> http://people.redhat.com/~rjones
> Read my programming and virtualization blog: http://rwmj.wordpress.com
> virt-p2v converts physical machines to virtual machines.  Boot with a
> live CD or over the network (PXE) and turn machines into KVM guests.
> http://libguestfs.org/virt-v2v
-derek

-- 
       Derek Atkins                 617-623-3745
       derek@ihtfp.com             www.ihtfp.com
       Computer and Internet Security Consultant