VirtualBox

Ticket #15569 (new defect)

Opened 11 months ago

Last modified 7 months ago

VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.

Reported by: frispete Owned by:
Priority: major Component: network
Version: VirtualBox 5.0.24 Keywords: VBoxNetFlt
Cc: Guest type: Windows
Host type: Linux

Description

In a setup of a Win2k8 VM on a openSUSE 13.2 host with a 4.2.5 kernel, I encounter:

Jun 27 23:48:05 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:46:55 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 3350 times, suppressed by syslog-ng 
Jun 27 23:48:35 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:47:25 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 1318 times, suppressed by syslog-ng 
Jun 27 23:49:05 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:47:55 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 589 times, suppressed by syslog-ng 
Jun 27 23:49:35 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:48:02 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 5 times, suppressed by syslog-ng 
Jun 27 23:49:41 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:48:32 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 622 times, suppressed by syslog-ng 
Jun 27 23:50:12 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:48:39 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 140 times, suppressed by syslog-ng 
Jun 27 23:50:18 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:49:08 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 377 times, suppressed by syslog-ng 
Jun 27 23:50:47 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:49:38 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 1291 times, suppressed by syslog-ng 
Jun 27 23:51:18 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:50:08 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 29 times, suppressed by syslog-ng 
Jun 27 23:51:49 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Jun 27 23:50:10 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 5 times, suppressed by syslog-ng

flooding my syslog. Here, more than 6500 packets were dropped in about two minutes.

Reading the source revealed, that this code path is only exercised, if VBOXNETFLT_SG_SUPPORT is not defined. Bears the questions, why does skb_copy fail this often and/or is VBoxNetFlt-linux.c able to deal with fragmented packets, which would avoid the copying (apart from making vbox VLAN support dysfunctional).

This VM is a vSphere vServer instance, that has to run somewhere (preferably not on a vCenter host that it manages itself) in order to avoid "chicken and egg" problems).

For that reason, it shares a NIC with the host in bridged mode.

This is the third virtualization solution, that I'm evaluating now.

1) VMware Workstation: host drivers badly integrated in the host kernel (kind of not at all), significant _host_ stalls perceptible, VM control from host (save, restore, shutdown, start) is working fine.

2) kvm/libvirt: good kernel integration, high cpu load in idle state, acceptable impact on host, bad client driver support, really bad VM control from host (ACPI interface nearly dysfunctional, forced me to control VM from host with awful wmi commands), therefore went on to

3) VirtualBox: acceptable kernel integration, nice distribution support, best behaviour on host impact, great suspend/resume performance, good VM control from host, nice UI, minor glitch in host systemd integration (packaging issue), definitely my favorite, but I would like to solve the bridging issue with whatever it takes (dedicated NIC, NAT?)

An attempt to discuss this on vbox-dev stalled already.

Any enlightment to work around/solve this issue is much appreciated.

Thanks, Pete

Change History

comment:1 Changed 10 months ago by frispete

The problem persists with 5.1.2:

Aug 11 16:51:56 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:51:09 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 317 times, suppressed by syslog-ng
Aug 11 16:52:26 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:51:39 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 574 times, suppressed by syslog-ng
Aug 11 16:52:57 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:52:09 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 32 times, suppressed by syslog-ng 
Aug 11 16:53:39 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:52:52 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 41 times, suppressed by syslog-ng
Aug 11 16:54:09 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet. 
Aug 11 16:53:39 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 2 times, suppressed by syslog-ng
Aug 11 16:54:57 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:54:10 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 33 times, suppressed by syslog-ng
Aug 11 16:55:29 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:54:42 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 80 times, suppressed by syslog-ng
Aug 11 16:55:59 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet. 
Aug 11 16:55:14 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 422 times, suppressed by syslog-ng
Aug 11 16:56:39 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:55:52 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 989 times, suppressed by syslog-ng
Aug 11 16:57:22 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:56:35 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 824 times, suppressed by syslog-ng
Aug 11 16:57:57 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:57:10 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 36 times, suppressed by syslog-ng
Aug 11 16:58:58 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:58:10 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 38 times, suppressed by syslog-ng
Aug 11 16:59:40 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:58:52 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 314 times, suppressed by syslog-ng
Aug 11 17:00:09 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet. 
Aug 11 16:59:22 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 300 times, suppressed by syslog-ng
Aug 11 17:00:39 server kernel: VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.
Aug 11 16:59:52 server kernel: Last message 'VBoxNetFlt: Failed t' repeated 113 times, suppressed by syslog-ng 

Apart from the original issue, what is interesting is the timestamp: it deviates from the host in an unexpected way...

