This document describes the root cause investigation for the core dump available in Manta at /trent.mick/public/bugs/oneachnodecrash/core.node.46811.
The program that the dumped process was running seems to be a 32bits node binary:
[root@headnode (coal) ~]# pargs /var/tmp/trent-sdconeachnode-core
core '/var/tmp/trent-sdconeachnode-core' of 46811: /zones/f26d87e2-f7bf-48b9-bf74-be2dc9e421aa/root/opt/smartdc/sdc/build/node/bin
argv[0]: /zones/f26d87e2-f7bf-48b9-bf74-be2dc9e421aa/root/opt/smartdc/sdc/build/node/bin/node
argv[1]: /zones/f26d87e2-f7bf-48b9-bf74-be2dc9e421aa/root/opt/smartdc/sdc/lib/sdc-oneachnode.js
argv[2]: -n
argv[3]: 564dd6c4-bea3-c59c-fbd9-02536df17513
argv[4]: /usr/sbin/vmadm reprovision f26d87e2-f7bf-48b9-bf74-be2dc9e421aa <<< '{"image_uuid":"33c369f6-3e55-11e6-8b0a-ffff48ffdb53"}'
[root@headnode (coal) ~]# file /zones/$(vmadm lookup -1 alias=sdc0)/root/opt/smartdc/sdc/build/node/bin/node
/zones/aa069796-a0fd-4949-9a0e-7b7abb7ea840/root/opt/smartdc/sdc/build/node/bin/node: ELF 32-bit LSB executable 80386 Version 1, dynamically linked, not stripped
[root@headnode (coal) ~]# file /var/tmp/trent-sdconeachnode-core
/var/tmp/trent-sdconeachnode-core: ELF 32-bit LSB core file 80386 Version 1, from 'node'
The process terminated due to a SIGBUS delivered to it:
[root@headnode (coal) ~]# mdb /zones/aa069796-a0fd-4949-9a0e-7b7abb7ea840/root/opt/smartdc/sdc/build/node/bin/node /var/tmp/trent-sdconeachnode-core
mdb: core file data for mapping at 8050000 not saved: I/O error
mdb: core file data for mapping at 8ee1000 not saved: I/O error
mdb: core file data for mapping at fead0000 not saved: I/O error
mdb: core file data for mapping at fec40000 not saved: I/O error
Loading modules: [ libumem.so.1 libc.so.1 ld.so.1 ]
> ::status
debugging core file of node (32-bit) from headnode0
file: /zones/aa069796-a0fd-4949-9a0e-7b7abb7ea840/root/opt/smartdc/sdc/build/node/bin/node
initial argv: /zones/f26d87e2-f7bf-48b9-bf74-be2dc9e421aa/root/opt/smartdc/sdc/build/node/bin
threading model: native threads
status: process terminated by SIGBUS (Bus Error), addr=844ed80
And the cause of the SIGBUS seems to be a page fault (%trapno = 0xe):
> ::regs
%cs = 0x0043 %eax = 0x08f6b1f8
%ds = 0x004b %ebx = 0x08f0b008
%ss = 0x004b %ecx = 0x0804371c
%es = 0x004b %edx = 0xfed32a40
%fs = 0x0000 %esi = 0x08f6b4b8
%gs = 0x01c3 %edi = 0x08043728
%eip = 0x0844ed80 _ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE
%ebp = 0x08043748
%kesp = 0x00000000
%eflags = 0x00210293
id=1 vip=0 vif=0 ac=0 vm=0 rf=1 nt=0 iopl=0x0
status=<of,df,IF,tf,SF,zf,AF,pf,CF>
%esp = 0x080436ec
%trapno = 0xe
%err = 0x14
I don't know what %err = 0x14 means? Is that the content of the "error code" that is supposed to be pushed on the stack by the CPU?
Trying to take a look at what's in %esp:
> 0x080436ec/X
0x80436ec: 84055a8
> 0x080436ec,4/B
0x80436ec: a8 55 40 8
It seems that the LSB of that register has the value 8, which is different from the value of %err, which would mean that either one of %err and the value at %esp could be the value of the "error code".
The value of the content at %esp (8, so fourth bit set to 1 and every other relevant bits set to 0) would indicate according to Intel Architecure Software Manual Volume 3 that:
- The fault was caused by a non-present page.
- The access causing the fault was a read.
- The access causing the fault originated when the processor was executing in supervisor mode
- The fault was caused by reserved bits set to 1 in a page directory
The value of %err (0x14, so 3rd bit set to 1 and every other relevant bits else set to 0) would indicate according to the same manual that:
- The fault was caused by a non-present page.
- The access causing the fault was a read.
- The access causing the fault originated when the processor was executing in user mode.
- The fault was not caused by reserved bit violation.
Since this core file was generated by a user program, it doesn't seem to make sense that the process was executing in supervisor mode, so I would think the correct error code for that trap was 0x14, and that it indicated the fault was caused by a reading a non-present page.
Looking at what code was executing when that fault happened:
> ::stacks
THREAD STATE SOBJ COUNT
1 UNPARKED <NONE> 1
_ZN4node13SlabAllocator8AllocateEN2v86HandleINS1_6ObjectEEEj+0x6d
_ZN4node10StreamWrap7OnAllocEP11uv_handle_sj+0x5c
uv__read+0x61
uv__stream_io+0x149
uv__io_poll+0x2a1
uv_run+0xda
_ZN4node5StartEiPPc+0x189
main+0x1b
_start+0x83
2 PARKED CV 1
libc.so.1`sema_wait+0x19
libc.so.1`sem_wait+0x35
_ZN2v88internal16SolarisSemaphore4WaitEv+0x15
_ZN2v88internal15RuntimeProfiler27WaitForSomeIsolateToEnterJSEv+0x5b
_ZN2v88internal12SignalSender3RunEv+0x3d
_ZN2v88internalL11ThreadEntryEPv+0x21
libc.so.1`_thrp_setup+0x88
libc.so.1`_lwp_start
> $C
08043748 _ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE(8f6b4b8, 8f6b1f8, 8f6b208, b4029700, 8f54130, 8f54134)
08043798 _ZN4node13SlabAllocator8AllocateEN2v86HandleINS1_6ObjectEEEj+0x6d(8f16e68, 8f6b4b8, 10000, 10000, 0, 5)
080437c8 _ZN4node10StreamWrap7OnAllocEP11uv_handle_sj+0x5c(8043808, 8f3a210, 10000, 10000, 8f0b008, b4008091)
08043998 uv__read+0x61(8f50fa8, 0, 4, 80439d8, 80439dc, 1)
080439f8 uv__stream_io+0x149(8ef3d60, 8f3a248, 1, 0, 8047a54, 8043b8c)
08047a78 uv__io_poll+0x2a1(8ef3d60, ea5d, f4240, 0, 8ef3d78, 0)
08047ab8 uv_run+0xda(8ef3d60, 0, 8047b5c, 0, 7d, 8f17dc8)
08047b18 _ZN4node5StartEiPPc+0x189(5, 8047b5c, 133f, 1f80, 8047b1c, fe9ec6e8)
08047b38 main+0x1b(5, 8047b5c, 8047b74, 8282db0, 0, 0)
08047b50 _start+0x83(5, 8047c60, 8047cb5, 8047d0c, 8047d0f, 8047d34)
At first, it seems surprising that only two threads were running:
* Node usually starts at least 4 additional threads for libuv (the threads that are part of libuv's thread pool to run filesystem I/O, name lookup, etc.)
* V8 itself uses multiple threads for implementing type feedback and code optimization, among other things
In other words, I would have expected to see a number of threads closer to 6 threads.
Actually, generating a core dump on purpose using the same binary used by sdc-oneach node also generates a core dump with only two threads:
[root@headnode (coal) ~]# /zones/$(vmadm lookup -1 alias=sdc0)/root/opt/smartdc/sdc/build/node/bin/node -e 'setTimeout(function dumpCore() {process.abort()}, 1000)'
[root@headnode (coal) ~]# /zones/aa069796-a0fd-4949-9a0e-7b7abb7ea840/root/opt/smartdc/sdc/build/node/bin/node -e 'setTimeout(function dumpCore() {process.abort()}, 1000)'
Abort (core dumped)
[root@headnode (coal) ~]# ls -lt /cores/
total 149577
-rw------- 1 root root 25602513 May 30 19:04 core.node.99578
-rw------- 1 root root 24553905 May 30 19:03 core.node.99215
-rw------- 1 root root 4982841 May 29 18:33 core.varpd.1948
-rw------- 1 root root 49598901 May 27 02:04 core.vmadmd.29492
-rw------- 1 root root 27815545 May 27 02:04 core.json.16825
-rw------- 1 root root 63785093 May 27 02:02 core.node.2913
-rw------- 1 root root 27527397 May 27 02:02 core.json.15291
[root@headnode (coal) ~]# pstack /cores/core.node.99578
core '/cores/core.node.99578' of 99578: /zones/aa069796-a0fd-4949-9a0e-7b7abb7ea840/root/opt/smartdc/sdc/build
----------------- lwp# 1 / thread# 1 --------------------
fe9821b5 _lwp_kill (1, 6, 90, fe9e0000, fe9e0000, 9870a829) + 15
fe916b6b raise (6, 0, 8047620, 80476f0, 0, 0) + 2b
fe8f140e abort (8f70810, aea0fd3d, 8047718, 842adc7, 80476cc, 80476ec) + 10e
0828781b ???????? (80476cc, 80476ec, 80476f8, 84b61ba, 80476cc, 0)
0842adc7 _ZN2v88internalL21Builtin_HandleApiCallENS0_12_GLOBAL__N_116BuiltinArgumentsILNS0_21BuiltinExtraArgumentsE1EEEPNS0_7IsolateE (2, 8047740, 8f0b008, 9510a301, 8047720, 8047750) + 157
9510a376 ???????? (fe834e59, 98708bf1, 98738e85, 98738e85, fe829759, 8047794)
95148c4b ???????? (9873ddb5, 80477d8, 95147b21, 2, 9873fe19, 8047794)
95147fb4 ???????? (9873e3e9, 2, 9873c205, 10, 80477cc, 95121892)
9510e501 ???????? (0, 9873e3e9, 9873c205, 95121801, c, 0)
95121892 ???????? (0, 0, 95112fe1, 0, 0, 0)
9511308a ???????? (95147b60, 9873c205, 9873e3e9, 1, 8047a4c, d)
084474d1 _ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb (8f6ae98, 1, 8047a4c, 804790f, aea1195d, 8f53134) + 101
08448c69 _ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb (80478fc, 8f53134, 8f6ae98, 1, 8047a4c, 804790f) + c9
0840654b _ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE (804795c, 8f53134, 8f6ae98, 1, 8047a4c, 8f18dd0) + 10b
0828bf6e _ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE (80479cc, 8f6ae98, 8f53134, 1, 8047a4c, 8f53024) + 5e
0828c156 _ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE (8047a2c, 8f6ae98, 8f6ae88, 1, 8047a4c, 8047a98) + 66
081ff1a7 _ZN4node9TimerWrap9OnTimeoutEP10uv_timer_si (8f3cf08, 0, 229f8253, 8ef3d60, 8ef3d60, 0) + 67
083f03e0 uv__run_timers (8ef3d60, 951, f4240, 0, 8ef3d78, 0) + 70
083e6035 uv_run (8ef3d60, 0, 8047b78, 0, 38, 8f17f08) + 75
0828e869 _ZN4node5StartEiPPc (3, 8047b78, 133f, 1f80, 8047b2c, fe9ec6e8) + 189
0829f91b main (3, 8047b78, 8047b88, feffb0a8, 8047b6c, 81f01e2) + 1b
081f0243 _start (3, 8047c7c, 8047cd1, 8047cd4, 0, 8047d0c) + 83
----------------- lwp# 2 / thread# 2 --------------------
fe97d539 __lwp_park (8f15dcc, 0, fe7fef28, fe96372c, 8f08e9c, fe9e0000) + 19
fe970fde sema_wait (8f15dcc, 8786a08, 0, 0, 8f15dcc, 8f21f10) + 19
fe9638ed sem_wait (8f15dcc, fe7fef78, fe7fef58, 84e26ed, 84e0220, 1) + 35
08624f35 _ZN2v88internal16SolarisSemaphore4WaitEv (8f15dc8, 8262670, 8ef4c20, 9760b9, fe9e70e0, 0) + 15
0853f32b _ZN2v88internal15RuntimeProfiler27WaitForSomeIsolateToEnterJSEv (8f21f30, 0, fe7fefc8, fe9e0000, 8, 0) + 5b
08272fed _ZN2v88internal12SignalSender3RunEv (8f21f10, 3, fec702a0, fe9e0000, fe9e0000, fec70240) + 3d
08624e01 _ZN2v88internalL11ThreadEntryEPv (8f21f10, 0, 0, 0) + 21
fe97d34b _thrp_setup (fec70240) + 88
fe97d4e0 _lwp_start (fec70240, 0, 0, 0, 0, 0)
[root@headnode (coal) ~]#
Moving on, it seems that the instruction at address _ZN4node13SlabAllocator8AllocateEN2v86HandleINS1_6ObjectEEEj+0x6d was running which I thought would be the same value as the value of %eip, but it seems it's not:
> ::regs ! grep %eip
%eip = 0x0844ed80 _ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE
> 0x0844ed80::dis ! grep 0x6d
_ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE+0x6d: addb %al,(%eax)
> 0x0844ed80/i
_ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE:
_ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE: andb $0x10,%al
>
It seems it makes more sense to get a page fault from addb %al,(%eax) than from andb $0x10,%al, so I'll assume that the former is really the instruction that was being executed.
However, that instruction writes a value to an address, whereas we assumed above the error code for the page fault indicated a page read fault.
Maybe the page fault occurs because the instruction that is being executed is at a page boundary? Neither %eip (0x0844ed80) nor (%eip + 0x6d) seem to be a multiple of a "common" page size (e.g 4 * 1024).
- Does that analysis seem to be correct?
- Is it possible to get the CR registers with mdb?
What does "<esp,20/apn" show? Also, it would be good to see "_ZN2v88internal7Factory12LookupSymbolENS0_6HandleINS0_6StringEEE::dis"
A little strange that the first instruction is an andb and not push...