[vbox-dev] disk I/O crashes of FreeBSD 9.1-P7 guest on Mac OS X 10.8.5 host

[Axel Rau]

Thanks for your reply, Klaus,

Am 23.09.2013 um 12:08 schrieb Klaus Espenlaub <klaus.espenlaub at oracle.com>:

> Hi Axel,
> 
> On 22.09.2013 13:38, Axel Rau wrote:
>> Hi,
>> 
>> This VM exists 6 month now and worked perfect.
>> Recently I upgraded the host from 10.8.4 to 10.8.5.
>> Today, I started the VM after a break of 2 month after upgrading VBox to 4.2.18r88780.
>> After that, I updated freebsd 9.1 to 9.1-P7 using freebsd-update.
>> Everything worked perfect so far.
>> Then I did a portsnap fetch and a portsnap update, which froze the VM immediately (lots of directories/file had to be removed).
>> After a few seconds the VM started rebooting but was unable to find the root disk (a SATA drive), until I powered down and restarted.
>> This was reproducible.
>> After that I switched the disks to a IDE controller: Same crash on portsnap update. Only difference: It completed its reboot.
> 
> Sounds like the host is not able to handle the I/O within the timeout 
> imposed by the guest OS. OSX is known for bad I/O performance, it is 
> easily overloaded, resulting in unbearable response time for I/O 
> requests (we've seen a 64K write request taking 3 minutes, and there are 
> probably worse situations). There is very little VirtualBox can do about 
> this.
Hmm, show me an OS which could not be slowed down like this, i.e. changing metadata in a big directory tree…
This machine has 12GB of RAM, mostly everything in its buffer cache and disk I/O is almost idle.
> 
>> Nothing interesting in the logs.
> 
> Which logs? Host (normal OSX logging and VBox.log) and guest logs?
Nothing related in all 3. I include the VBox.log from one crash/reboot:
---
00:46:02.079956 Reset initiated by ACPI
00:46:02.079990 Changing the VM state from 'RUNNING' to 'RESETTING'.
00:46:02.111833 CPUMSetGuestCpuIdFeature: Enabled APIC
00:46:02.111858 CPUMClearGuestCpuIdFeature: Disabled x2APIC
00:46:02.111868 PIT: mode=3 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:46:02.114523 AHCI#0: Reset the HBA
00:46:02.114593 Audio: set_record_source ars=0 als=0 (not implemented)
00:46:02.114639 PIIX3 ATA: Ctl#1: finished processing RESET
00:46:02.114662 PDMR3Reset: after     2 ms, 1 loops: 1 async tasks - piix3ide/0
00:46:02.114679 PIIX3 ATA: Ctl#0: finished processing RESET
00:46:02.114770 Changing the VM state from 'RESETTING' to 'RUNNING'.
00:46:02.117474 Guest Log: BIOS: VirtualBox 4.2.18
00:46:02.117564 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:46:02.128446 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 CmdIf0=0xe7 (-1 usec ago) CmdIf1=0xe7 (-1 usec ago)
00:46:02.128546 PIIX3 ATA: Ctl#0: finished processing RESET
00:46:02.128848 Guest Log: BIOS: ata0-0: PCHS=16383/16/63 LCHS=1024/255/63
00:46:02.129411 PIIX3 ATA: Ctl#0: RESET, DevSel=1 AIOIf=0 CmdIf0=0xec (-1 usec ago) CmdIf1=0xe7 (-1 usec ago)
00:46:02.129432 PIIX3 ATA: Ctl#0: finished processing RESET
00:46:02.129711 Guest Log: BIOS: ata0-1: PCHS=16383/16/63 LCHS=1024/255/63
00:46:02.135809 AHCI#0: Reset the HBA
00:46:02.136015 AHCI#0: Port 2 reset
00:46:02.136197 PIT: mode=2 count=0x48d3 (18643) - 64.00 Hz (ch=0)
00:46:02.137067 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=00000001142fd000 w=640 h=480 bpp=32 cbLine=0xA00, flags=0x1
00:46:04.611390 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:46:04.611579 Guest Log: BIOS: Boot : bseqnr=1, bootseq=0231
00:46:04.611714 Guest Log: BIOS: Boot from Floppy 0 failed
00:46:04.611870 Guest Log: BIOS: Boot : bseqnr=2, bootseq=0023
00:46:04.612456 Guest Log: BIOS: CDROM boot failure code : 0003
00:46:04.612577 Guest Log: BIOS: Boot from CD-ROM failed
00:46:04.612728 Guest Log: BIOS: Boot : bseqnr=3, bootseq=0002
00:46:04.612927 Guest Log: BIOS: Booting from Hard Disk...
00:46:04.618205 Display::handleDisplayResize(): uScreenId = 0, pvVRAM=0000000000000000 w=720 h=400 bpp=0 cbLine=0x0, flags=0x1
00:46:18.039745 PIT: mode=2 count=0x10000 (65536) - 18.20 Hz (ch=0)
00:46:21.349620 Audio: set_record_source ars=0 als=0 (not implemented)
00:46:21.357079 Audio: set_record_source ars=0 als=0 (not implemented)
00:46:21.481979 OHCI: USB Reset
00:46:21.592076 OHCI: Software reset
00:46:21.592151 OHCI: USB Operational
00:46:21.680332 AHCI#0: Reset the HBA
00:46:24.317664 PIIX3 ATA: Ctl#0: RESET, DevSel=0 AIOIf=0 CmdIf0=0xc4 (-1 usec ago) CmdIf1=0xec (-1 usec ago)
00:46:24.327768 PIIX3 ATA: Ctl#0: finished processing RESET
00:46:24.452119 AHCI#0: Port 2 reset
---
and the freebsd dmesg:
---
FreeBSD 9.1-RELEASE-p7 (GENERIC) #0: Mon Sep  9 21:34:37 UTC 2013

