Segfault during StreamWrap's slab alloc

[ry]

Experienced with 0.6.7-pre f3da6c6

#0  0x0000000000596b14 in v8::Object::GetIndexedPropertiesExternalArrayDataLength() ()
#1  0x000000000055270f in node::Buffer::Length (handle=<value optimized out>, suggested_size=65536)
    at ../src/node_buffer.h:80
#2  node::Buffer::Length (handle=<value optimized out>, suggested_size=65536) at ../src/node_buffer.h:84
#3  node::StreamWrap::NewSlab (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:156
#4  node::StreamWrap::OnAlloc (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:186
#5  0x00000000008001a3 in uv__read (stream=0x284bb90) at src/unix/stream.c:530
#6  0x0000000000800a12 in uv__stream_io (loop=0xc42120, watcher=0x284bc08, revents=1) at src/unix/stream.c:697
#7  0x0000000000806d32 in ev_invoke_pending (loop=0xc42120) at src/unix/ev/ev.c:2143
#8  0x0000000000807af6 in ev_run (loop=0xc42120, flags=0) at src/unix/ev/ev.c:2519
#9  0x00000000007f6eb7 in uv_run (loop=0xc41e00) at src/unix/core.c:200
#10 0x0000000000538527 in node::Start (argc=<value optimized out>, argv=0x27ef760) at ../src/node.cc:2650
#11 0x00007f6f52098c4d in __libc_start_main (main=<value optimized out>, argc=<value optimized out>, 
    ubp_av=<value optimized out>, init=<value optimized out>, fini=<value optimized out>, 
    rtld_fini=<value optimized out>, stack_end=0x7fff25689578) at libc-start.c:226
#12 0x0000000000533e89 in _start ()

cc @mranney @dannycoates

[ry]

Looking at the core dumps

(gdb) f 3
#3  node::StreamWrap::NewSlab (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:156
156   assert(Buffer::Length(b) == SLAB_SIZE);
(gdb) print b
$2 = <value optimized out>
(gdb) disassemble 
Dump of assembler code for function _ZN4node10StreamWrap7OnAllocEP11uv_handle_sm:
   [...]
   0x00000000005526e0 <+192>:   mov    edi,0x100000
   0x00000000005526e5 <+197>:   mov    r15,QWORD PTR [rbx+0x8]
   0x00000000005526e9 <+201>:   call   0x53c900 <_ZN4node6Buffer3NewEm>
   0x00000000005526ee <+206>:   mov    rdx,QWORD PTR [rax+0x8]
   0x00000000005526f2 <+210>:   mov    rsi,QWORD PTR [rip+0x6eab07]        # 0xc3d200 <_ZN4nodeL8slab_symE>
   0x00000000005526f9 <+217>:   mov    rbp,rax
   0x00000000005526fc <+220>:   mov    rdi,QWORD PTR [rsp+0x8]
   0x0000000000552701 <+225>:   call   0x587040 <_ZN2v86Object14SetHiddenValueENS_6HandleINS_6StringEEENS1_INS_5ValueEEE>
   0x0000000000552706 <+230>:   mov    rdi,QWORD PTR [rbp+0x8]
   0x000000000055270a <+234>:   call   0x596b10 <_ZN2v86Object43GetIndexedPropertiesExternalArrayDataLengthEv>
=> 0x000000000055270f <+239>:   cmp    eax,0x100000
   0x0000000000552714 <+244>:   jne    0x55280a <_ZN4node10StreamWrap7OnAllocEP11uv_handle_sm+490>
   [...]

corresponds to https://github.com/joyent/node/blob/f3da6c6c045fb9d629509cea53e3631342f785d3/src/stream_wrap.cc#L154-156 $rbp contains the buffer b.

(gdb) p *(Buffer*)$rbp
$1 = {<node::ObjectWrap> = {_vptr.ObjectWrap = 0x2269ba0, handle_ = {<v8::Handle<v8::Object>> = {
        val_ = 0x0}, <No data fields>}, refs_ = 0}, 
  static constructor_template = {<v8::Handle<v8::FunctionTemplate>> = {val_ = 0x226c7e0}, <No data fields>}, 
  length_ = 0, data_ = 0x0, callback_ = 0, callback_hint_ = 0x0}

It seems that length_ , data_ and handle_.val_ are zeroed out. It's the same in the rest of the core files. I suspect that the Buffer's destructor has been called https://github.com/joyent/node/blob/f3da6c6c045fb9d629509cea53e3631342f785d3/src/node_buffer.cc#L200-202

It may be that the buffer is getting GCed very quickly and that is causing the error. As it is just constructed there are no references to it and the weak callback will be made if a GC occurs. This is bad.

I think @postwait informed me of this problem about 6 months ago but I ignored it because nothing in my house was burning. Should not have ignored.

[mrb]

Did this happen randomly or with specific code? This is relevant to #2468, @bnoordhuis mentioned porting the stream_wrap slab allocator to udp_wrap. I actually got this mostly working on my fork locally but I'm curious as to what causes the above segfault. Seems like 0.6.x needs some serious work to unify and harden slab allocation.

[ry]

@mrb It's probably not relevant if my theory is correct. It's a general problem with buffers

[mrb]

Sorry, I meant it WILL be relevant if the slab allocator makes its way to the UDP side. @ry Can we try to force heap compaction in the case of buffer-caused fragmentation?

[ry]

@mrb Buffers aren't on the V8 heap - so it can't be compacted. Let's talk on IRC or on #2468.

[mrb]

@ry Ah, derp. I'll catch you on IRC in a bit.

[bnoordhuis]

I can sometimes reproduce this with make test when it tries to run simple/test-process-kill-null

