VirtualBox

Opened 13 years ago

Closed 12 years ago

#9549 closed defect (fixed)

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

Reported by: Arend Dittmer Owned by:
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 (7)

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

Download all attachments as: .zip

Change History (20)

by Arend Dittmer, 13 years ago

Attachment: trace_vbx_startup_hang.rtf added

Stack Trace VirtualBox

comment:1 by Christian Pötzsch, 13 years ago

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?

by Arend Dittmer, 13 years ago

Attachment: pagefile_vol_vmware.vmdk added

in reply to:  1 comment:2 by Arend Dittmer, 13 years ago

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 by Christian Pötzsch, 13 years ago

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.

in reply to:  3 comment:4 by Arend Dittmer, 13 years ago

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

by Arend Dittmer, 13 years ago

Attachment: usbcomp_user.vmdk added

by Arend Dittmer, 13 years ago

Attachment: usbcomp_7.vmdk added

by Arend Dittmer, 13 years ago

Attachment: Sample of VBoxSVC.txt added

by Arend Dittmer, 13 years ago

Attachment: create-launch_vm_vbox.bash added

This is the complete create and launch script.

by Arend Dittmer, 13 years ago

Attachment: create-launch_vm_vbox_log added

Logfile of create and launch script.

comment:5 by Christian Pötzsch, 13 years ago

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.

in reply to:  5 comment:6 by Arend Dittmer, 13 years ago

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.

in reply to:  5 comment:7 by Arend Dittmer, 13 years ago

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

in reply to:  5 comment:8 by Arend Dittmer, 13 years ago

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 by Christian Pötzsch, 13 years ago

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

comment:10 by Arend Dittmer, 13 years ago

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

comment:11 by Arend Dittmer, 13 years ago

Will this fix be in 4.1.4?

comment:12 by Frank Mehnert, 13 years ago

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

Yes, 4.1.4 will include this fix.

comment:13 by Frank Mehnert, 12 years ago

Resolution: fixed
Status: newclosed

And 4.1.4 was finally released today.

Note: See TracTickets for help on using tickets.

© 2023 Oracle
ContactPrivacy policyTerms of Use