VirtualBox

Ticket #3719 (reopened defect)

Opened 5 years ago

Last modified 3 years ago

Very slow OVF import/export -> fixed in SVN

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

Description

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

disk accesses.png Download (146.1 KB) - added by DevOne 5 years ago.
Disk accesses
VMDK write.png Download (86.3 KB) - added by jms19 4 years ago.
Slow VMDK write under XP
procmon_comment46.PNG Download (154.3 KB) - added by andrewsharpe79 3 years ago.
comment 46
procexp_comment46.PNG Download (22.2 KB) - added by andrewsharpe79 3 years ago.
comment 64

Change History

Changed 5 years ago by DevOne

Disk accesses

comment:1 Changed 5 years ago by Technologov

Looks interesting. Adding myself :)

-Technologov

comment:2 Changed 5 years ago by frank

  • Status changed from new to closed
  • Resolution set to fixed
  • Component changed from other to OVF

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

comment:3 follow-up: ↓ 4 Changed 5 years ago by jms19

  • Status changed from closed to reopened
  • Resolution fixed deleted

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.

comment:4 in reply to: ↑ 3 Changed 4 years ago by fatso

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 Changed 4 years ago by lyallp

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 Changed 4 years ago by TDMedia

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 Changed 4 years ago by sandervl73

  • Version changed from VirtualBox 2.2.0 to VirtualBox 3.1.6

#6506 marked as a duplicate.

comment:8 follow-up: ↓ 12 Changed 4 years ago by klaus

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 Changed 4 years ago by jms19

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 Changed 4 years ago by drescherjm@…

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 Changed 4 years ago by klaus

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

comment:12 in reply to: ↑ 8 Changed 4 years ago by TDMedia

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 Changed 4 years ago by tinjaw

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 follow-up: ↓ 15 Changed 4 years ago by drescherjm@…

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

comment:15 in reply to: ↑ 14 Changed 4 years ago by tinjaw

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 Changed 4 years ago by tinjaw

No change with 3.2.4.

comment:17 Changed 4 years ago by tinjaw

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 follow-up: ↓ 19 Changed 4 years ago by tinjaw

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.

comment:19 in reply to: ↑ 18 Changed 4 years ago by tinjaw

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 Changed 4 years ago by sandervl73

  • Summary changed from Very slow OVF import/export to Very slow OVF import/export -> fixed in SVN

That should be fixed in 3.2.6 beta 1.

comment:21 Changed 4 years ago by umoeller

  • Status changed from reopened to closed
  • Resolution set to fixed

comment:22 Changed 4 years ago by lyallp

  • Status changed from closed to reopened
  • Resolution fixed deleted

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 Changed 4 years ago by jms19

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

comment:24 Changed 4 years ago by achimha

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

comment:25 Changed 4 years ago by jms19

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 Changed 4 years ago by jms19

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 Changed 4 years ago by 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.

comment:28 Changed 4 years ago by jms19

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 Changed 4 years ago by lyallp

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 Changed 4 years ago by 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.

comment:31 Changed 4 years ago by lyallp

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 Changed 4 years ago by 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.

comment:33 Changed 4 years ago by jms19

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 Changed 4 years ago by 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.

Changed 4 years ago by jms19

Slow VMDK write under XP

comment:35 Changed 4 years ago by jms19

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 Changed 4 years ago by 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>

comment:37 Changed 4 years ago by 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.

comment:38 Changed 4 years ago by aeichner

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

comment:39 Changed 4 years ago by aeichner

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

comment:40 Changed 4 years ago by jms19

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

comment:41 Changed 4 years ago by lyallp

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 Changed 4 years ago by sandervl73

  • Status changed from reopened to closed
  • Resolution set to fixed

comment:43 Changed 3 years ago by mooninite

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

comment:44 Changed 3 years ago by lyallp

Also confirmed on Gentoo Linux, XFS filesystem.

comment:45 Changed 3 years ago by frank

Thanks for the feedback!

comment:46 follow-up: ↓ 47 Changed 3 years ago by andrewsharpe79

  • Status changed from closed to reopened
  • Resolution fixed deleted

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)

Changed 3 years ago by andrewsharpe79

comment 46

Changed 3 years ago by andrewsharpe79

comment 64

comment:47 in reply to: ↑ 46 Changed 3 years ago by andrewsharpe79

... while exporting

comment:48 follow-up: ↓ 50 Changed 3 years ago by 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.

comment:49 Changed 3 years ago by jms19

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.

comment:50 in reply to: ↑ 48 Changed 3 years ago by andrewsharpe79

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 follow-up: ↓ 52 Changed 3 years ago by jms19

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

comment:52 in reply to: ↑ 51 Changed 3 years ago by andrewsharpe79

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 Changed 3 years ago by tbrowder

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

Note: See TracTickets for help on using tickets.

www.oracle.com
ContactPrivacy policyTerms of Use