comment:2 Changed 8 months ago by Epsi

Hi,

I'm experiencing this issue too only it's causing massive performance issues on my system.

1.2 MILLION messages in just over 4 hours and rapidly increasing:

$ journalctl | head -1
-- Logs begin at Sun 2016-09-11 07:47:05 MDT, end at Sun 2016-09-11 12:26:31 MDT. --

$ journalctl | grep "VBoxNetFlt: Failed to allocate packet buffer" | wc -l ; date
1251309
Sun Sep 11 12:29:15 MDT 2016

I'm running:

VirtualBox v4.0.26
Ubuntu 15.10
kernel 4.2.0-42
64GB RAM
2x 4-core AMD CPU's
4 VM's

Please let me know what other information I could provide.

Thanks,

-Jeff

comment:3 Changed 8 months ago by Epsi

Hi,

I upgraded to:

Ubuntu 16.04 VirtualBox v5.1.6 kernel 4.4.0-38

and it's still occurring.

There's about 100,000 messages in my log in the last 12 hours.

comment:4 Changed 8 months ago by Christoph Nelles

Having the same problem, VM Log is clean. Happens irregularly but then it fills the kernel log.

It looks like a kernel memory allocation fails:

https://www.virtualbox.org/svn/vbox/trunk/src/VBox/HostDrivers/VBoxNetFlt/linux/VBoxNetFlt-linux.c

        struct sk_buff *pCopy = skb_copy(pBuf, GFP_ATOMIC);
        dev_kfree_skb(pBuf);
        if (!pCopy)
        {
            LogRel(("VBoxNetFlt: Failed to allocate packet buffer, dropping the packet.\n"));
            return 0;
        }

GFP_ATOMIC says that memory allocations must be satisfied immediately or the allocation has to fail, in contrast to giving the kernel the freedom to delay the operation to try to free memory.

From my very limited kernel knowledge my guess would be to increase vm.min_free_kbytes. I have currently set it to 256MB and still get these messages.

Currently I am looking at the free memory pages in the different memory zones and wait for the next message to appear.

@Epsi, what is your min_free_kbytes setting, can you spare 1GB for reserving more memory for the kernel?

sysctl vm.min_free_kbytes
sysctl -w vm.min_free_kbytes=1048576

Does this improve the situation? Can you do

echo m > /proc/sysrq-trigger

and post the generated Meminfo (goes to kernel log) to pastebin or so?

Last edited 8 months ago by Christoph Nelles (previous) (diff)

comment:5 Changed 8 months ago by Epsi

Hi Christoph,

I have plenty of RAM. The sysctl tweak seems to have helped. I made the change, then kicked off a huge copy to my NAS server which is when the errors seem to mostly appear. No errors in the system log. I changed the parameter back to the original 90112 value and the errors came back.

$ sysctl vm.min_free_kbytes
vm.min_free_kbytes = 90112

$ sudo sysctl -w vm.min_free_kbytes=1048576
vm.min_free_kbytes = 1048576

Here's the meminfo output though I ran it after the above change.

Oct 06 15:35:06 myhname kernel: sysrq: SysRq : Show Memory
Oct 06 15:35:06 myhname kernel: Mem-Info:
Oct 06 15:35:06 myhname kernel: active_anon:1460472 inactive_anon:423767 isolated_anon:0
                               active_file:5138345 inactive_file:5396652 isolated_file:0
                               unevictable:28 dirty:140 writeback:0 unstable:0
                               slab_reclaimable:1101142 slab_unreclaimable:63744
                               mapped:2507169 shmem:191479 pagetables:20104 bounce:0
                               free:458141 free_pcp:1621 free_cma:0
