With solo5, firewall runs out of memory after a while and can't recover

[talex5]

First reported by @palainp in #116 (comment). I see this too now, after a few days.

2020-10-26 15:26:48 -00:00: INF [memory_pressure] Writing meminfo: free 115MiB / 124MiB (93.24 %)
[...]
2020-10-27 09:00:57 -00:00: INF [client_eth:dom33:10.137.0.15] who-has 10.137.0.16? responding with fe:ff:ff:ff:ff:ff
2020-10-27 09:01:04 -00:00: INF [memory_pressure] Writing meminfo: free 13MiB / 124MiB (9.99 %)
2020-10-27 09:01:04 -00:00: WRN [firewall] Memory low - dropping packet and resetting NAT table
2020-10-27 09:01:04 -00:00: INF [memory_pressure] Writing meminfo: free 13MiB / 124MiB (9.99 %)
2020-10-27 09:01:04 -00:00: WRN [firewall] Memory low - dropping packet and resetting NAT table
2020-10-27 09:01:04 -00:00: INF [memory_pressure] Writing meminfo: free 13MiB / 124MiB (9.99 %)
2020-10-27 09:01:04 -00:00: WRN [firewall] Memory low - dropping packet and resetting NAT table

[hannesm]

I managed to get memtrace (and memtrace_viewer) to work with MirageOS unikernels -- take a look at https://github.com/hannesm/memtrace-mirage this may be useful for debugging it further (being able to see the OCaml view of which call stacks refer to how much memory) -- see https://blog.janestreet.com/finding-memory-leaks-with-memtrace/ for a great description of memtrace_viewer.

[palainp]

My current thinking is that malloc_footprint() is too pessimistic and need some time to be updated when we run out of free memory.

The second solution offered by @mato in #116 (comment) was to use sbrk(0) instead of malloc_footprint() but this function is currently not available in nolibc (https://github.com/mirage/ocaml-freestanding/blob/master/nolibc/include/unistd.h).

The easiest workaround may be to add the state function (and use the slower but more accurate mallinfo) in addition to the actual quick_state and if we get low on free memory reported by quick_state we can more accurately assess the free memory before calling the GC. We will see a drop in performance (or a growth on CPU usage) for a while but when quick_state will be updated the unikernel will work as before.

[talex5]

It seems to fail very suddenly. Here's an example (I got it to print GC stats and heap stats once a minute; the unikernel had been running fine for several days before this):

GC stats
minor_collections: 7775
major_collections: 149
compactions:       0

minor_words:    2018361516
promoted_words:   32060857
major_words:      32078117

top_heap_words: 1331712
heap_words:     1331712
live_words:     1008819
free_words:      316710
largest_free:       384
fragments:         6183

live_blocks: 271475
free_blocks: 49212
heap_chunks: 14
2020-11-01 03:31:48 -00:00: INF [memory_pressure] :Writing meminfo: free 115MiB / 124MiB (93.24 %)

GC stats
minor_collections: 7822
major_collections: 150
compactions:       0

minor_words:    2030324081
promoted_words:   32236779
major_words:      32254039

top_heap_words: 1331712
heap_words:     1331712
live_words:     1184741
free_words:      140033
largest_free:       800
fragments:         6938

live_blocks: 309418
free_blocks: 15954
heap_chunks: 14
2020-11-01 03:32:48 -00:00: INF [memory_pressure] :Writing meminfo: free 115MiB / 124MiB (93.24 %)

GC stats
minor_collections: 7942
major_collections: 153
compactions:       0

minor_words:    2061383180
promoted_words:   32681555
major_words:      32698815

top_heap_words: 1531904
heap_words:     1531904
live_words:      693951
free_words:      835167
largest_free:    194872
fragments:         2786

live_blocks: 204263
free_blocks: 23925
heap_chunks: 15
2020-11-01 03:32:57 -00:00: INF [memory_pressure] :Writing meminfo: free 12MiB / 124MiB (9.10 %)
2020-11-01 03:32:57 -00:00: WRN [firewall] Memory low - dropping packet and resetting NAT table

GC stats
minor_collections: 7943
major_collections: 155
compactions:       0

minor_words:    2061387164
promoted_words:   32681970
major_words:      32699230

top_heap_words: 1531904
heap_words:     1531904
live_words:      468643
free_words:     1062198
largest_free:    194812
fragments:         1063

live_blocks: 144429
free_blocks: 14564
heap_chunks: 15
2020-11-01 03:32:57 -00:00: INF [memory_pressure] :Writing meminfo: free 12MiB / 124MiB (9.10 %)

So, it had 115 MB free. Then it tried to increase the OCaml heap by 1.5 MB. Then there was only 12 MB free??

When this happened, I was uploading a 30K file to gmail.

When it happens, it always seems to have just under 10% free.

[mato]

If you give it, say, 512MB of memory, and sample meminfo every 30s or so (both the raw numbers from GC and OS.MM), what does that look like over time? And, is there an amount of memory with which you reach a plateau and don't run out?

[talex5]

@mato: that's roughtly what I'm doing already (except sampling every 60s rather than every 30s). I'd normally run the firewall with 32MB, but here I'm testing with 128MB, which should be way more than it needs.

Memory use looks completely flat until it fails. I only showed the last two good reports before failure, but it continued like that for days.

Note that the reports above where it went from 115 MB free to 12 MB free (and head_chunks went up by 1) are only 9 seconds apart!

[mato]

