VirtualBox

Ticket #9549 (closed defect: fixed)

Opened 3 years ago

Last modified 3 years ago

VirtualBox GUI Intermittently Hangs at Startup of Virtual Machine => Fixed in SVN

Reported by: arend Owned by:
Priority: major Component: GUI
Version: VirtualBox 4.0.12 Keywords: hang osx startup
Cc: arend@… Guest type: other
Host type: Mac OS X

Description

I am creating, configuring and running a virtual machine named mypocket7 from a script through VBoxManage. After the Virtual Machine is created with createvm the script attaches two immutable virtual hard drives in vmdk format to the created vm. The virtual hard drives are stored on a USB flash drive formatted with FAT32. The script also attaches a page volume vmdk from local disk and a DVD

VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 0 --device 0 --type hdd --mtype immutable --medium "/Volumes/MYPOCKET7/vm-images/usbcomp_7.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 0 --device 1 --type hdd --mtype immutable --medium "/Volumes/MYPOCKET7/vm-images/usbcomp_user.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 1 --device 0 --type hdd --medium "/tmp/vmusbcomp2736/pagefile_vol_vmware.vmdk"
VBoxManage storageattach MyPocket7 --storagectl "IDE Controller" --port 1 --device 1 --type dvddrive --medium host:'host:MATSHITA DVD-R   UJ-898' --passthrough on

The script then launches the vm. I have tried

VirtualBox" --startvm MyPocket7

and

VBoxManage" startvm MyPocket7

with the same result: The VirtualBox GUI 'hangs' intermittently at startup before a log file is created. While the 'hang' occurs intermittently, when it occurs OSX always reports the same stack trace for the VirtualBox/VBoxManage process. I have observed the hang with Snow Leopard as well as Lion and on both of the Macs I own (a Mac Mini and a Macbook).

The main VirtualBox/VBoxManage thread hangs at

                      17 Console::powerUp(IProgress**, bool) + 6109 (in VBoxC.dylib) [0x1052c6f1d]
                        17 SharedStub + 91 (in VBoxXPCOM.dylib) [0x1028c759b]
                          17 PrepareAndDispatch + 507 (in VBoxXPCOM.dylib) [0x1028c8368]
                            17 DConnectStub::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) + 1471 (in VBoxXPCOMIPCC.dylib) [0x102cbeefb]
                              17 IPC_WaitMessage(unsigned int, nsID const&, ipcIMessageObserver*, ipcIMessageObserver*, unsigned int) + 242 (in VBoxXPCOMIPCC.dylib) [0x102cb5cea]
                                17 _ZL10WaitTargetRK4nsIDjPP10ipcMessagePFjPvP13ipcTargetDataPKS2_ES5_ + 632 (in VBoxXPCOMIPCC.dylib) [0x102cb597c]

Within the same process a second thread that was spawned by the main thread and enumerates media waits as well

          17 VBoxGlobal::startEnumeratingMedia()::MediaEnumThread::run() + 444 (in VirtualBox.dylib) [0x10106f41c]
            17 VBoxMedium::blockAndQueryState() + 101 (in VirtualBox.dylib) [0x10102c405]
              17 CMedium::RefreshState() + 61 (in VirtualBox.dylib) [0x10122077d]
                17 SharedStub + 91 (in VBoxXPCOM.dylib) [0x1028c759b]
                  17 PrepareAndDispatch + 507 (in VBoxXPCOM.dylib) [0x1028c8368]
                    17 DConnectStub::CallMethod(unsigned short, nsXPTMethodInfo const*, nsXPTCMiniVariant*) + 1471 (in VBoxXPCOMIPCC.dylib) [0x102cbeefb]
                      17 IPC_WaitMessage(unsigned int, nsID const&, ipcIMessageObserver*, ipcIMessageObserver*, unsigned int) + 242 (in VBoxXPCOMIPCC.dylib) [0x102cb5cea]
                        17 _ZL10WaitTargetRK4nsIDjPP10ipcMessagePFjPvP13ipcTargetDataPKS2_ES5_ + 632 (in VBoxXPCOMIPCC.dylib) [0x102cb597c]

The complete stack trace generated after the OSX 'force quit' is attached.

