VirtualBox

Opened 16 years ago

Closed 5 years ago

Last modified 4 years ago

#3719 closed defect (obsolete)

Very slow OVF import/export -> fixed in SVN

Reported by: DevOne Owned by:
Component: OVF Version: VirtualBox 3.1.6
Keywords: Cc:
Guest type: other Host type: other

Description (last modified by aeichner)

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.

Attachments (4)

disk accesses.png (146.1 KB ) - added by DevOne 16 years ago.
Disk accesses
VMDK write.png (86.3 KB ) - added by Jon Schneider 14 years ago.
Slow VMDK write under XP
procmon_comment46.PNG (154.3 KB ) - added by Andrew 14 years ago.
comment 46
procexp_comment46.PNG (22.2 KB ) - added by Andrew 14 years ago.
comment 64

Download all attachments as: .zip

Change History (66)

by DevOne, 16 years ago

Attachment: disk accesses.png added

Disk accesses

comment:1 by Technologov, 15 years ago

Looks interesting. Adding myself :)

-Technologov

comment:2 by Frank Mehnert, 15 years ago

Component: otherOVF
Resolution: fixed
Status: newclosed

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

comment:3 by Jon Schneider, 15 years ago

Resolution: fixed
Status: closedreopened

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.

in reply to:  3 comment:4 by Carl-Erik Kopseng, 15 years ago

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).

comment:5 by Lyall Pearce, 15 years ago

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

comment:6 by Matthew A., 14 years ago

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.

comment:7 by Sander van Leeuwen, 14 years ago

Version: VirtualBox 2.2.0VirtualBox 3.1.6

#6506 marked as a duplicate.

comment:8 by Klaus Espenlaub, 14 years ago

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.

comment:9 by Jon Schneider, 14 years ago

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.

comment:10 by John M. Drescher, 14 years ago

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.

comment:11 by Klaus Espenlaub, 14 years ago

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...

in reply to:  8 comment:12 by Matthew A., 14 years ago

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.

comment:13 by Chaim Krause, 14 years ago

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.

comment:14 by John M. Drescher, 14 years ago

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

in reply to:  14 comment:15 by Chaim Krause, 14 years ago

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.

comment:16 by Chaim Krause, 14 years ago

No change with 3.2.4.

comment:17 by Chaim Krause, 14 years ago

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.

comment:18 by Chaim Krause, 14 years ago

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.

in reply to:  18 comment:19 by Chaim Krause, 14 years ago

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.

comment:20 by Sander van Leeuwen, 14 years ago

Summary: Very slow OVF import/exportVery slow OVF import/export -> fixed in SVN

That should be fixed in 3.2.6 beta 1.

comment:21 by umoeller, 14 years ago

Resolution: fixed
Status: reopenedclosed

comment:22 by Lyall Pearce, 14 years ago

Resolution: fixed
Status: closedreopened

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.

comment:23 by Jon Schneider, 14 years ago

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

comment:24 by Achim Hasenmueller, 14 years ago

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

comment:25 by Jon Schneider, 14 years ago

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

comment:26 by Jon Schneider, 14 years ago

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

comment:27 by aeichner, 14 years ago

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.

comment:28 by Jon Schneider, 14 years ago

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.

comment:29 by Lyall Pearce, 14 years ago

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.

comment:30 by aeichner, 14 years ago

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.

comment:31 by Lyall Pearce, 14 years ago

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.

comment:32 by aeichner, 14 years ago

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.

comment:33 by Jon Schneider, 14 years ago

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.

comment:34 by aeichner, 14 years ago

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.

by Jon Schneider, 14 years ago

Attachment: VMDK write.png added

Slow VMDK write under XP

comment:35 by Jon Schneider, 14 years ago

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

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

comment:36 by aeichner, 14 years ago

The syscall causing the massive slowdown is ftruncate NTFS:

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

XFS:

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

comment:37 by aeichner, 14 years ago

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

comment:38 by aeichner, 14 years ago

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

comment:39 by aeichner, 14 years ago

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

comment:40 by Jon Schneider, 14 years ago

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

comment:41 by Lyall Pearce, 14 years ago

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

comment:42 by Sander van Leeuwen, 14 years ago

Resolution: fixed
Status: reopenedclosed

comment:43 by Michael, 14 years ago

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

comment:44 by Lyall Pearce, 14 years ago

Also confirmed on Gentoo Linux, XFS filesystem.

comment:45 by Frank Mehnert, 14 years ago

Thanks for the feedback!

comment:46 by Andrew, 14 years ago

Resolution: fixed
Status: closedreopened

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)

by Andrew, 14 years ago

Attachment: procmon_comment46.PNG added

comment 46

by Andrew, 14 years ago

Attachment: procexp_comment46.PNG added

comment 64

in reply to:  46 comment:47 by Andrew, 14 years ago

... while exporting

comment:48 by Jon Schneider, 14 years ago

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.

comment:49 by Jon Schneider, 14 years ago

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.

in reply to:  48 comment:50 by Andrew, 14 years ago

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.

comment:51 by Jon Schneider, 14 years ago

| 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.

in reply to:  51 comment:52 by Andrew, 14 years ago

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

comment:53 by Tom Browder, 13 years ago

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).

comment:54 by aeichner, 8 years ago

Description: modified (diff)
Resolution: obsolete
Status: reopenedclosed

Please reopen if still relevant with a recent VirtualBox release.

comment:55 by pengc99, 8 years ago

Resolution: obsolete
Status: closedreopened

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

comment:56 by pengc99, 8 years ago

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.

comment:57 by aeichner, 8 years ago

Please attach the VBoxSVC.log after a failed export.

comment:58 by Simon Coleman, 8 years ago

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

comment:59 by Simon Coleman, 8 years ago

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]

comment:60 by aeichner, 5 years ago

Resolution: obsolete
Status: reopenedclosed

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.

comment:61 by jmbreuer, 4 years ago

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.

comment:62 by Klaus Espenlaub, 4 years ago

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.

Note: See TracTickets for help on using tickets.

© 2024 Oracle Support Privacy / Do Not Sell My Info Terms of Use Trademark Policy Automated Access Etiquette