(gdb) bt           
#0  0x0000000000596954 in v8::Object::GetIndexedPropertiesExternalArrayDataLength() ()
#1  0x00000000005526ff in node::Buffer::Length (handle=<value optimized out>, suggested_size=65536) at ../src/node_buffer.h:80
#2  node::Buffer::Length (handle=<value optimized out>, suggested_size=65536) at ../src/node_buffer.h:84
#3  node::StreamWrap::NewSlab (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:156
#4  node::StreamWrap::OnAlloc (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:186
#5  0x00000000007fffe3 in uv__read (stream=0x26603b0) at src/unix/stream.c:530
#6  0x0000000000800852 in uv__stream_io (loop=0xc42120, watcher=0x2660428, revents=1) at src/unix/stream.c:697
#7  0x0000000000806b92 in ev_invoke_pending (loop=0xc42120) at src/unix/ev/ev.c:2143
#8  0x0000000000807956 in ev_run (loop=0xc42120, flags=0) at src/unix/ev/ev.c:2519
#9  0x00000000007f6cf7 in uv_run (loop=0xc41e00) at src/unix/core.c:200
#10 0x00000000005384e7 in node::Start (argc=<value optimized out>, argv=0x2640760) at ../src/node.cc:2654
#11 0x00002b4cef58ac4d in __libc_start_main (main=<value optimized out>, argc=<value optimized out>, ubp_av=<value optimized out>, init=<value optimized out>, fini=<value optimized out>, rtld_fini=<value optimized out>, stack_end=0x7fff7ac7b768) at libc-start.c:226
#12 0x0000000000533e29 in _start ()

(gdb) bt f
#0  0x0000000000596954 in v8::Object::GetIndexedPropertiesExternalArrayDataLength() ()
No symbol table info available.
#1  0x00000000005526ff in node::Buffer::Length (handle=<value optimized out>, suggested_size=65536) at ../src/node_buffer.h:80
No locals.
#2  node::Buffer::Length (handle=<value optimized out>, suggested_size=65536) at ../src/node_buffer.h:84
No locals.
#3  node::StreamWrap::NewSlab (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:156
        b = <value optimized out>
#4  node::StreamWrap::OnAlloc (handle=<value optimized out>, suggested_size=65536) at ../src/stream_wrap.cc:186
        wrap = 0x2660380
        __PRETTY_FUNCTION__ = "static uv_buf_t node::StreamWrap::OnAlloc(uv_handle_t*, size_t)"
        slab = <value optimized out>
        scope = {
          isolate_ = 0x26371a0, 
          prev_next_ = 0x2670320, 
          prev_limit_ = 0x2672050, 
          is_closed_ = false
        }
        slab_v = <value optimized out>
#5  0x00000000007fffe3 in uv__read (stream=0x26603b0) at src/unix/stream.c:530
        buf = {
          base = 0x4146476f2171522a <Address 0x4146476f2171522a out of bounds>, 
          len = 12827240
        }
        nread = 8421523
        msg = {
          msg_name = 0x40, 
          msg_namelen = 0, 
          msg_iov = 0x7fff7ac7b4a0, 
          msg_iovlen = 8399828, 
          msg_control = 0x40, 
          msg_controllen = 40303808, 
          msg_flags = 2059908304
        }
        cmsg = 0x7fff7ac7b500
        cmsg_space = "h\272\303\000\000\000\000\000 !\304\000\000\000\000\000`\000\000\000\000\000\000\000 !\304\000\000\000\000\000\060\265\307z\377\177\000\000\025z\177\000\000\000\000\000\210\023\000\000\000\000\000\000\210\023\000\000\000\000\000"
        ev = 0xc42120
        __PRETTY_FUNCTION__ = "uv__read"
#6  0x0000000000800852 in uv__stream_io (loop=0xc42120, watcher=0x2660428, revents=1) at src/unix/stream.c:697
        stream = 0x26603b0
        __PRETTY_FUNCTION__ = "uv__stream_io"
#7  0x0000000000806b92 in ev_invoke_pending (loop=0xc42120) at src/unix/ev/ev.c:2143
        p = 0x266f910
        pri = 2
#8  0x0000000000807956 in ev_run (loop=0xc42120, flags=0) at src/unix/ev/ev.c:2519
        __PRETTY_FUNCTION__ = "ev_run"
#9  0x00000000007f6cf7 in uv_run (loop=0xc41e00) at src/unix/core.c:200
No locals.
#10 0x00000000005384e7 in node::Start (argc=<value optimized out>, argv=0x2640760) at ../src/node.cc:2654
        handle_scope = {
          isolate_ = 0x26371a0, 
          prev_next_ = 0x0, 
          prev_limit_ = 0x0, 
          is_closed_ = false
        }
#11 0x00002b4cef58ac4d in __libc_start_main (main=<value optimized out>, argc=<value optimized out>, ubp_av=<value optimized out>, init=<value optimized out>, fini=<value optimized out>, rtld_fini=<value optimized out>, stack_end=0x7fff7ac7b768) at libc-start.c:226
        result = <value optimized out>
        unwind_buf = {
          cancel_jmp_buf = {{
              jmp_buf = {0, 7397026626989898184, 5455360, 140735253297008, 0, 0, -7396756626246026808, 3476315158803298760}, 
              mask_was_saved = 0
            }}, 
          priv = {
            pad = {0x0, 0x0, 0x81d3a0, 0x7fff7ac7b778}, 
            data = {
              prev = 0x0, 
              cleanup = 0x0, 
              canceltype = 8508320
            }
          }
        }
        not_first_call = <value optimized out>
#12 0x0000000000533e29 in _start ()
No symbol table info available.

[ry]

@mranney, @dannycoates : please test this patch https://gist.github.com/1585672

[mranney]

Is there any expected performance impact?

[ry]

@mranney, no