I did a little homework looking at the relevant code sections and believe that there may be a race condition between two threads in the VirtualBox/VBoxManage process. There is one thread that enumerates the media list in startEnumerating media and there is a second thread that looks for immutable images to reset, which can probably not complete as the enumeration thread is still working. I wonder if this issue is only a problem when storing immutable drives on a USB flash drive resulting in a 'slower' device enumeration that conflicts with the powerUp call during which VirtualBox/VBoxManage looks for immutable images to reset.

        if (!fCurrentSnapshotIsOnline)
        {
            LogFlowThisFunc(("Looking for immutable images to reset\n"));

            com::SafeIfaceArray<IMediumAttachment> atts;
            rc = mMachine->COMGETTER(MediumAttachments)(ComSafeArrayAsOutParam(atts));
... 

Attachments

trace_vbx_startup_hang.rtf Download (9.3 KB) - added by arend 3 years ago.
Stack Trace VirtualBox
pagefile_vol_vmware.vmdk Download (924 bytes) - added by arend 3 years ago.
usbcomp_user.vmdk Download (890 bytes) - added by arend 3 years ago.
usbcomp_7.vmdk Download (1.2 KB) - added by arend 3 years ago.
Sample of VBoxSVC.txt Download (43.9 KB) - added by arend 3 years ago.
create-launch_vm_vbox.bash Download (1.9 KB) - added by arend 3 years ago.
This is the complete create and launch script.
create-launch_vm_vbox_log Download (2.8 KB) - added by arend 3 years ago.
Logfile of create and launch script.

Change History

Changed 3 years ago by arend

Stack Trace VirtualBox

comment:1 follow-up: ↓ 2 Changed 3 years ago by poetzsch

Can you attach the content of "Sample Process" in the Activity Manager of the process VBoxSVC when this hangs happens?

The pagefile vmdk is just a normal vmdk, right?

Changed 3 years ago by arend

comment:2 in reply to: ↑ 1 Changed 3 years ago by arend

Replying to poetzsch:

Can you attach the content of "Sample Process" in the Activity Manager of the process VBoxSVC when this hangs happens?

The pagefile vmdk is just a normal vmdk, right?

Thank you very for looking into this right away. Yes, the pagefile is a regular vmdk that is dynamically growing and split into multiple extents. I am attaching the descriptor for your reference.

I will try to reproduce again. You are referring to the 'Activity Monitor', right?

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

Yes the "Activity Monitor", sorry.

Can you also give a little bit more info on the other disks. How big they are, virtually and in reality. Are they also splitted? Maybe you could also check what happens when the disks are not immutable.

I tried with an external usb disk as well, but couldn't reproduce it so far.

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

Replying to poetzsch:

Yes the "Activity Monitor", sorry.

Can you also give a little bit more info on the other disks. How big they are, virtually and in reality. Are they also splitted? Maybe you could also check what happens when the disks are not immutable.

I tried with an external usb disk as well, but couldn't reproduce it so far.

I just reproduced again. Just as a side note ... I have seen the issue when staring with VBoxManage as well as with VirtualBox but it seems to me that the probability of the error occurring is much higher when starting with 'VBoxManage startvm'. I am attaching the sample of VBoxSvc.

The other drives are also vmdks, that are split and preallocated. usbcomp_7 is 24GB and usbcomp_user is 5GB. I am also attaching their descriptors. The ls output of the directory where the images are located below:

-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:50 usbcomp_7-f001.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f002.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f003.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:36 usbcomp_7-f004.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:38 usbcomp_7-f005.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:41 usbcomp_7-f006.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:51 usbcomp_7-f007.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:46 usbcomp_7-f008.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:48 usbcomp_7-f009.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:50 usbcomp_7-f010.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:53 usbcomp_7-f011.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  5 23:55 usbcomp_7-f012.vmdk
-rwxrwxrwx  1 adittmer  staff     3145728 Jul  5 23:55 usbcomp_7-f013.vmdk
-rwxrwxrwx  1 adittmer  staff        1279 Jul  6 19:21 usbcomp_7.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Aug 28 17:50 usbcomp_user-f001.vmdk
-rwxrwxrwx  1 adittmer  staff  2147221504 Jul  6 00:01 usbcomp_user-f002.vmdk
-rwxrwxrwx  1 adittmer  staff  1074266112 Aug 28 17:50 usbcomp_user-f003.vmdk
-rwxrwxrwx  1 adittmer  staff         890 Jul  6 19:22 usbcomp_user.vmdk

Changed 3 years ago by arend

Changed 3 years ago by arend

Changed 3 years ago by arend

Changed 3 years ago by arend

This is the complete create and launch script.

Changed 3 years ago by arend

Logfile of create and launch script.

comment:5 follow-ups: ↓ 6 ↓ 7 ↓ 8 Changed 3 years ago by poetzsch

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

comment:6 in reply to: ↑ 5 Changed 3 years ago by arend

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

Thank you very much. I really appreciate you looking into this. You probably already saw this indication of an unreleased lock in the sample.

    +                     2674 Medium::RefreshState(unsigned int*)  (in VBoxSVC) + 332  [0x1000e56fc]
    +                       2674 Medium::queryInfo(bool, bool)  (in VBoxSVC) + 1290  [0x1000e3b6a]
    +                         2674 util::AutoLockBase::acquire()  (in VBoxSVC) + 17  [0x1001d5471]
    +                           2674 util::AutoLockBase::callLockOnAllHandles()  (in VBoxSVC) + 50  [0x1001d52f2]
    +                             2674 RTSemRWRequestRead  (in VBoxRT.dylib) + 355  [0x1003f1463]
    +                               2674 _ZL34rtSemEventMultiPosixWaitIndefiniteP23RTSEMEVENTMULTIINTERNALjPK15RTLOCKVALSRCPOS  (in VBoxRT.dylib) + 101  [0x1003833e5]

If it helps with reproducing the issue I am more than happy to send you a USB drive. Just let me know.

comment:7 in reply to: ↑ 5 Changed 3 years ago by arend

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

To your earlier question ... as the issue is intermittent it is of course hard to say for sure .... but it looks like this is not an issue with drives attached as normal drives ('non-immutable')

comment:8 in reply to: ↑ 5 Changed 3 years ago by arend

Replying to poetzsch:

Thanks for the info. When I look at the bt your assumption seems to be right. Anyway, I have to reproduce this which will need some time.

Looked a little bit further into this. I found that not having the 'capture hint' that needs to be OK'ed pop up makes it much more likely that the error condition will occur. So the highest probability for the hang to occur is when starting the VM with 'VBoxManage startvm' and suppressing the initial capture window with "$VMM_PATH/VBoxManage" setextradata global GUI/SuppressMessages ,confirmInputCapture,remindAboutAutoCapture". With these changes and my current setup I can reproduce the issue with almost all startup attempts.

I added a few lines of code to the constructor of UIMachine in VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp that synchronize the media enumeration thread. I have not been able to reproduce the issue after incorporating these changes. When swapping out the binaries with the originals the issue appears again.

--- 392,399 ----
bash-3.2$ diff --context=4 /Users/adittmer/VBOX_4.X/fix/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp /Users/adittmer/VBOX_4.X/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp
*** /Users/adittmer/VBOX_4.X/fix/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp  2011-07-15 08:33:53.000000000 -0700
--- /Users/adittmer/VBOX_4.X/VirtualBox-4.0.12_OSE/src/VBox/Frontends/VirtualBox/src/runtime/UIMachine.cpp      2011-09-04 16:05:02.000000000 -0700
***************
*** 392,399 ****
--- 392,404 ----
  
      /* Cache IMedium data: */
      vboxGlobal().startEnumeratingMedia();
  
+     /* Make sure asynchronous enum thread has finished before proceeding */
+     QEventLoop wait_for_enum_complete;
+     connect (&vboxGlobal(), SIGNAL (mediumEnumFinished (const VBoxMediaList &)), &wait_for_enum_complete, SLOT(quit()));
+     wait_for_enum_complete.exec();
+ 
      /* Storing self: */
      if (m_ppThis)
          *m_ppThis = this;

comment:9 Changed 3 years ago by poetzsch

I think I fixed it. Can you give  this test build a try?

comment:10 Changed 3 years ago by arend

Thank you very much. My initial tests indicate that you fixed the problem.

comment:11 Changed 3 years ago by arend

Will this fix be in 4.1.4?

comment:12 Changed 3 years ago by frank

  • Summary changed from VirtualBox GUI Intermittently Hangs at Startup of Virtual Machine to VirtualBox GUI Intermittently Hangs at Startup of Virtual Machine => Fixed in SVN

Yes, 4.1.4 will include this fix.

comment:13 Changed 3 years ago by frank

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

And 4.1.4 was finally released today.

Note: See TracTickets for help on using tickets.

www.oracle.com
ContactPrivacy policyTerms of Use