vm on Axels-Macpro
root at vm-fbsd:/root # dmesg
Copyright (c) 1992-2012 The FreeBSD Project.
Copyright (c) 1979, 1980, 1983, 1986, 1988, 1989, 1991, 1992, 1993, 1994
	The Regents of the University of California. All rights reserved.
FreeBSD is a registered trademark of The FreeBSD Foundation.
FreeBSD 9.1-RELEASE-p7 #0: Mon Sep  9 21:34:37 UTC 2013
    root at amd64-builder.daemonology.net:/usr/obj/usr/src/sys/GENERIC amd64
CPU: Intel(R) Xeon(R) CPU           W3680  @ 3.33GHz (3330.93-MHz K8-class CPU)
  Origin = "GenuineIntel"  Id = 0x206c2  Family = 6  Model = 2c  Stepping = 2
  Features=0x1783fbff<FPU,VME,DE,PSE,TSC,MSR,PAE,MCE,CX8,APIC,SEP,MTRR,PGE,MCA,CMOV,PAT,PSE36,MMX,FXSR,SSE,SSE2,HTT>
  Features2=0x201<SSE3,SSSE3>
  AMD Features=0x28100800<SYSCALL,NX,RDTSCP,LM>
  AMD Features2=0x1<LAHF>
real memory  = 4905238528 (4678 MB)
avail memory = 4172632064 (3979 MB)
Event timer "LAPIC" quality 400
ACPI APIC Table: <VBOX   VBOXAPIC>
FreeBSD/SMP: Multiprocessor System Detected: 2 CPUs
FreeBSD/SMP: 1 package(s) x 2 core(s)
 cpu0 (BSP): APIC ID:  0
 cpu1 (AP): APIC ID:  1
