Understanding the reason for VM crash (OOM) from a crash dump

Questions / Help
,
1

Hi, we’re trying to understand why the VM crashed with OOM error by analysing the crash dump. Here’s the output of erl_crashdump_analyzer.sh:

$ ./erl_crashdump_analyzer.sh prod-2crash-2.dump
analyzing prod-2crash-2.dump, generated on:  Wed Mar 16 07:10:32 2022

Slogan: eheap_alloc: Cannot allocate 762886488 bytes of memory (of type "old_heap").

Memory:
===
  processes: 694 Mb
  processes_used: 694 Mb
  system: 2230 Mb
  atom: 1 Mb
  atom_used: 1 Mb
  binary: 2164 Mb
  code: 0 Mb
  ets: 6 Mb
  ---
  total: 2924 Mb

Different message queue lengths (5 largest different):
===
 990 0

Error logger queue length:
===

File descriptors open:
===
  UDP:  0
  TCP:  109
  Files:  1
  ---
  Total:  110

Number of processes:
===
     990

Processes Heap+Stack memory sizes (words) used in the VM (5 largest different):
===
   1 66222786
   1 999631
   1 514838
   1 318187
   2 121536

Processes OldHeap memory sizes (words) used in the VM (5 largest different):
===
   1 999631
   3 833026
  13 514838
   1 318187
   4 196650

Process States when crashing (sum):
===
   1 CONNECTED
   1 CONNECTED|BINARY_IO
 104 CONNECTED|BINARY_IO|PORT_LOCK
   1 CONNECTED|BINARY_IO|SOFT_EOF|PORT_LOCK
   8 CONNECTED|PORT_LOCK
   1 CONNECTED|SOFT_EOF
   1 Current Process Garbing
   1 Current Process Internal ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL | ACTIVE | GC | DIRTY_ACTIVE_SYS | DIRTY_RUNNING_SYS
   1 Garbing
   1 Internal ACT_PRIO_HIGH | USR_PRIO_HIGH | PRQ_PRIO_HIGH
   3 Internal ACT_PRIO_HIGH | USR_PRIO_HIGH | PRQ_PRIO_HIGH | OFF_HEAP_MSGQ
   3 Internal ACT_PRIO_LOW | USR_PRIO_LOW | PRQ_PRIO_LOW
   4 Internal ACT_PRIO_MAX | USR_PRIO_MAX | PRQ_PRIO_MAX
   1 Internal ACT_PRIO_MAX | USR_PRIO_MAX | PRQ_PRIO_MAX | OFF_HEAP_MSGQ
 973 Internal ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL
   1 Internal ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL | ACTIVE | GC | DIRTY_ACTIVE_SYS | DIRTY_RUNNING_SYS
   4 Internal ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL | OFF_HEAP_MSGQ
 989 Waiting

The crash dump is +1.6GB in size and the tool spews out this error:

 ./erl_crashdump_analyzer.sh: line 30: let: m=Current Process Program counter: 0x00007f6b23b608b8 ('Elixir.Jason.Decoder':string/7 + 24)/(1024*1024): syntax error in expression (error token is "Process Program counter: 0x00007f6b23b608b8 ('Elixir.Jason.Decoder':string/7 + 24)/(1024*1024)")

Here are some relevant parts of the crash dump:

31 =dirty_cpu_scheduler:3
32 Scheduler Sleep Info Flags:
33 Scheduler Sleep Info Aux Work:
34 Current Process: <0.24269.0>
35 Current Process State: Garbing
36 Current Process Internal State: ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL | ACTIVE | GC | DIRTY_ACTIVE_SYS | DIRTY_RUNNING_SYS
37 Current Process Program counter: 0x00007f6b23b608b8 ('Elixir.Jason.Decoder':string/7 + 24)
38 Current Process Limited Stack Trace:
39 0x00007f6a3e9bc490:SReturn addr 0x23B60130 ('Elixir.Jason.Decoder':parse/2 + 288)
40 0x00007f6a3e9bc4b8:SReturn addr 0x232685D0 ('Elixir.Tesla.Middleware.JSON':process/3 + 72)
41 0x00007f6a3e9bc4d0:SReturn addr 0x23267DF0 ('Elixir.Tesla.Middleware.JSON':decode/2 + 280)
42 0x00007f6a3e9bc4e8:SReturn addr 0x23C900D0 ('Elixir.Tesla.Middleware.Retry':retry/3 + 216)
...
47 0x00007f6a3e9bc578:SReturn addr 0x23E5AE98 ('Elixir.Oban.Queue.Executor':perform/1 + 296)
48 0x00007f6a3e9bc5a0:SReturn addr 0x23E597B0 ('Elixir.Oban.Queue.Executor':call/1 + 136)
49 0x00007f6a3e9bc5b0:SReturn addr 0x60B011E0 ('Elixir.Task.Supervised':invoke_mfa/2 + 128)
50 0x00007f6a3e9bc5f8:SReturn addr 0x60B01920 ('Elixir.Task.Supervised':reply/4 + 320)
51 0x00007f6a3e9bc610:SReturn addr 0x6C5CB950 (proc_lib:init_p_do_apply/3 + 64)
52 0x00007f6a3e9bc630:SReturn addr 0x9A0F88 (<terminate process normally>)
...
104 =dirty_io_run_queue
105 Run Queue Max Length: 0
106 Run Queue High Length: 0
107 Run Queue Normal Length: 0
108 Run Queue Low Length: 0
109 Run Queue Port Length: 0
110 Run Queue Flags: OUT_OF_WORK | HALFTIME_OUT_OF_WORK
111 =memory
112 total: 3066553160
113 processes: 728034440
114 processes_used: 728028416
115 system: 2338518720
116 atom: 1917297
117 atom_used: 1915015
118 binary: 2269481192
119 code: 42046517
120 ets: 6942480
...
24606 =proc:<0.24269.0>
24607 State: Garbing
24608 Spawned as: proc_lib:init_p/5
24609 Last scheduled in for: 'Elixir.Jason.Decoder':string/7
24610 Spawned by: <0.3530.0>
24611 Message queue length: 0
24612 Number of heap fragments: 6552
24613 Heap fragment data: 3373654
24614 Link list: [<0.3530.0>, {from,<0.3531.0>,#Ref<0.2180618153.564920321.79435>}, {from,<0.24270.0>,#Ref<0.2180618153.564920321.79437>}]
24615 Reductions: 1513280838
24616 Stack+heap: 66222786
24617 OldHeap: 0
24618 Heap unused: 3372710
24619 OldHeap unused: 0
24620 BinVHeap: 275173304
24621 OldBinVHeap: 0
24622 BinVHeap unused: 87907486
24623 OldBinVHeap unused: 28711198
24624 Memory: 556772760
24625 New heap start: 7F6A1F07F028
24626 New heap top: 7F6A3D001108
24627 Stack top: 7F6A3E9BC490
24628 Stack end: 7F6A3E9BC638
24629 Old heap start: 0
24630 Old heap top: 0
24631 Old heap end: 0
24632 Program counter: 0x00007f6b23b608b8 ('Elixir.Jason.Decoder':string/7 + 24)
24633 Internal State: ACT_PRIO_NORMAL | USR_PRIO_NORMAL | PRQ_PRIO_NORMAL | ACTIVE | GC | DIRTY_ACTIVE_SYS | DIRTY_RUNNING_SYS

Things that we managed to figure out so far:

  • The VM went down trying to allocate extra ~760MB of memory while already consuming ~3GB,
  • The culprit is the process with pid 0.24269.0: an Oban job that was paging through the results of an external API and accumulating JSON responses in memory (this was probably a mistake); it looks like that particular endpoint had an unusual amount of data; running the job would bring the whole VM down again and again after the app was brought up; removing the job solved the problem,
  • The VM crashed when the offending process was doing garbage collection,
  • The system was not showing any signs of overload in terms of CPU or memory prior to going down,
  • It’s unlikely that the data returned by the endpoint would be huge, definitely not in the ballpark of hundreds of megabytes,
  • We’re on Erlang 23.3.4.11 and Elixir 1.13.3,
  • We’re using the default Logger config (handle_otp_reports: true, handle_sasl_reports: false).

I’m unable to inspect the offending process in crashdump_viewer - the tool cannot handle that, reading the heap of the process times out and the UI disappears.

What really happened here?

My theory is that the offending process went over some per-process memory limit and crashed; while logging the crash, the VM went down. Can this be somehow confirmed? I was not able to reproduce it.

Is there a way to prevent this from happening again?

2

Which http client are you using? You might want to look at Finch as it reduces the amount of data copying. This can really help when dealing with large responses.

3

Thanks, I’ll look into that! But the priority now is to pinpoint the actual reason for the crash and find measures to prevent this from happening again.

4

The memory of 556Mb on that single process indeed looks like it’s the culprit, and somewhere it must have gotten all that data from. If the crashdump is 1.6gb and this process alone is already at 500Mb then you could try some manual inspection of the crashdump as 1/3 of the whole file belongs to this one process. Assuming it’s JSON you might be quick in figuring out what kind of payload can have become this large.

In terms of preventing, you could set up a maximum memory limit either only for these worker processes using process_flag_max_heap_size or for all processes in the system with the +hmax parameter. E.g. setup a 300Mb per-process memory limit, if that is more than you expect. That will ensure that individual “poison” data sets won’t kill your VM.