Very slow OVF import/export -> fixed in SVN

[DevOne]

OVF import/export is very slow, and it looks like it can be improved: During import, I noticed VirtualBox was reading at 4MB/s. This is on an internal hard disk, with the source and target on two different disks.

I used Process Monitor from Sysinternals, and noticed that VirtualBox is reading blocks of 64KB, 26 bytes and 16 bytes, repetitively (see attached screenshot). I think the reading speed would largely benefit from cached IOs, with a bigger buffer.

[DevOne]

Disk accesses

[Technologov]

Looks interesting. Adding myself :)

-Technologov

[Frank Mehnert]

Should be fixed in VBox 3.0.0, please try the newest release (currently 3.0.2).

[Jon Schneider]

I have just upgraded from v2 to v3.0.6 and am waiting for an export. It is as slow if not slower than before.

[Carl-Erik Kopseng]

I have just upgraded from v2 to v3.0.6 and am waiting for an export. It is as slow if not slower than before.

I am using the latest release (3.1.2 as of today) on 64 bit Windows 7 on an Intel X-25M SSD drive and too much RAM. Disk I/O is NOT an issue here, yet the export crawls at a measly 9 MB/s and a low cpu usage (for the most part).

The estimated time is pessimistic though: it estimated 32 min at the start of an export, but it took more in the order of ten minutes (suddenly dropping by 15 minutes).

I would try working on utilizing more than one core when exporting. The cpu utilization never rose above 50% (~100% on one core).

[Lyall Pearce]

VirtualBox 3.1.2 PUEL edition. Hosted on Linux with XFS filesystems.

Export a 32G dynamic disk with Windows XP Pro installed, crawled along at less than 1MB a second output from/to the same local disk.

Intel(R) Core(TM)2 Duo CPU E6550 @ 2.33GHz GenuineIntel GNU/Linux

[Matthew A.]

Same story here. Trying to export an appliance and it starts off fast (around 10MB/s), but then begins to crawl after the output file is about 250MB. The rate is somewhere under 1MB/s, and the source and destination drives are different.

Details:

• Windows 7 x64
• Latest release of VBox (3.1.6 as of today)
• Source drive is local internal SATA device, destination is a NAS mount with write speeds normally above 10MB/s.

[Sander van Leeuwen]

#6506 marked as a duplicate.

[Klaus Espenlaub]

Keep in mind that the VMDK export part is pretty cpu-intensive, as it compresses the resulting image file. Thus the write rate can become much lower than the write rate your filesystem can handle. Blocks of zeroes compress to very little data (64KByte become 512 bytes). So check if any of your cores is pretty constantly at 100% load.

[Jon Schneider]

pretty cpu-intensive

That's the thing. It never uses much CPU. My windows box is more powerful, exports from one disk to another and yet is horrificly slow (compared do doing much the same on the Mac confined to one disk) at doing so.

[John M. Drescher]

In my case in bug #6506 the CPU usage was very minimal on my quad core intel q9550. The problem seemed to be that the writes were way too small and that they were getting flushed way to often.

[Klaus Espenlaub]

This should be more efficient with the 3.2.0 betas, if the true cause was the somewhat silly code we had to update the VMDK header. Locally we never managed to reproduce seriously bad performance, but that may have been just "luck".

From what I can tell there should be no flushes triggered by our code.

It's always just Windows which has issues with handling things with reasonable performance...

[Matthew A.]

Replying to klaus:

Keep in mind that the VMDK export part is pretty cpu-intensive...

As with the others, my CPU usage is very low. It actually dropped substantially as soon as the slowdown hit. Also, after I cancel the operation, the file continues to grow for a while before being deleted (from around 10 to 30 seconds), almost as if the IO is being cached or queued in some way.

[Chaim Krause]

I too am experiencing this. Even today with version 3.1.8 r61349. I am on 64-bit Win7 with dual Xeons (4 cores total) and 8GB RAM. I will try to spend some time monitoring what's going on as my work time permits.

[John M. Drescher]

I would try the current release. You are at least 2 versions behind.

[Chaim Krause]