ioapic0 <Version 1.1> irqs 0-23 on motherboard
kbd1 at kbdmux0
acpi0: <VBOX VBOXXSDT> on motherboard
acpi0: Power Button (fixed)
acpi0: Sleep Button (fixed)
cpu0: <ACPI CPU> on acpi0
cpu1: <ACPI CPU> on acpi0
attimer0: <AT timer> port 0x40-0x43,0x50-0x53 on acpi0
Timecounter "i8254" frequency 1193182 Hz quality 0
Event timer "i8254" frequency 1193182 Hz quality 100
Timecounter "ACPI-fast" frequency 3579545 Hz quality 900
acpi_timer0: <32-bit timer at 3.579545MHz> port 0x4008-0x400b on acpi0
pcib0: <ACPI Host-PCI bridge> port 0xcf8-0xcff on acpi0
pci0: <ACPI PCI bus> on pcib0
isab0: <PCI-ISA bridge> at device 1.0 on pci0
isa0: <ISA bus> on isab0
atapci0: <Intel PIIX4 UDMA33 controller> port 0x1f0-0x1f7,0x3f6,0x170-0x177,0x376,0xd000-0xd00f at device 1.1 on pci0
ata0: <ATA channel> at channel 0 on atapci0
ata1: <ATA channel> at channel 1 on atapci0
vgapci0: <VGA-compatible display> mem 0xe0000000-0xe1ffffff irq 18 at device 2.0 on pci0
em0: <Intel(R) PRO/1000 Legacy Network Connection 1.0.4> port 0xd010-0xd017 mem 0xf0000000-0xf001ffff irq 19 at device 3.0 on pci0
em0: Ethernet address: 08:00:27:58:46:a2
pci0: <base peripheral> at device 4.0 (no driver attached)
pcm0: <Intel ICH (82801AA)> port 0xd100-0xd1ff,0xd200-0xd23f irq 21 at device 5.0 on pci0
pcm0: <SigmaTel STAC9700/83/84 AC97 Codec>
ohci0: <OHCI (generic) USB controller> mem 0xf0804000-0xf0804fff irq 22 at device 6.0 on pci0
usbus0 on ohci0
pci0: <bridge> at device 7.0 (no driver attached)
ahci0: <Intel ICH8M AHCI SATA controller> port 0xd240-0xd247,0xd250-0xd257,0xd260-0xd26f mem 0xf0806000-0xf0807fff irq 21 at device 13.0 on pci0
ahci0: AHCI v1.10 with 3 3Gbps ports, Port Multiplier not supported
ahcich0: <AHCI channel> at channel 0 on ahci0
ahcich1: <AHCI channel> at channel 1 on ahci0
ahcich2: <AHCI channel> at channel 2 on ahci0
acpi_acad0: <AC Adapter> on acpi0
atkbdc0: <Keyboard controller (i8042)> port 0x60,0x64 irq 1 on acpi0
atkbd0: <AT Keyboard> irq 1 on atkbdc0
kbd0 at atkbd0
atkbd0: [GIANT-LOCKED]
psm0: <PS/2 Mouse> irq 12 on atkbdc0
psm0: [GIANT-LOCKED]
psm0: model IntelliMouse Explorer, device ID 4
qpi0: <QPI system bus> on motherboard
orm0: <ISA Option ROMs> at iomem 0xc0000-0xc7fff,0xe2000-0xe6fff on isa0
sc0: <System console> at flags 0x100 on isa0
sc0: VGA <16 virtual consoles, flags=0x300>
vga0: <Generic ISA VGA> at port 0x3c0-0x3df iomem 0xa0000-0xbffff on isa0
atrtc0: <AT realtime clock> at port 0x70 irq 8 on isa0
Event timer "RTC" frequency 32768 Hz quality 0
ppc0: cannot reserve I/O port range
ctl: CAM Target Layer loaded
Timecounters tick every 10.000 msec
pcm0: measured ac97 link rate at 39279 Hz
usbus0: 12Mbps Full Speed USB v1.0
ugen0.1: <Apple> at usbus0
uhub0: <Apple OHCI root HUB, class 9/0, rev 1.00/1.00, addr 1> on usbus0
uhub0: 8 ports with 8 removable, self powered
cd0 at ahcich2 bus 0 scbus4 target 0 lun 0
cd0: <VBOX CD-ROM 1.0> Removable CD-ROM SCSI-0 device 
cd0: 300.000MB/s transfers (SATA 2.x, UDMA6, ATAPI 12bytes, PIO 8192bytes)
cd0: Attempt to query device size failed: NOT READY, Medium not present
ada0 at ata0 bus 0 scbus0 target 0 lun 0
ada0: <VBOX HARDDISK 1.0> ATA-6 device
ada0: 33.300MB/s transfers (UDMA2, PIO 65536bytes)
ada0: 30720MB (62914560 512 byte sectors: 16H 63S/T 16383C)
ada0: Previously was known as ad0
ada1 at ata0 bus 0 scbus0 target 1 lun 0
ada1: <VBOX HARDDISK 1.0> ATA-6 device
ada1: 33.300MB/s transfers (UDMA2, PIO 65536bytes)
ada1: 102400MB (209715200 512 byte sectors: 16H 63S/T 16383C)
ada1: Previously was known as ad1
SMP: AP CPU #1 Launched!
Trying to mount root from ufs:/dev/ada0p2 [rw]...
WARNING: / was not properly dismounted
WARNING: /disk1 was not properly dismounted

--- 
> 
>> This is a 6-core Xeon, 2 cores dedicated to the VM.
> 
> Sounds unlikely that you have dedicated cores for the VM... guess you 
> simply set the VCPU count to 2.
Yes (-;.
> 
>> Questions: Has this combination of host/guest OS versions been tested?
> 
> Probably not - there is a near infinite number of combinations, and you 
> use a quite unusual one.
> 
>> What can I do to further help finding the cause?
> 
> Clarifying which log looks normal would provide a starting point.

Axel
---
PGP-Key:29E99DD6  ☀ +49 151 2300 9283  ☀ computing @ chaos claudius