ERL-428: beam.smp crash under load

[OTP-Maintainer]

Original reporter: dane Affected versions: OTP-19.1, OTP-19.0, OTP-20.0 Fixed in versions: OTP-20.0.1, OTP-19.3.6.1 Component: erts Migrated from: https://bugs.erlang.org/browse/ERL-428

---

beam.smp VM crashes under significant load (28 core/56 threads CPU).

All OTPs starting from 19.0 are affected.
OTP 18 is not affected.

Build details:
./configure --enable-dynamic-ssl-lib --with-ssl=/usr/local --disable-sctp --enable-smp-support --disable-hipe

VM flags: tried various combinations, it does not matter at all (crash happens even if no VM parameters are specified).

Crash stack:

(gdb) bt
#0  erts_port_output (c_p=<value optimized out>, flags=<value optimized out>, prt=<value optimized out>, from=<value optimized out>, list=<value optimized out>, refp=<value optimized out>) at atomic.h:240
#1  0x0000000000541d66 in erts_internal_port_command_3 (A__p=0xbff01e0e0, BIF__ARGS=0x846ec00c0) at beam/erl_bif_port.c:197
#2  0x000000000043838a in process_main () at beam/beam_emu.c:2866
#3  0x00000000004cd30c in sched_thread_func (vesdp=0x852100100) at beam/erl_process.c:8206
#4  0x00000000005decfc in thr_wrapper (vtwd=0x7fffffffdce0) at pthread/ethread.c:114
#5  0x00000008013064f5 in pthread_create () from /lib/libthr.so.3
#6  0x0000000000000000 in ?? ()

[OTP-Maintainer]

dane said:

Not sure if it's the same or a separate issue, but I'm also observing a different crash under similar conditions (high CPU load) on 19.3.3 deployed on Linux machine. Stack is: 

* 1    Thread 0x7f848bfff700 (LWP 19935) mbc_alloc_finalize (valid_blk_info=1, want_blk_sz=40, crr=0x2, flags=<optimized out>, org_blk_sz=<optimized out>, blk=0x7f85165002c8, allctr=0x7f85165b8200) at beam/erl_alloc_util.c:2362
(gdb) bt
#0  mbc_alloc_finalize (valid_blk_info=1, want_blk_sz=40, crr=0x2, flags=<optimized out>, org_blk_sz=<optimized out>, blk=0x7f85165002c8, allctr=0x7f85165b8200) at beam/erl_alloc_util.c:2362
#1  mbc_alloc (allctr=allctr@entry=0x7f85165b8200, size=size@entry=32) at beam/erl_alloc_util.c:2434
#2  0x000000000047551b in do_erts_alcu_alloc (size=32, extra=0x7f85165b8200, type=19) at beam/erl_alloc_util.c:5387
#3  erts_alcu_alloc_thr_spec (type=19, extra=<optimized out>, size=32) at beam/erl_alloc_util.c:5441
#4  0x00000000004b65c9 in erts_alloc (size=32, type=2530) at beam/erl_alloc.h:237
#5  erts_create_tmp_dsbuf (size=size@entry=64) at beam/utils.c:2568
#6  0x00000000004c719a in term2list_dsprintf (term=63943473132627, p=0x7f850bb46c80) at beam/bif.c:4111
#7  pid_to_list_1 (A__p=0x7f850bb46c80, BIF__ARGS=<optimized out>) at beam/bif.c:4168
#8  0x00000000004448e9 in process_main () at beam/beam_emu.c:2867
#9  0x00000000004e4bbd in sched_thread_func (vesdp=0x7f85035800c0) at beam/erl_process.c:8206
#10 0x000000000065612b in thr_wrapper (vtwd=<optimized out>) at pthread/ethread.c:114
#11 0x00007f8556bb4dc5 in start_thread (arg=0x7f848bfff700) at pthread_create.c:308
#12 0x00007f85566db73d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:113

Could it be memory corruption?

[OTP-Maintainer]

lukas said:

Yes it does seem like a memory corruption fault, at least in the second backtrace.

Have you saved the core files? Would it be possible to give me access to them together with the beam.smp that produced them?

[OTP-Maintainer]

dane said:

I do have core files, first crash with on FreeBSD, OTH R19.3.4 (2x, each core dump size is 62 Gb), R20.RC1 (32 Gb core dump).
And second crash is on 19.3 (Linux, ~170 Gb dump size - memory leak, not memory corruption).

Unfortunately, I'm unable to provide access to those core files, as they contain sensitive data. Also these are huge.

May I help by supplying more stack prints, or some other information? Please feel free to contact me via e-mail.

[OTP-Maintainer]

dane said:

Stack trace from R20.RC1

[OTP-Maintainer]

dane said:

Few more bits (Erlang R20 RC2 now).

#0  erts_port_output (c_p=<value optimized out>, flags=<value optimized out>, prt=<value optimized out>, from=<value optimized out>, list=<value optimized out>, refp=<value optimized out>) at atomic.h:240
#1  0x000000000054d6b6 in erts_internal_port_command_3 (A__p=0x94530b900, BIF__ARGS=0x85414cd40, A__I=<value optimized out>) at beam/erl_bif_port.c:197
#2  0x0000000000439d02 in process_main (x_reg_array=0x85414cd40, f_reg_array=0x85414edc0) at beam/beam_emu.c:2886
#3  0x00000000004d296b in sched_thread_func (vesdp=0x8522ad400) at beam/erl_process.c:8833
#4  0x00000000005eed9c in thr_wrapper (vtwd=0x7fffffffdd28) at pthread/ethread.c:118
#5  0x00000008013574f5 in pthread_create () from /lib/libthr.so.3
#6  0x0000000000000000 in ?? ()

(gdb) fr 2
#2  0x0000000000439d02 in process_main (x_reg_array=0x85414cd40, f_reg_array=0x85414edc0) at beam/beam_emu.c:2886
2886        result = (*bf)(c_p, reg, I);

(gdb) etp-process-info c_p
  Pid: <0.7156.1311>
  State: on-heap-msgq | running | active | prq-prio-normal | usr-prio-normal | act-prio-normal

  Flags: on-heap-msgq
  Current function: crypto:aes_gcm_encrypt/5
  CP: unknown
  I: #Cp<gen_fsm:loop/7+0x118>
  Heap size: 4185
  Old-heap size: 4185
  Mbuf size: 0
  Msgq len: 1 (inner=1, outer=0)
  Parent: <0.7263.0>
  Pointer: (Process *) 0x94530b900

(gdb) etp-stacktrace c_p
% Stacktrace (31)
#Cp<gen_fsm:loop/7+0x118>  (I)
#Cp<prim_inet:send/3+0xa0>.
<our stuff>
#Cp<gen_fsm:handle_msg/7+0xe8>.
#Cp<proc_lib:init_p_do_apply/3+0x58>.
#Cp<terminate process normally>.

[OTP-Maintainer]

dane said:

Result of thread apply all bt full (Erlang R20 RC1 crash, but all crashed look exactly the same)

[OTP-Maintainer]

lukas said:

Seems like both crashes happen during a call to erlang:port_command. (if we disregard the pid2list crash as you suggested in your mail).

Most likely something is corrupt with the data sent into the bif call. Is the "Current Function" crypto:aes_gcm_encrypt/5 in all the crashes? ("Current Function" in this case is most likely the nif that was most recently called by the process).

What do you get if you do:

{code}
> f 1
> etp BIF_ARGS[0]
> etp BIF_ARGS[1]
> etp BIF_ARGS[2]
{code}

Does all of the arguments print valid terms?

[OTP-Maintainer]

dane said:

Yes, it seems like all the crashes happen in crypto:aes_gcm_encrypt/5

