Skip to content

wasm: out of memory with lots of HeapIdle #3237

@anuraaga

Description

@anuraaga

I am debugging an OOM panic with a wasm binary and want to check if this is a fact of life. The binary is handling HTTP requests in Envoy

https://github.com/corazawaf/coraza-proxy-wasm

After a while, it crashes with this, from a C++ function that's calling malloc which I have linked into the binary (recall the fix to allow malloc to not be corrupted for polyglot)

Proxy-Wasm plugin in-VM backtrace:
  0:  0xaf0a6 - runtime.runtimePanic
  1:  0xac0ac - runtime.alloc
  2:  0xc02a3 - malloc
  3:  0x1db10 - _Znwm
  4:  0x9967b - _ZN3re24Prog14MarkSuccessorsEPNS_11SparseArrayIiEES3_PNSt3__26vectorINS5_IiNS4_9allocatorIiEEEENS6_IS8_EEEEPNS_10SparseSetTIvEEPS8_
  5:  0x98bab - _ZN3re24Prog7FlattenEv
  6:  0xa141d - _ZN3re28Compiler6FinishEPNS_6RegexpE
  7:  0xa06bf - _ZN3re28Compiler7CompileEPNS_6RegexpEbx
  8:  0xa1511 - _ZN3re26Regexp20CompileToReverseProgEx
  9:  0xa8128 - _ZNSt3__217__call_once_proxyINS_5tupleIJOZNK3re23RE211ReverseProgEvE3$_1OPKS3_EEEEEvPv

I print memstats after each request, and they look like the below. There is no upward trend in the number of live objects so I don't think we have a memory leak. HeapIdle remains high throughout the program - is this because the memory gets fragmented and something we can't improve? Or is there by any chance a possible bug? I'm not too sure why it panics even though there's still plenty of headway from this 512MB heap up to the theoretical 4GB max, this may be an Envoy quirk. But either way I'd expect 512MB to be enough especially given the amount of idle heap. So wondering if there is a way to debug what could cause this and perhaps reduce heap fragmentation somehow.

Thanks!