Replying to drescherjm@gmail.com:

I would try the current release. You are at least 2 versions behind.

Doh! That made me realized that I downloaded the latest today but apparently never got around to installing it. Installing 3.2.4 now and will report back with findings.

[Chaim Krause]

No change with 3.2.4.

[Chaim Krause]

It appears that the cloning of the HDD is the issue. And when I monitor the process it seems to be reading in the cloned image over and over. In my case tens of thousand of times. The target file is created almost instantly, but is locked and the progress is reported as progressing with no change to the file during that time.

[Chaim Krause]

I find this interesting. I am just about to walk out the door at work, so I will get actual times tomorrow. But for now, try this yourself.

vboxmanage createhd --filename foo.vdi --size 102400 vboxmanage clonehd foo.vdi foo.vdmk --format vdmk --variant stream

and compare with

vboxmanage createhd --filename foo.vdi --size 1048576 vboxmanage clonehd foo.vdi foo.vdmk --format vdmk --variant stream

In both cases there is nothing on that disk, just metadata, but the time to copy is vastly greater in the latter case. My uneducated guess would be that these times should be similar since no actual data is being copied, just metadata.

[Chaim Krause]

Of course those were typos. Corrections with times.

vboxmanage createhd --filename foo.vdi --size 102400
time: < 3 seconds
vboxmanage clonehd foo.vdi foo.vmdk --format vmdk --variant stream
time: 2 minutes

vboxmanage createhd --filename foo.vdi --size 1024000
time: < 3 seconds
vboxmanage clonehd foo.vdi foo.vmdk --format vmdk --variant stream
time: 12.5 minutes

I mentioned this on IRC and klaus was able to reproduce (with even worse performance), so now the optimization of the code may begin.

[Sander van Leeuwen]

That should be fixed in 3.2.6 beta 1.

[Lyall Pearce]

Version 3.2.8 PUEL version on Linux x86 Gentoo - Linux kernel 2.6.34-gentoo-r1 using Intel Core2 Duo E6550 @ 2.33Ghz - 3G of memory.

Exporting a 7GB Gentoo Linux VM, still crawling at around 0.5MB / second.

Exporting onto the same physical disk and logical volume (XFS filesystem).

With no VM's running and the only thing really happening being the Export, no process is using more than 5% and Top reports nearly 50% wait time.

I wouldn't bother if compression was happening and the machine was CPU bound, but it's I/O bound, implying that something deeper is amiss.

[Jon Schneider]

I believe I've noticed that the VMDK file created is phenomenally fragmented. Is this the reason creating it is so slow ?

[Achim Hasenmueller]

How did you determine that the VMDK file is "phenomenally fragmented"? Have you tried with 3.2.8?

[Jon Schneider]

I first suspected fragmentation when copying to an external drive for external backup and my disk buzzed doing so.

After that I found that windows defragmenter reported that the VMDK was in many fragments.

I've (obviously) let the defragmenter do its stuff

ok just done another test. This is a half-full 1TB NTFS partition I use for backups, videos and the like. Large multi-gigabyte files on the whole that get written in one go. There's nothing interesting it does in the background and is indeed usually spun down such that it takes a second of two to get going again.

I've just done an export of a barely used FreeBSD install I did and run the "Analyze" thing of windows defragmenter. The other (less) fragmented file is one I transferred from our Reading server over SDSL and I did it in several restarted rsyncs. But look at the relative number of fragments. Also average file size (67MB) and explain why this happens time and time again. That's why I suspect something odd with the way the VMDK is written. === Volume Muffin (E:)

Volume size = 932 GB Cluster size = 4 KB Used space = 519 GB Free space = 413 GB Percent free space = 44 %

Volume fragmentation

Total fragmentation = 0 % File fragmentation = 0 % Free space fragmentation = 0 %

File fragmentation

Total files = 8,871 Average file size = 62 MB Total fragmented files = 4 Total excess fragments = 58,719 Average fragments per file = 7.61

Pagefile fragmentation

Pagefile size = 0 bytes Total fragments = 0

Folder fragmentation

Total folders = 1,175 Fragmented folders = 1 Excess folder fragments = 0