Oct 06 15:35:06 myhname kernel: Node 0 DMA free:14956kB min:252kB low:312kB high:376kB active_anon:0kB inactive_anon:0kB active_file:0kB inactive_file:0kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:15992kB managed:15908kB mlocked:0kB dirty:0kB writeback:0kB mapped:128kB shmem:0kB slab_reclaimable:0kB slab_unreclaimable:48kB kernel_stack:0kB pagetables:0kB unstable:0kB bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? yes
Oct 06 15:35:06 myhname kernel: lowmem_reserve[]: 0 2810 32121 32121 32121
Oct 06 15:35:06 myhname kernel: Node 0 DMA32 free:178508kB min:47364kB low:59204kB high:71044kB active_anon:187012kB inactive_anon:201128kB active_file:946520kB inactive_file:980664kB unevictable:0kB isolated(anon):0kB isolated(file):0kB present:2998208kB managed:2983236kB mlocked:0kB dirty:100kB writeback:0kB mapped:394016kB shmem:20008kB slab_reclaimable:91348kB slab_unreclaimable:13056kB kernel_stack:912kB pagetables:4256kB unstable:0kB bounce:0kB free_pcp:2144kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 06 15:35:06 myhname kernel: lowmem_reserve[]: 0 0 29310 29310 29310
Oct 06 15:35:06 myhname kernel: Node 0 Normal free:1355952kB min:476544kB low:595680kB high:714816kB active_anon:3582828kB inactive_anon:694212kB active_file:9490312kB inactive_file:9723324kB unevictable:16kB isolated(anon):0kB isolated(file):0kB present:30539776kB managed:30014364kB mlocked:16kB dirty:312kB writeback:0kB mapped:4008776kB shmem:676136kB slab_reclaimable:1167952kB slab_unreclaimable:75452kB kernel_stack:6144kB pagetables:32384kB unstable:0kB bounce:0kB free_pcp:3208kB local_pcp:444kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 06 15:35:06 myhname kernel: lowmem_reserve[]: 0 0 0 0 0
Oct 06 15:35:06 myhname kernel: Node 1 Normal free:283148kB min:524412kB low:655512kB high:786616kB active_anon:2072048kB inactive_anon:799728kB active_file:10116548kB inactive_file:10882620kB unevictable:96kB isolated(anon):0kB isolated(file):0kB present:33554432kB managed:33029168kB mlocked:96kB dirty:148kB writeback:0kB mapped:5625756kB shmem:69772kB slab_reclaimable:3145268kB slab_unreclaimable:166420kB kernel_stack:8032kB pagetables:43776kB unstable:0kB bounce:0kB free_pcp:1132kB local_pcp:40kB free_cma:0kB writeback_tmp:0kB pages_scanned:0 all_unreclaimable? no
Oct 06 15:35:06 myhname kernel: lowmem_reserve[]: 0 0 0 0 0
Oct 06 15:35:06 myhname kernel: Node 0 DMA: 1*4kB (U) 1*8kB (U) 0*16kB 1*32kB (U) 1*64kB (U) 0*128kB 0*256kB 1*512kB (U) 0*1024kB 1*2048kB (M) 3*4096kB (M) = 14956kB
Oct 06 15:35:06 myhname kernel: Node 0 DMA32: 9072*4kB (UME) 11997*8kB (UME) 1614*16kB (UME) 239*32kB (UME) 83*64kB (UME) 37*128kB (UME) 7*256kB (ME) 2*512kB (M) 0*1024kB 0*2048kB 0*4096kB = 178600kB
Oct 06 15:35:06 myhname kernel: Node 0 Normal: 50408*4kB (UMEH) 25045*8kB (UMEH) 11119*16kB (UMEH) 6052*32kB (UMEH) 3232*64kB (UME) 1377*128kB (UME) 470*256kB (UME) 108*512kB (UM) 23*1024kB (M) 0*2048kB 0*4096kB = 1355832kB
Oct 06 15:35:06 myhname kernel: Node 1 Normal: 9875*4kB (UME) 5590*8kB (UME) 2717*16kB (UME) 1052*32kB (UME) 933*64kB (UME) 257*128kB (UM) 98*256kB (UM) 0*512kB 0*1024kB 2*2048kB (M) 0*4096kB = 283148kB
Oct 06 15:35:06 myhname kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Oct 06 15:35:06 myhname kernel: Node 0 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Oct 06 15:35:06 myhname kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=1048576kB
Oct 06 15:35:06 myhname kernel: Node 1 hugepages_total=0 hugepages_free=0 hugepages_surp=0 hugepages_size=2048kB
Oct 06 15:35:06 myhname kernel: 10728976 total pagecache pages
Oct 06 15:35:06 myhname kernel: 2500 pages in swap cache
Oct 06 15:35:06 myhname kernel: Swap cache stats: add 61494, delete 58994, find 446981/448570
Oct 06 15:35:06 myhname kernel: Free swap  = 3972392kB
Oct 06 15:35:06 myhname kernel: Total swap = 4194300kB
Oct 06 15:35:06 myhname kernel: 16777102 pages RAM
Oct 06 15:35:06 myhname kernel: 0 pages HighMem/MovableOnly
Oct 06 15:35:06 myhname kernel: 266433 pages reserved
Oct 06 15:35:06 myhname kernel: 0 pages cma reserved
Oct 06 15:35:06 myhname kernel: 0 pages hwpoisoned

comment:6 Changed 7 months ago by frank

The flooding is fixed in VBox 5.1.8.

Note: See TracTickets for help on using tickets.

www.oracle.com
ContactPrivacy policyTerms of Use