Memory use looks completely flat until it fails. I only showed the last two good reports before failure, but it continued like that for days.

Ah, so, it suffers from "sudden death" after working fine for days. That's very strange. No ideas off the top of my head, I'll think about it.

[palainp]

Between 03:32:48 and 03:32:57 the number of fragments is divided by 2 and the size of the largest free block increased a lot, it may reveals a memory consolidation from the allocator.

I'm not sure I understand correctly how and when the footprint value is updated but looks like we might have to expect success in this test : https://github.com/mirage/ocaml-freestanding/blob/master/nolibc/dlmalloc.i#L4775

This bug is difficult to trigger because we may have to wait a long time to get it. I'm currently trying to evaluate the free memory available with mallinfo() if we are low on the value reported by malloc_footprint.

[palainp]

Update:
I use a mirage-xen pinned at https://github.com/palainp/mirage-xen.git that add stat() using mallinfo() and this modified status function in memory_pressure.ml:

let status () =
  let stats = OS.Memory.quick_stat () in
  if fraction_free stats > 0.1 then `Ok
  else (
    let stats = OS.Memory.stat () in
    if fraction_free stats > 0.1 then (
      Log.info (fun f -> f "quick_stat reported low memory but stat doesn't");
      `Ok
    ) else (
      Gc.full_major ();
      let stats = OS.Memory.stat () in
      report_mem_usage stats;
      if fraction_free stats < 0.1 then `Memory_critical
      else `Ok
    )
  )

This morning I got the following in the unikernel logs:

2020-11-06 09:02:16 -00:00: INF [client_eth:dom15:10.137.0.17] who-has 10.137.0.21? responding with fe:ff:ff:ff:ff:ff
2020-11-06 09:02:24 -00:00: INF [memory_pressure] quick_stat reported low memory but stat doesn't
...
2020-11-06 09:02:57 -00:00: INF [memory_pressure] quick_stat reported low memory but stat doesn't
2020-11-06 09:03:22 -00:00: INF [client_eth:dom10:10.137.0.5] who-has 10.137.0.21? responding with fe:ff:ff:ff:ff:ff

So now I still don't know what the bug is due to, but when it appears the kernel runs 100% for 30" then goes back to a normal situation.

[palainp]

After the previous quick_stat reported low memory but stat doesn't the unikernel worked fine for 2h, but then this message came back and stayed for another 2h...

Now I'm trying to use malloc_trim() when there is a difference between the free memory returned by footprint() and mallinfo() to try to update the value returned by footprint() sooner : https://github.com/palainp/ocaml-freestanding/commit/d50da12bca520e8b4f8b89f8d5bbb4508654632d palainp/mirage-xen@2ec4710 palainp@1d459cd

[palainp]

Update: Unfortunately, using malloc_trim() didn't change anything (the quick_stat still report low memory when stat doesn't). I'm now trying to call sbrk() instead of malloc_footprint(): palainp/mirage-xen@fddeef9 (and ocaml-freestanding no longer need to be pinned).

I actually have the same memory reporting with malloc_footprint() when the unikernel starts:

2020-11-12 06:58:15 -00:00: INF [memory_pressure] Writing meminfo: free 51MiB / 60MiB (85.90 %)

and with sbrk():

2020-11-12 14:14:19 -00:00: INF [memory_pressure] Writing meminfo: free 51MiB / 60MiB (85.89 %)

[xaki23]

bit of a strange observation here.
my "mirage fw test instance" is between a "vpn VM" and a "sync backup offsite" one that gets restarted hourly.
this tends to be a not so bad test because it sees a lot of vm stop/starts and plenty of traffic and doesnt make me too unhappy when it breaks (the backup sync will just restart it on next cycle).

for the last 5 days, i have been running a mirage-fw with the following particulars there:

• templated pvh, so with Xen PVH booting via multiboot protocol (from pvgrub2-pvh) Solo5/solo5#482 applied so it would start through grub
• the "report mem stats every 10 min" from Report memory usage every 10 minutes #121
• vm set to memory 42, maxmem 1000 (which in practice gets reported as 1GB total by solo5 from the start, and xen slowly adjusts it up over the next few days)

this fw has been stable for 5d now, and grepping the log there has been zero movement in the mem stats, they have all been "INF [memory_pressure] Writing meminfo: free 987MiB / 996MiB (99.16 %)".
it did not even blink with different amounts of downstream VMs, and it has been pushing a lot of GBs in those days, using up about 25k sec of CPU time.

for comparison, another instance (no mem-reporting, started as dom0-supplied kernel, 64MB total) would reliably hit the OOM wall within very few hours.

not fully sure what that means yet, some options include "it didnt see any peaks at all", "the peaks are too short to be seen with 10min reporting, and stay well below 1GB", or "the OOM doesnt happen when started through multiboot".

going to crosstest with a different load profile // usecase and a different mem setting and/or bootpath in the backup role next.

[xaki23]

i can rule out "something different about the used package versions" (caused by pinning solo5 to dev for multiboot or building outside docker in general):
the exact same binary that is stable when run templated/grub/multiboot hits the OOM wall when running via "plain xen" path.

still no OOM when multibooted, and using it in "all roles" now.

one unrelated looking crash:

Fatal error: exception (Failure "Netif: ERROR response")
Raised at file "string.ml", line 115, characters 19-34
Called from file "src/sexp.ml", line 113, characters 13-47
Solo5: solo5_exit(2) called

no idea what that was about or what triggered it.

[xbc5]

Any developments on this?