Memory leak Windows Guest (frequent iSCSI connects)

[Steve Radich]

The last comment in #5159 is a little similar to what I'm seeing - Host is Ubuntu, VirtualBox 3.1.2. Guest is Windows Sever 2008 R2 64 bit, allocating 1024mb ram however according to "top" VIRT is 8055m and increasing by at least a meg per minute. This is a significant ram leak.

$ ps v -p 2526

PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND

2526 ? Sl 117:35 227 19 8266792 5480812 66.8 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526

This guest is running .Net application processing data, .net seems to be in many of these posts (or Visual Studio) but clearly that shouldn't be related to the parent partition (linux host) loosing ram.

[Steve Radich]

Showing pace of leak (these are posted at the time they show in the history).

$ps v -p 2526

PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND

2526 ? Sl 121:16 228 19 8295464 5479628 66.8 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526

[Steve Radich]

$ ps v -p 2526

PID TTY STAT TIME MAJFL TRS DRS RSS %MEM COMMAND

2526 ? Sl 122:44 228 19 8304680 5488996 66.9 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526

9,216k lost?

[Steve Radich]

I tried to save state and resume to hope it saved the virtual machines ram and the new process didn't have the leak - the save went fine, the restore appeared fine but the box wasn't pingable - after several seconds the virtual machine reset - This is VBox-resume.log

The VBox-Save.log is the log after saving state incase that shows anything useful.

[Steve Radich]

Same as VBox.log - however after attempting to "save state"

[Steve Radich]

Resuming from saved state - guest reset after several seconds, never worked when resuming..

[Frank Mehnert]

This leak could be related to the frequent iSCSI connects. Any idea why VBox does connect to the iSCSI target that often?

[Steve Radich]

I don't know why it connects often however the target is COMSTAR on b129 OpenSolaris.

[Steve Radich]

I do feel you are prematurely dismissing this as an iSCSI bug.

As to priority (mainly for anyone else reading this): it blocks the host from working since ram is leaked VERY quickly. That said the server is semi-functional since it seems to just start using the swap file (although other relatively inactive tasks are swapped out, including other virtual machines that can't respond properly since their ram may have been swapped). Perhaps one down from blocker is correct classification since swap can be increased as a temporary work around (just saying this for anyone else that reads the thread).

Here's a leak shown without any iscsi logins during the period - at the end is the next login entry:

26:36:52.035 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ ps v -p 3909
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 3909 ?        Sl   402:25    440    19 6525056 5587852 68.1 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ ps v -p 3909
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 3909 ?        Sl   402:25    440    19 6527104 5588944 68.2 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ tail -2 VBox.log
26:34:52.033 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
26:36:52.035 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ ps v -p 3909
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 3909 ?        Sl   402:26    440    19 6531200 5586684 68.1 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ tail -2 VBox.log
26:34:52.033 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
26:36:52.035 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ ps v -p 3909
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 3909 ?        Sl   402:28    441    19 6537344 5589420 68.2 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ tail -2 VBox.log
26:34:52.033 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
26:36:52.035 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful

Finally after a login:

bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ ps v -p 3909
  PID TTY      STAT   TIME  MAJFL   TRS   DRS   RSS %MEM COMMAND
 3909 ?        Sl   402:29    441    19 6544512 5592960 68.2 /usr/lib/virtualbox/VirtualBox --comment ChartFlightDev1 --startvm 6ccd3661-6126-4c28-9b8c-005e8cea5526
bitshop@c2050r79ubvb01:~/.VirtualBox/Machines/ChartFlightDev1/Logs$ tail -2 VBox.log
26:36:52.035 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful
26:42:10.038 iSCSI: login to target iqn.1995-10.com.bitshop.zfs001:prodtier:chartflightdev1 successful

Is there any further debugging information about the connecting that I can log / trace / investigate from the VirtualBox side? Short of packet capturing? The COMSTAR host was not down/unreachable any during all of these reconnects and I'll investigate that further as time permits, however I'm assuming just a re-login isn't a problem since it should be able to log in anytime.

Thank you for the quick response,

Steve Radich - BitShop.com

[Klaus Espenlaub]

That log noise is a known issue with the current iSCSI initiator implementation in VirtualBox. It gets kicked out by the COMSTAR iSCSI target code if the guest is not accessing the iSCSI target for about 20 seconds. It's on the todo list, but fixing this is a major task. Not aware of any leak either...

[Steve Radich]

This virtual machine is now listed as Aborted, the log has nothing about why it aborted - There is one log entry that isn't a iSCSI login:

146:07:00.058 PIIX3 IDE: guest issued command 0xa0 while controller busy

Then other logins after that again, so I don't think this aborted the guest.

The host OS I believe ran out of swap space, but I'm a Windows Admin really so not sure I'm reading this correctly - In /var/log/messages:

Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.171453] 11663 total pagecache pages Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.171456] 10598 pages in swap cache Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.171459] Swap cache stats: add 9894818, delete 9884220, find 49297/73849 Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.171461] Free swap = 0kB Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.171463] Total swap = 31997944kB Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.201246] 2097136 pages RAM Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.201249] 74546 pages reserved Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.201251] 784236 pages shared Feb 6 11:30:40 c2050r79ubvb01 kernel: [660767.201253] 1226296 pages non-shared

I see Free swap = 0kB, that's 32gb swap + 8gb ram to run 3 guests with 1 gb ram each.

One guest simply syncs files often, robocopy launched once per minute - that has now leaked ~ 10 gb ram.

[faulebutter]

I experience the same problem with VB 3.2.8 PUEL on F13 host with heavy network load (VMDK on an NFS share and VRDP session with video running). The VM gets killed by kernel due to memory overallocation. (I've also posted this on forums: ​http://forums.virtualbox.org/viewtopic.php?f=7&t=34702&p=155557#p155557).