[2022-10-18 03:41:48.211576][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 305275600, HeapInuse: 235409808, HeapReleased: 0, TotalAlloc: 6501802146, Mallocs: 29364142, Frees: 29072016, Live: 292126, GCSys: 8448210
[2022-10-18 03:41:50.277445][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 310489168, HeapInuse: 230196240, HeapReleased: 0, TotalAlloc: 6417949203, Mallocs: 28800064, Frees: 28502873, Live: 297191, GCSys: 8448210
[2022-10-18 03:41:50.357212][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 303646512, HeapInuse: 237038896, HeapReleased: 0, TotalAlloc: 6424564660, Mallocs: 28829160, Frees: 28502873, Live: 326287, GCSys: 8448210
[2022-10-18 03:41:50.436784][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 296803760, HeapInuse: 243881648, HeapReleased: 0, TotalAlloc: 6431180187, Mallocs: 28858258, Frees: 28502873, Live: 355385, GCSys: 8448210
[2022-10-18 03:41:50.520306][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 298149872, HeapInuse: 242535536, HeapReleased: 0, TotalAlloc: 6508661253, Mallocs: 29398622, Frees: 29072016, Live: 326606, GCSys: 8448210
[2022-10-18 03:41:50.599077][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 289961008, HeapInuse: 250724400, HeapReleased: 0, TotalAlloc: 6437795718, Mallocs: 28887356, Frees: 28502873, Live: 384483, GCSys: 8448210
[2022-10-18 03:41:50.678640][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 291307120, HeapInuse: 249378288, HeapReleased: 0, TotalAlloc: 6515276784, Mallocs: 29427720, Frees: 29072016, Live: 355704, GCSys: 8448210
[2022-10-18 03:41:50.768192][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 284167968, HeapInuse: 256517440, HeapReleased: 0, TotalAlloc: 6522151153, Mallocs: 29462448, Frees: 29072016, Live: 390432, GCSys: 8448210
[2022-10-18 03:41:50.846150][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 283118112, HeapInuse: 257567296, HeapReleased: 0, TotalAlloc: 6444411385, Mallocs: 28916455, Frees: 28502873, Live: 413582, GCSys: 8448210
[2022-10-18 03:41:50.929658][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 277325312, HeapInuse: 263360096, HeapReleased: 0, TotalAlloc: 6528766612, Mallocs: 29491544, Frees: 29072016, Live: 419528, GCSys: 8448210
[2022-10-18 03:41:51.012431][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 275936928, HeapInuse: 264748480, HeapReleased: 0, TotalAlloc: 6451328804, Mallocs: 28951026, Frees: 28502873, Live: 448153, GCSys: 8448210
[2022-10-18 03:41:51.090576][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 269094176, HeapInuse: 271591232, HeapReleased: 0, TotalAlloc: 6457944335, Mallocs: 28980124, Frees: 28502873, Live: 477251, GCSys: 8448210
[2022-10-18 03:41:51.168760][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 262251520, HeapInuse: 278433888, HeapReleased: 0, TotalAlloc: 6464559788, Mallocs: 29009220, Frees: 28502873, Live: 506347, GCSys: 8448210
[2022-10-18 03:41:51.253787][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 270273440, HeapInuse: 270411968, HeapReleased: 0, TotalAlloc: 6535549993, Mallocs: 29526228, Frees: 29072016, Live: 454212, GCSys: 8448210
[2022-10-18 03:41:51.331706][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 263430768, HeapInuse: 277254640, HeapReleased: 0, TotalAlloc: 6542165458, Mallocs: 29555325, Frees: 29072016, Live: 483309, GCSys: 8448210
[2022-10-18 03:41:51.409618][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 255408768, HeapInuse: 285276640, HeapReleased: 0, TotalAlloc: 6471175319, Mallocs: 29038318, Frees: 28502873, Live: 535445, GCSys: 8448210
[2022-10-18 03:41:51.493998][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 256056576, HeapInuse: 284628832, HeapReleased: 0, TotalAlloc: 6549271681, Mallocs: 29589918, Frees: 29072016, Live: 517902, GCSys: 8448210
[2022-10-18 03:41:51.573293][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 248566032, HeapInuse: 292119376, HeapReleased: 0, TotalAlloc: 6477790844, Mallocs: 29067415, Frees: 28502873, Live: 564542, GCSys: 8448210
[2022-10-18 03:41:51.653381][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 241723136, HeapInuse: 298962272, HeapReleased: 0, TotalAlloc: 6484406515, Mallocs: 29096514, Frees: 28502873, Live: 593641, GCSys: 8448210
[2022-10-18 03:41:51.732819][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 234880464, HeapInuse: 305804944, HeapReleased: 0, TotalAlloc: 6491021978, Mallocs: 29125611, Frees: 28502873, Live: 622738, GCSys: 8448210
[2022-10-18 03:41:51.817217][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 227416400, HeapInuse: 313269008, HeapReleased: 0, TotalAlloc: 6498218488, Mallocs: 29160311, Frees: 28502873, Live: 657438, GCSys: 8448210
[2022-10-18 03:41:51.898968][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 220573664, HeapInuse: 320111744, HeapReleased: 0, TotalAlloc: 6504834011, Mallocs: 29189408, Frees: 28502873, Live: 686535, GCSys: 8448210
[2022-10-18 03:41:51.979107][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 213730912, HeapInuse: 326954496, HeapReleased: 0, TotalAlloc: 6511449540, Mallocs: 29218506, Frees: 28502873, Live: 715633, GCSys: 8448210
[2022-10-18 03:41:52.063271][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 206663520, HeapInuse: 334021888, HeapReleased: 0, TotalAlloc: 6518252118, Mallocs: 29252702, Frees: 28502873, Live: 749829, GCSys: 8448210
[2022-10-18 03:41:52.142527][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 199820624, HeapInuse: 340864784, HeapReleased: 0, TotalAlloc: 6524867789, Mallocs: 29281801, Frees: 28502873, Live: 778928, GCSys: 8448210
[2022-10-18 03:41:52.222177][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 192977888, HeapInuse: 347707520, HeapReleased: 0, TotalAlloc: 6531483310, Mallocs: 29310898, Frees: 28502873, Live: 808025, GCSys: 8448210
[2022-10-18 03:41:52.305710][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 185846912, HeapInuse: 354838496, HeapReleased: 0, TotalAlloc: 6538353295, Mallocs: 29344928, Frees: 28502873, Live: 842055, GCSys: 8448210
[2022-10-18 03:41:52.392574][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 179004160, HeapInuse: 361681248, HeapReleased: 0, TotalAlloc: 6544968822, Mallocs: 29374026, Frees: 28502873, Live: 871153, GCSys: 8448210
[2022-10-18 03:41:52.472070][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 249213904, HeapInuse: 291471504, HeapReleased: 0, TotalAlloc: 6555887144, Mallocs: 29619015, Frees: 29072016, Live: 546999, GCSys: 8448210
[2022-10-18 03:41:54.262522][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 172161408, HeapInuse: 368524000, HeapReleased: 0, TotalAlloc: 6551584353, Mallocs: 29403124, Frees: 28502873, Live: 900251, GCSys: 8448210
[2022-10-18 03:41:56.306579][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 308585056, HeapInuse: 232100352, HeapReleased: 0, TotalAlloc: 6558266266, Mallocs: 29433374, Frees: 29134881, Live: 298493, GCSys: 8448210
[2022-10-18 03:41:56.388781][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 301742176, HeapInuse: 238943232, HeapReleased: 0, TotalAlloc: 6564881929, Mallocs: 29462472, Frees: 29134881, Live: 327591, GCSys: 8448210
[2022-10-18 03:41:56.470830][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 294899536, HeapInuse: 245785872, HeapReleased: 0, TotalAlloc: 6571497382, Mallocs: 29491567, Frees: 29134881, Live: 356686, GCSys: 8448210
[2022-10-18 03:41:56.550087][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 288056784, HeapInuse: 252628624, HeapReleased: 0, TotalAlloc: 6578112911, Mallocs: 29520665, Frees: 29134881, Live: 385784, GCSys: 8448210
[2022-10-18 03:41:56.628840][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 281213888, HeapInuse: 259471520, HeapReleased: 0, TotalAlloc: 6584728580, Mallocs: 29549764, Frees: 29134881, Live: 414883, GCSys: 8448210
[2022-10-18 03:41:56.707301][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 274371216, HeapInuse: 266314192, HeapReleased: 0, TotalAlloc: 6591344043, Mallocs: 29578861, Frees: 29134881, Live: 443980, GCSys: 8448210
[2022-10-18 03:41:56.785671][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 267528496, HeapInuse: 273156912, HeapReleased: 0, TotalAlloc: 6597959562, Mallocs: 29607957, Frees: 29134881, Live: 473076, GCSys: 8448210
[2022-10-18 03:41:57.041439][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 260685744, HeapInuse: 279999664, HeapReleased: 0, TotalAlloc: 6604575091, Mallocs: 29637055, Frees: 29134881, Live: 502174, GCSys: 8448210
[2022-10-18 03:41:52.472070][18][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 249213904, HeapInuse: 291471504, HeapReleased: 0, TotalAlloc: 6555887144, Mallocs: 29619015, Frees: 29072016, Live: 546999, GCSys: 8448210
[2022-10-18 03:41:54.262522][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 172161408, HeapInuse: 368524000, HeapReleased: 0, TotalAlloc: 6551584353, Mallocs: 29403124, Frees: 28502873, Live: 900251, GCSys: 8448210
[2022-10-18 03:41:56.306579][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 308585056, HeapInuse: 232100352, HeapReleased: 0, TotalAlloc: 6558266266, Mallocs: 29433374, Frees: 29134881, Live: 298493, GCSys: 8448210
[2022-10-18 03:41:56.388781][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 301742176, HeapInuse: 238943232, HeapReleased: 0, TotalAlloc: 6564881929, Mallocs: 29462472, Frees: 29134881, Live: 327591, GCSys: 8448210
[2022-10-18 03:41:56.470830][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 294899536, HeapInuse: 245785872, HeapReleased: 0, TotalAlloc: 6571497382, Mallocs: 29491567, Frees: 29134881, Live: 356686, GCSys: 8448210
[2022-10-18 03:41:56.550087][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 288056784, HeapInuse: 252628624, HeapReleased: 0, TotalAlloc: 6578112911, Mallocs: 29520665, Frees: 29134881, Live: 385784, GCSys: 8448210
[2022-10-18 03:41:56.628840][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 281213888, HeapInuse: 259471520, HeapReleased: 0, TotalAlloc: 6584728580, Mallocs: 29549764, Frees: 29134881, Live: 414883, GCSys: 8448210
[2022-10-18 03:41:56.707301][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 274371216, HeapInuse: 266314192, HeapReleased: 0, TotalAlloc: 6591344043, Mallocs: 29578861, Frees: 29134881, Live: 443980, GCSys: 8448210
[2022-10-18 03:41:56.785671][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 267528496, HeapInuse: 273156912, HeapReleased: 0, TotalAlloc: 6597959562, Mallocs: 29607957, Frees: 29134881, Live: 473076, GCSys: 8448210
[2022-10-18 03:41:57.041439][17][debug][wasm] [source/extensions/common/wasm/context.cc:1167] wasm log coraza-filter my_vm_id: Sys: 549133632, HeapSys: 540685408, HeapIdle: 260685744, HeapInuse: 279999664, HeapReleased: 0, TotalAlloc: 6604575091, Mallocs: 29637055, Frees: 29134881, Live: 502174, GCSys: 8448210```

Metadata

Metadata

Assignees

No one assigned

    Labels

    wasmWebAssembly

    Type

    No type

    Projects

    No projects

    Milestone

    No milestone

    Relationships

    None yet

    Development

    No branches or pull requests

    Issue actions