VBoxManage hangs after calling futex(..., FUTEX_WAIT_PRIVATE, ...)

[Petar Bogdanovic]

Hi,

since I upgraded from 3.0.12 to 3.1.0..

VBoxManage startvm {id} --type {headless,sdl}

..sometimes hangs. It just affects the startvm subcommand while showvminfo, controlvm (and probably others) are pretty reliable.

When the system is idle, it rarely happens but when it's under heavy load (e.g. compiling something), then it will almost certainly hang.

A short strace revealed the following:

(...)
write(1, "Remote session has been successf"..., 45Remote session has been successfully opened.
) = 45
write(9, "8", 1)                        = 1
gettimeofday({1261672393, 414255}, NULL) = 0
gettimeofday({1261672393, 414282}, NULL) = 0
gettimeofday({1261672393, 414309}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 414336878}) = 0
futex(0x96098e0, FUTEX_WAIT_PRIVATE, 33, {29, 999972122}) = 0
futex(0x9609bac, FUTEX_WAKE_PRIVATE, 1) = 0
write(9, "8", 1)                        = 1
gettimeofday({1261672393, 414553}, NULL) = 0
gettimeofday({1261672393, 414581}, NULL) = 0
gettimeofday({1261672393, 414608}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 414635799}) = 0
futex(0x96098e0, FUTEX_WAIT_PRIVATE, 35, {29, 999972201}) = 0
futex(0x9609bac, FUTEX_WAKE_PRIVATE, 1) = 0
write(9, "8", 1)                        = 1
gettimeofday({1261672393, 414822}, NULL) = 0
gettimeofday({1261672393, 414850}, NULL) = 0
gettimeofday({1261672393, 414878}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 414905386}) = 0
futex(0x96098e0, FUTEX_WAIT_PRIVATE, 37, {29, 999972614}) = 0
futex(0x9609bac, FUTEX_WAKE_PRIVATE, 1) = 0
write(9, "8", 1)                        = 1
gettimeofday({1261672393, 415100}, NULL) = 0
gettimeofday({1261672393, 415129}, NULL) = 0
gettimeofday({1261672393, 415155}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 415182796}) = 0
futex(0x96098e0, FUTEX_WAIT_PRIVATE, 39, {29, 999972204}) = 0
futex(0x9609bac, FUTEX_WAKE_PRIVATE, 1) = 0
gettimeofday({1261672393, 415335}, NULL) = 0
gettimeofday({1261672393, 415364}, NULL) = 0
gettimeofday({1261672393, 415391}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 415419418}) = 0
futex(0x9609c38, FUTEX_WAIT_PRIVATE, 37, {1047991, 607971582}) = 0
futex(0x9609d4c, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x9609e10, FUTEX_CMP_REQUEUE_PRIVATE, 1, 2147483647, 0x960a284, 12) = 1
sched_yield()                           = 0
gettimeofday({1261672393, 416255}, NULL) = 0
gettimeofday({1261672393, 416284}, NULL) = 0
gettimeofday({1261672393, 416311}, NULL) = 0
clock_gettime(CLOCK_REALTIME, {1261672393, 416339089}) = 0
futex(0x9609c38, FUTEX_WAIT_PRIVATE, 39, {1047991, 606971911}
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^ stops and waits here

When using..

/usr/lib/virtualbox/VBox{Headless,SDL} --startvm {id}

..directly, everything works fine.

I tried to start VBoxSVC before running VBoxManage but that didn't help. Same applies to removing --auto-shutdown or lowering --pipe.

Any ideas what else I could try?

Thanks

[Petar Bogdanovic]

Hm, I can't reproduce this with 3.1.2. Please close.

[Marc Schütz]

Reopening. I'm having quite similar symptoms with 3.1.4 / Linux-x86, so I'm certain this is related.

VBoxManage startvm ... --type gui gets stuck almost every time. It also sleeps waits in futex(). After that, all other VBoxManage commands will also hang; you cannot even start the VirtualBox GUI until you killall all VBoxSVC and VirtualBox processes: killall -9 VBoxSVC killall -9 VirtualBox

This is the output of VBoxManage startvm: Waiting for the remote session to open... Remote session has been successfully opened. At this point, it just sits there and waits.

If I start VBoxSVC beforehand, it prints "Informational: VirtualBox object created (rc=NS_OK)." and doesn't do anything else.

These VirtualBox related processes are running according to pstree: init-+-VBoxSVC-+-VirtualBox---3*[{VirtualBox}]

| `-8*[{VBoxSVC}] :

|bash---VBoxManage---VBoxManage-+-VBoxXPCOMIPCD

| | `-3*[{VBoxManage}]

ps ax|grep V: 23979 pts/5 S+ 0:00 /bin/bash /usr/bin/VBoxManage --nologo startvm winxp --type gui 23980 pts/5 Sl+ 0:00 /usr/lib/virtualbox/VBoxManage --nologo startvm winxp --type gui 23983 pts/5 S+ 0:00 /usr/lib/virtualbox/VBoxXPCOMIPCD 23990 ? Sl 0:00 /usr/lib/virtualbox/VBoxSVC --pipe 13 --auto-shutdown 24000 ? Sl 0:00 /usr/lib/virtualbox/VirtualBox --comment winxp --startvm 136d5e95-4219-4a3a-b8f0-b1b7de90798e

Here's what the processes are doing:

strace -p 23979: waitpid(-1, ^{C <unfinished ...>}

strace -p 23980: restart_syscall(<... resuming interrupted call ...>

strace -p 23983: restart_syscall(<... resuming interrupted call ...>

strace -p 23990: futex(0x81c4430, FUTEX_WAIT_PRIVATE, 441, NULL

strace -p 24000: restart_syscall(<... resuming interrupted call ...>

Playing with the --pipe parameter had no effect for me either.

Please tell me what other information I can provide.

[Marc Schütz]

Sorry for the formatting, here are the relevant parts again:

init-+-VBoxSVC-+-VirtualBox---3*[{VirtualBox}]
     |         `-8*[{VBoxSVC}]
     :
     |                   |-bash---VBoxManage---VBoxManage-+-VBoxXPCOMIPCD
     |                   |                                `-3*[{VBoxManage}]

ps ax|grep V:
23979 pts/5 S+  0:00 /bin/bash /usr/bin/VBoxManage --nologo startvm winxp --type gui
23980 pts/5 Sl+ 0:00 /usr/lib/virtualbox/VBoxManage --nologo startvm winxp --type gui
23983 pts/5 S+  0:00 /usr/lib/virtualbox/VBoxXPCOMIPCD
23990 ?     Sl  0:00 /usr/lib/virtualbox/VBoxSVC --pipe 13 --auto-shutdown
24000 ?     Sl  0:00 /usr/lib/virtualbox/VirtualBox --comment winxp --startvm 136d5e95-4219-4a3a-b8f0-b1b7de90798e 

[Frank Mehnert]

Please reopen if still relevant with VBox 4.1.6.

[Petar Bogdanovic]

Long gone, thanks for closing.

[Alex]

I'm experiencing a problem similar to this one, I'm unable to shutdown a VM and unable to do anything more with it.

doing a strace for the command: $ strace VBoxManage controlvm w7-vm poweroff the process hangs and these are the latest lines of strace: [...] futex(0x197e770, FUTEX_WAKE_PRIVATE, 1) = 1 futex(0x198767c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 25, {1323964345, 488719000}, ffffffff) = -1 EAGAIN (Resource temporarily unavailable) futex(0x19876c8, FUTEX_WAKE_PRIVATE, 1) = 0 futex(0x19879ac, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 23, {1327144894, 463827000}, ffffffff) = 0 futex(0x19879f8, FUTEX_WAKE_PRIVATE, 1) = 0 write(7, "8", 1) = 1 futex(0x198767c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 27, {1323964345, 489028000}, ffffffff) = 0 futex(0x19876c8, FUTEX_WAKE_PRIVATE, 1) = 0 futex(0x19879ac, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 25, {1327144894, 463251000}, ffffffff

I'm using vbox 4.1.6, kernel 2.6.39

[Alex]

Sorry for the bad formatting, is a better log:

futex(0x197e770, FUTEX_WAKE_PRIVATE, 1) = 1
futex(0x198767c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 25, {1323964345, 488719000}, ffffffff) = -1 EAGAIN (Resource temporarily unavailable)
futex(0x19876c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x19879ac, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 23, {1327144894, 463827000}, ffffffff) = 0
futex(0x19879f8, FUTEX_WAKE_PRIVATE, 1) = 0
write(7, "8", 1)                        = 1
futex(0x198767c, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 27, {1323964345, 489028000}, ffffffff) = 0
futex(0x19876c8, FUTEX_WAKE_PRIVATE, 1) = 0
futex(0x19879ac, FUTEX_WAIT_BITSET_PRIVATE|FUTEX_CLOCK_REALTIME, 25, {1327144894, 463251000}, ffffffff

[aeichner]

Please reopen if still relevant with a recent VirtualBox release.