Master File Table (MFT) fragmentation

Total MFT size = 12 MB MFT record count = 10,426 Percent MFT in use = 83 % Total MFT fragments = 2

---

Fragments File Size Most fragmented files 58,678 969 MB \tmp\FreeBSD 8.vmdk 26 2.27 GB \backups\nc-dev-svr01-Thursday.tar.bz2 2 12 KB \tmp\FreeBSD 8.ovf

[Jon Schneider]

Also note

12k OVF file in two fragments itself quite a feat and I would not have thought possible on a 1TB filesystem.

Yes I'm running 3.2.8 .

Just transferred a 1GB file over and defragmenter tool reports (or rather doesn't report) any fragmentation for it.

How about somebody else do an export (sandwiched between a couple of slices of gigabyte files) and defragmenter Analyse

[aeichner]

This sounds more like a problem with your filesystem and/or disk setup. We can't do anything if the process is I/O bound because the export process is probably waiting for the write to complete before it can't continue. It would be probably a bug in our code if the export process uses 100% CPU and doesn't make any progess but that isn't the case here.

Regarding the fragmentation. The VMDK is written in 64k chunks which contain the compressed data and the .ovf file is written in one chunk. It is the task of the filesystem driver to the allocate space on the disk and we can't influence it if decides to fragment the file.

I can't see a VBox bug here so far.

[Jon Schneider]

I can't see a VBox bug here so far

except that OVF export is staggeringly slow in a way nobody can explain, I've offered some insight and proved that generally my filesystem does not fragment things like this.

I'm waiting for somebody else to do the test I suggest and prove me wrong.

[Lyall Pearce]

I/O binding includes Read and Write, not just write. I can copy the 7G file, in minutes. There is nothing wrong with the filesystem setup, I tried on a different filesystem that I had only formatted 4 hours before, same speed. It did finish exporting the 7G VM, down to 3.5G, but took about 3 hours. On a completely different Computer with Gentoo Installation, same speeds. Happy to run any diagnostic tools to identify disk reads/writes, just tell me what you want run.

[aeichner]

Just did a test trying to reproduce the problem. The source VM has a VDI image which uses 15GB on the disk. The virtual size of the disk is 50GB. The filesystem where the VDI is stored is ext3. I exported the VM to a ntfs formatted volume which is on the same physical disk as the ext3 volume so they have to share the available I/O bandwidth. The physical disk has a 4K physical sector size and the NTFS volume is a bit misaligned so performance isn't optimal. The host OS is Ubuntu 10.04 amd64 and I used the fuse ntfs driver to access the volume which means additional userspace/kernelspace rountrips influencing performance even more.

VBox exported the whole VM in ~19 minutes.

This includes converting the VDI to a stream optimized VMDK which involves compressing the whole data, and reading the VMDK again to create the checksum for the manifest. The resulting VMDK is 7.6GB big.

I monitored the I/O usage with iotop. Reading from the source VDI happend with 15-30MB/s and writing to the vmdk with 5-10MB/s.

I'll try to export few more VM with different filesystems as source and destination.

[Lyall Pearce]

Ran another test, on the Gentoo box. Output to an NTFS mounted disk (using ntfs3g version 2010.8.8) Screamed along at around 5MB/s (to me, 5M/s is screaming).

My conclusion, at least for me, is there is a problem with XFS interaction.

[aeichner]

It is indeed caused by the XFS filesystem. Created a fresh volume with XFS on it and exported the VM onto that volume. The export is running for 22 minutes now and is at 2% now.

[Jon Schneider]

I haven't checked but suspect a flush is happening explicitly or otherwise between writes.

NTFS (vanilla) and XFS are doing so and taking a rotation or two to effect. In my case above that's N x 58,678 x 8.3ms

ext[234] taking a riskier approach by default are only pretending it's done.

Can't speak for Fuse and others.

I suggest unixy people use strace and windowsy people procmon or similar during export to find out what is really going on. Unfortunately the original procmon screenshot didn't include writes.

[aeichner]

An excerpt fro the strace log:

4568  write(17, "\04\0\0\0\16\34\0", 12) = 12
4568  write(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
4568  write(17, "\2002\0\2172\0\0\0\0\0\2322\0\2422\0\2722\0\3032\0"..., 512) = 512
4568  write(17, "\2002\0\2172\0\0\0\0\0\2322\0\2422\0\2722\0\3032\0"..., 512) = 512
4568  write(17, "x^\355]\vtT\325\271\336\223\204d\230\4f\300\200\210\24\242\245\26\21\21\10Rh\324&\302\4"..., 6886) = 6886
4568  write(17, "\200\4\0\0\0346\32\0", 12) = 12
4568  write(17, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
4568  write(17, "\2002\0\2172\0\0\0\0\0\2322\0\2422\0\2722\0\3032\0"..., 512) = 512
4568  write(17, "\2002\0\2172\0\0\0\0\0\2322\0\2422\0\2722\0\3032\0"..., 512) = 512
4568  write(17, "x^\355\235kl\G\25\307\217\327N\3428\216\343:\217\346\325d\233\244i\310\303\2174!I\t"..., 3000) = 3000

As you can see there are mostly small writes to the file. I used a I/O benchmark and configured it to write only in 512 byte blocks but I still get around 16 MB/s there. Need to check which write calls is blocking most.

[Jon Schneider]

Slow VMDK write under XP

[Jon Schneider]

ok same sort of thing in my VMDK write attachment above.

Tiny writes of 512 bytes. Calls to SetEndOfFileInformationFile() why ? Calls to SetAllInformationFile() why ?

[aeichner]

The syscall causing the massive slowdown is ftruncate NTFS:

5675  ftruncate(17, 65396304)           = 0 <0.000063>

XFS:

5738  ftruncate(17, 10247409)           = 0 <0.027886>

[aeichner]

ftruncate is called here ​http://www.virtualbox.org/browser/trunk/src/VBox/Devices/Storage/VmdkHDDCore.cpp#L1023 just before the compressed data is written.

[aeichner]

We are currently testing a fix for this issue. Works nice so far, performance is much better for xfs now.

[aeichner]

Fixed in svn and will be shipped in the next maintenance release, Thanks for the report!

[Jon Schneider]

Sounds good thanks. May I ask whether the fixed version performs well on NTFS it being in somewhat greater use than XFS.

[Lyall Pearce]

Excellent news.
I gather no strace output is required?
I look forward to the next release where I can 'give it a bash'.

[Michael]

Confirmed fixed. My export times went from 1 hour to about 5 minutes. A BIG thank you from me! THANK YOU

[Lyall Pearce]

Also confirmed on Gentoo Linux, XFS filesystem.

[Frank Mehnert]

Thanks for the feedback!

[Andrew]

Am having the problem now.

XP Pro (SP2) on NTFS VBox 3.2.10 r66523

CPU usage stays down (apart from spikes - see attached procexp image), IO speed is low and most time appears to be spent reading the existing disk image (see attached procmon image)

[Andrew]

comment 46

[Andrew]

comment 64

[Andrew]

... while exporting

[Jon Schneider]

Notice how reads of about a megabyte are taking a second or so rather than 10-30ms as you'd expect on a modern device. Looks like a fragmentation or hardware problem or simply underlying load.

[Jon Schneider]

Further to that the very high durations don't add up. See also ​http://forum.sysinternals.com/procmon-duration-value-not-correct_topic24377.html

However the reads of 64k still look too slow to me.

[Andrew]

Replying to jms19:

Notice how reads of about a megabyte are taking a second or so rather than 10-30ms as you'd expect on a modern device. Looks like a fragmentation or hardware problem or simply underlying load.

New host install (~5 days old) so fragmentation out of the question, the system load is negligible and all other things on the system run fine (including the VM), so I'm reluctant to call it a hardware problem.

I wouldn't call the data that I've provided conclusive and I'm happy to capture anything else that might be of interest.

[Jon Schneider]

| New host install (~5 days old)

which could be read as unproven. Disk images do grow in a way that makes them fragment. That's a fact of life.

Your poor filesystem performance is there in black and white on the procmon screenshot. ReadFiles of 64kB are taking 0.1s.

Something isn't happy, already busy or there is fragmentation.

I'm guessing if you were to simply copy the vdi that would also take longer than it should.

[Andrew]

Aye, big file copy does take longer than it should.

Happy to chalk this up as a bogus environment for me. I've had a look at the fragmentation and run sysinternals contig on the VDI which took the fragments from 37 to 1, however this did not improve the export.

Thanks, A

[Tom Browder]

I'm using a Win 7 64-bit host with a Linux Ubuntu 64-bit guest and VirtualBox 4.0.10: it's still excruciatingly slow (using ova format).

[aeichner]

Please reopen if still relevant with a recent VirtualBox release.

[pengc99]

noticed the problem in 5.1.2r108956 on Windows 7 exporting a Windows 7 guest. 8+ hours to export a 60gb VM.

[pengc99]

Updated my installation to the latest available at the time of this report (5.1.4r110228) and I'm still experiencing this problem.

Initial export hangs for a very long time at 0% for about 10 minutes, then slowly crawls past 1% after that.

CPU usage is near zero (2x quad core X5365, 64GB RAM), disk activity near zero.

[aeichner]

Please attach the VBoxSVC.log after a failed export.

[Simon Coleman]

I also experience this issue, exporting 70gb windows vmdk with no snapshots. Vbox 5.1.6 r110634 (Qt5.5.1) on win7/64bit+ patches to early sept.

VM source is a reliable usb2 drive, target is reliable San storage mount over wired connection On starting ovf2 export for single file, 1.5Gb is quickly written to network Progress bar reaches stage 2/4 but remains at 0% After 30mins no data has been written for 15mins On cancelling (after another 15min of inactivity) the Cancel dialog reports as cancelling, but no activity still. Still in cancelling state 30mins later with no sign of progress or error. No data written to any log I can find. Final entry in the vboxsvc.log was: 00:00:26.650524 ApplWrit Loading settings file "c:\VM\virtualbox\dev-vm-sc-xp\dev-vm-sc-xp.vbox" with version "1.15-windows" But I think this is written before the export begins. The last entry in the machine log reports successful shutdown & removal of the UI. Any idea of where export logs are written? [nothing appears in windows syslog that I can see] A similar export of a linux vm from the same machine (2gb source file) runs ok, but was from the local HDD in 15min.

As the windows machine runs fine from the usb disk it should not fail to export. A previous export of a 2Gb linux machine (stored on local hdd, rather than usb though) exported ok

[Simon Coleman]

Now routed over a 1gb lan link the current estimate is 18 hours for 78Gb transfer, which is appalling...

Previous crash my bad - possibly caused by san traffic being routing over my wi fi card (although its normally very reliable but I think the data rate must have just been too slow)

Currently ResMon reports vbox reading the usb disk file at 15MB/sec.

It didn't take anywhere near that long to *write* this file to the usb disk when I copied it on & set the vm up a few weeks ago. [about an hour to write the file out] AFAIK the vmdk size is unchanged from then & haven't used the machine much. Do these files experience a lot of fragmentation after use? [I had assumed the files were roughly contiguous so any usage based fragmentation was internal to the VM]

[aeichner]

No activity for 3 years and there were quite some changes in the appliance import/export code. Please reopen if still an issue with a recent VirtualBox release.

[jmbreuer]

Just for the record / as a bisection point, I'm experiencing this exact issue (OVF export horribly slow - 40 minutes for a 35 GB VM) with VirtualBox 5.2.26 x64 on CentOS 7.6.1810.

Neither I/O nor any CPU core is used significantly during the export according to atop.

[Klaus Espenlaub]

Compressing 35GB of data does take a while, because it is done on a single thread. One CPU thread should be kept busy most of the time, but I wonder if something our code does makes it move between CPUs. With today's CPUs this can make the load quite hard to spot.

BTW, reporting data points for 5.2.26 won't get much attention. That build is over 2 years old and there were quite a few further updates before VirtualBox 5.x reached its end of life in July 2020.