Arguments themselves are valid:
(gdb) etp BIF__ARGS[0]
#Port<0.4984663>.
(gdb) etp BIF__ARGS[1]
[#HeapBinary<0x17,0x18140000,0xd8c84f91,0x1fc33bd7>].
(gdb) etp BIF__ARGS[2]
[].

However #Port<0.4984663> does not exist: 
I listed all ports using etp-ports, and there is no Port <0.4984663> in erts_ports table! Could it be a race condition, i.e. port has been closed and removed from the table?
I guess it was TCP (SSL) port (tcp_inet).

How do I list contents of #HeapBinary?

Update: so I went ahead and did this:
(gdb) set $port_index = ((HUint)BIF__ARGS[0]).hval[1]
(gdb) set $port_address = (Port*)(erts_port.r.o.tab[$port_index])
(gdb) p $port_address
$46 = (struct _erl_drv_port *) 0x0

Indeed, this port has been deleted from ports table somehow.

[OTP-Maintainer]

lukas said:

The contents of the binary should be what is printed in the dump, i.e. Size = 0x17 bytes, payload = 0x18140000,0xd8c84f91,0x1fc33bd7

Can you do a etp-port-info on the "prt" value that is in the argument list? Ports live on for a short while after they have been removed from the port table, so just because it is not in the table does not mean that it is dead.

[OTP-Maintainer]

dane said:

(gdb) etp-port-info $rbx
  Port: #Port<0.4984663>
  Name: tcp_inet
  State: free port-specific-lock
  Scheduler flags: exited GARBAGE
  Connected: <0.7156.1311>
  Pointer: (Port *) 0x9c9332d18

{code:java}
(gdb) p *((Port *) 0x9c9332d18)
$3 =
{
  common =
  {
    id = 9142134322034039,
    refc = {atmc = {counter = 1}, sint = 1},
    tracer = 18446744073709551611,
    trace_flags = 0,
    timer = {counter = 0},
    u =
    {
      alive = {started_interval = 109663846, reg = 0x4edaa0, links = 0x9c9332d18, monitors = 0x843183c48},
      release = {later = 109663846, func = 0x4edaa0 < release_port>, data = 0x9c9332d18, next = 0x843183c48}
    }
  },

  sched =
  {
    next = 0x0,
    taskq =
    {
      local = {busy = {first = 0x0, last = 0x0, table = 0x0, nosuspend = 0x0}, first = 0x0},
      in = {first = 0x0, last = 0x0}, bpq = 0x9c9332f20},
      flags = {counter = 2056},
      mtx = {mtx = {pt_mtx = 0x860c3e510}}
  },

  timeout_task = {counter = 0},
  lock = 0x9c9332f38,
  xports = 0x0,
  run_queue = {counter = 35634971200},
  connected = {counter = 35148776087338819},
  caller = 18446744073709551611,
  data = {counter = 0},
  bytes_in = 0,
  bytes_out = 4683, 
  ioq = 
  {
    size = 0, v_start = 0x0, v_end = 0x0, v_head = 0x0, 
    v_tail = 0x0, v_small = 
    {
      {iov_base = 0x9c92e7a40, iov_len = 0}, 
      {iov_base = 0x52800000001, iov_len = 0}, {iov_base = 0x13000000003, iov_len = 0}, 
      {iov_base = 0x4f80f0064807687, iov_len = 11066000177494644420}, 
      {iov_base = 0xf801f89b5f328442,iov_len = 8106501903609669379}
    }, 
    b_start = 0x0, b_end = 0x0, b_head = 0x0, b_tail = 0x0, 
    b_small = {0x0, 0x9b2f731451165986, 0x87ffaea703f801f8, 0xf80f002937957214, 0x979106fffa56c404}
  }, 
  dist_entry = 0x0, 
  name = 0x9c9332f40 "tcp_inet", 
  drv_ptr = 0x849c807d8, 
  drv_data = 42030275256, 
  os_pid = -1, 
  suspended = 0x0, 
  linebuf = 0x0, 
  state = {counter = 1280}, 
  control_flags = 0, 
  port_data_lock = 0x0, 
  psd = {counter = 0}, 
  reds = 1200, 
  async_open_port = 0x0
}
{code}

[OTP-Maintainer]

dane said:

A few more bits on it: 
actual SIGSEGV happens during atomic decrement call, 

{noformat}
0x4b9154 <erts_port_output+3636>        mov    (%rcx,%rbx,8),%rbp                                                                                                                                                                                                                                                         
0x4b9158 <erts_port_output+3640>        test   %rbp,%rbp                                                                                                                                                                                                                                                                   
0x4b915b <erts_port_output+3643>        je     0x4b91da <erts_port_output+3770>                                                                                                                                                                                                                                            
0x4b915d <erts_port_output+3645>        mov    $0xffffffffffffffff,%rax                                                                                                                                                                                                                                                    
0x4b9164 <erts_port_output+3652>        lock xadd %rax,-0x8(%rbp)                                                                                                                                                                                                                                                          
0x4b916a <erts_port_output+3658>        cmp    $0x1,%rax                                                                                                                                                                                                                                                                  
0x4b916e <erts_port_output+3662>        jne    0x4b91d7 <erts_port_output+3767>                                                                                                                                                                                                                                            
0x4b9170 <erts_port_output+3664>        lea    -0x10(%rbp),%r14
{noformat}

[OTP-Maintainer]

lukas said:

hmm, ok. So we can see that the port is in the process of being cleaned up (state = free, sflags = exited, refc > 0), but has not yet been freed (refc would be 0 if it had been). 

Is there any way that you can figure out which exact decrement it is that it fails in? From the small asm snippet that you posted I can't figure it out. If you cannot see it, could you attach a dump of the entire erts_port_output function to this case and I'll have a look.

[OTP-Maintainer]

dane said:

SIGSEGV happens in cleanup_scheduled_outputv(evp, cbin) call (io.c:2258)

{code:java}
    if (res != ERTS_PORT_OP_SCHEDULED) {
    if (drv->outputv)
        cleanup_scheduled_outputv(evp, cbin);  // <<< crashes here <<<
    else
        cleanup_scheduled_output(buf);
    return res;
    }
{code}

{code:java}
258538     if (res != ERTS_PORT_OP_SCHEDULED) {
 258539         if (drv->outputv)
 258540   4b9128:       48 8b 44 24 78          mov    0x78(%rsp),%rax
 258541   4b912d:       48 83 78 68 00          cmpq   $0x0,0x68(%rax)
 258542   4b9132:       0f 84 1d 01 00 00       je     4b9255 <erts_port_output+0xf35>
 258543   4b9138:       49 89 df                mov    %rbx,%r15
 258544 static ERTS_INLINE void
 258545 cleanup_scheduled_outputv(ErlIOVec *ev, ErlDrvBinary *cbinp)
 258546 {
 258547     int i;
 258548     /* Need to free all binaries */
 258549     for (i = 1; i < ev->vsize; i++)
 258550   4b913b:       41 8b 07                mov    (%r15),%eax
 258551   4b913e:       83 f8 02                cmp    $0x2,%eax
 258552   4b9141:       0f 8c 9e 00 00 00       jl     4b91e5 <erts_port_output+0xec5>
 258553   4b9147:       bb 01 00 00 00          mov    $0x1,%ebx
 258554   4b914c:       0f 1f 40 00             nopl   0x0(%rax)
 258555         if (ev->binv[i])
 258556   4b9150:       49 8b 4f 18             mov    0x18(%r15),%rcx
 258557   4b9154:       48 8b 2c d9             mov    (%rcx,%rbx,8),%rbp
 258558   4b9158:       48 85 ed                test   %rbp,%rbp
 258559   4b915b:       74 7d                   je     4b91da <erts_port_output+0xeba>
 258560   4b915d:       48 c7 c0 ff ff ff ff    mov    $0xffffffffffffffff,%rax
 258561 ETHR_NATMC_FUNC__(add_return_mb)(ETHR_ATMC_T__ *var, ETHR_AINT_T__ incr)
 258562 {
 258563     ETHR_AINT_T__ tmp;
 258564
 258565     tmp = incr;
 258566     __asm__ __volatile__(
 258567   4b9164:       f0 48 0f c1 45 f8       lock xadd %rax,-0x8(%rbp)                    ; <<< crashes here <<< 
 258568   4b916a:       48 83 f8 01             cmp    $0x1,%rax
 258569   4b916e:       75 67                   jne    4b91d7 <erts_port_output+0xeb7>
 258570 {
 258571     Binary *bin;
 258572     if (!dbin)
 258573         return;
 258574
 258575     bin = ErlDrvBinary2Binary(dbin);
 258576   4b9170:       4c 8d 75 f0             lea    -0x10(%rbp),%r14
{code}

I might be wrong here, but it looks like crash happens in erts_bin_release (line erl_binary.h:476) when it does erts_refc_dectest.

{noformat}
(gdb) set $iov=((ErlIOVec*)$r15)
(gdb) p *$iov
$16 = {vsize = 2, size = 23, iov = 0x843b43c08, binv = 0x843b43c28}
(gdb) p *$iov->iov
$19 = {iov_base = 0x0, iov_len = 0}
(gdb) p *$iov->binv
$18 = (ErlDrvBinary *) 0x0
{noformat}

So, it seems like it has been freed already. 

[OTP-Maintainer]

lukas said:

Interesting. I think I may have found the culprit.

Would you mind trying this branch and see if that solves the problem? https://github.com/garazdawi/otp/tree/lukas/erts/fix_outputv_port_task_cleanup

I've done some basic testing of it, but I haven't as yet written a test that triggers this scenario, so there may be some incorrect code in there.

[OTP-Maintainer]

lukas said:

I found a fault in my original fix while developing a regression test for this. The branch now contains a fixup and the test that I used to trigger the fault.

Let me know if this fix also solves the issue that you have been seeing.

[OTP-Maintainer]

dane said:

It looks stable so far. However it might take long to trigger this condition, so I'll continue monitoring it for a couple more days. 
I'm running this patchset on R20 RC2 now (and hope this patch will make it to OTP20 release)

[OTP-Maintainer]

lukas said:

Great!

No, it will not make it to OTP-20, but I'll put it out in a patch soon after on both 19.3 and 20.0.

[OTP-Maintainer]

dane said:

I can now confirm that it was the root cause. And it's been fixed by the patch.
Thanks for your help!

It's really unfortunate that the fix won't get into OTP R20 release. VM crash seems rather major issue.

[OTP-Maintainer]

lukas said:

Great! The fix (or some version of it) will be part of the OTP 20.0.1 patch to be released soon after the OTP 20 release.