-
-
Save papertigers/f67c1501bcbfdde947a9 to your computer and use it in GitHub Desktop.
| root@prod-2122:/home/djg# dtrace -n 'pid$target::gettimeofday:return {@[ustack()] = count()} tick-10sec {trunc(@,10); exit(0)}' -p82428 | |
| dtrace: description 'pid$target::gettimeofday:return ' matched 3 probes | |
| CPU ID FUNCTION:NAME | |
| 5 73848 :tick-10sec | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c0b7bc | |
| 0xa854e8f6 | |
| 0xb410db41 | |
| 0xb4121bb2 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69 | |
| node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x1ae | |
| node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e | |
| node`uv__read+0x53b | |
| node`uv__stream_io+0x14b | |
| 1295 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0xb4156d68 | |
| 0xb4115e89 | |
| 0x87c420ca | |
| 0xb410db41 | |
| 0xa85fe064 | |
| 0xa859ce64 | |
| 0xa85d94c9 | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0xa8546a91 | |
| 0xa85ef857 | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| 1301 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c0b7bc | |
| 0xa8552529 | |
| 0x87c489d0 | |
| 0xb410db41 | |
| 0xa8517392 | |
| 0xb410db41 | |
| 0x87c4147a | |
| 0xa85fe245 | |
| 0xa859ce64 | |
| 0xa85d94c9 | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0xa8546a91 | |
| 0xa85ef857 | |
| 1301 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xa85db19f | |
| 0x87c11ca3 | |
| 0xb4115e89 | |
| 0xa859cadc | |
| 0xa85d94c9 | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0xa8546a91 | |
| 0xa85ef857 | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535 | |
| node`http_parser_execute+0x428 | |
| node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d | |
| 1301 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xa85db19f | |
| 0x87c120b2 | |
| 0xb4115e89 | |
| 0xa859cadc | |
| 0xa85d94c9 | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0xa8546a91 | |
| 0xa85ef857 | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535 | |
| node`http_parser_execute+0x428 | |
| node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d | |
| 1301 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c4da80 | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69 | |
| node`_ZN4node10StreamWrap10AfterWriteEP10uv_write_si+0xbb | |
| node`uv__stream_io+0x350 | |
| node`ev_invoke_pending+0x63 | |
| node`uv__run+0x94 | |
| node`uv_run+0x17 | |
| node`_ZN4node5StartEiPPc+0x1c7 | |
| 1315 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c0b7bc | |
| 0x87c213ce | |
| 0xb412d408 | |
| 0xb410db41 | |
| 0x87cb9d9c | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69 | |
| node`_ZN4node7TCPWrap12OnConnectionEP11uv_stream_si+0x14b | |
| node`uv__server_io+0x9f | |
| 1315 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c0b7bc | |
| 0xa854e8f6 | |
| 0xb4121bb9 | |
| 0xb4112b4a | |
| node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101 | |
| node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9 | |
| node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0 | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e | |
| node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69 | |
| node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c | |
| node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e | |
| node`uv__read+0x28d | |
| node`uv__stream_io+0x14b | |
| node`ev_invoke_pending+0x63 | |
| 1315 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c37067 | |
| 0xa857d842 | |
| 0xa851dea4 | |
| 0xa8532f35 | |
| 0xb410db41 | |
| 0x87c4ba72 | |
| 0xb410db41 | |
| 0x87c28277 | |
| 0x87c24b30 | |
| 0x87c28a94 | |
| 0x87c16aeb | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0x87c166dd | |
| 41574 | |
| libc.so.1`gettimeofday+0x1e | |
| node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb | |
| 0xb410a336 | |
| 0xb4117759 | |
| 0xb410db41 | |
| 0xb4115e82 | |
| 0x87c36b85 | |
| 0xa857d842 | |
| 0xa851dea4 | |
| 0xa8532f35 | |
| 0xb410db41 | |
| 0x87c4ba72 | |
| 0xb410db41 | |
| 0x87c28277 | |
| 0x87c24b30 | |
| 0x87c28a94 | |
| 0x87c16aeb | |
| 0xb412d444 | |
| 0xb410db41 | |
| 0x87c166dd | |
| 41574 |
19 73896 gettimeofday:return 1368127855 937768
19 73896 gettimeofday:return 1368127855 937778
19 73896 gettimeofday:return 1368127855 937782
19 73896 gettimeofday:return 1368127855 937792
19 73896 gettimeofday:return 1368127855 937797
19 73896 gettimeofday:return 1368127855 937805
19 73896 gettimeofday:return 1368127855 937810
19 73896 gettimeofday:return 1368127855 937819
19 73896 gettimeofday:return 1368127855 937824
19 73896 gettimeofday:return 1368127855 937834
19 73896 gettimeofday:return 1368127855 937839
19 73896 gettimeofday:return 1368127855 937849
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949003025
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949003141
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949003709
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949003825
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949082053
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949082169
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949089177
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949091845
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949091961
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949092653
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949092769
21 3819 _ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE:return 2949093077
root@prod-2122:/home/djg# dtrace -x ustackframes=100 -x jstackstrsize=2048 -n 'pid$target::gettimeofday:return {@[jstack()] = count()} tick-10sec {trunc(@,10); exit(0)}' -p82428
dtrace: description 'pid$target::gettimeofday:return ' matched 3 probes
CPU ID FUNCTION:NAME
1 73848 :tick-10sec
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as exports.active at timers.js position 9406
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
37
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as exports.active at timers.js position 9406
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
417
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
afterWrite at net.js position 27224
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap10AfterWriteEP10uv_write_si+0xbb
node`uv__stream_io+0x350
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
427
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
HeaderSet at position 4628
<< constructor >>
(anon) as Client.send_header at position 6390
<< adaptor >>
filter_func at line 444
new_client at position 23886
new_client_wrapper at position 20368
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
(anon) as parser.onIncoming at http.js position 95660
parserOnHeadersComplete at http.js position 4858
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535
node`http_parser_execute+0x428
node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d
<< internal code >>
(anon) as socket.ondata at http.js position 92380
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
472
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as exports.active at timers.js position 9406
(anon) as Socket._write at net.js position 24412
(anon) as Socket.write at net.js position 22070
<< adaptor >>
(anon) as OutgoingMessage.end at http.js position 40310
<< adaptor >>
(anon) as Client.res_end at position 12110
filter_func at line 444
new_client at position 23886
new_client_wrapper at position 20368
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
(anon) as parser.onIncoming at http.js position 95660
parserOnHeadersComplete at http.js position 4858
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535
node`http_parser_execute+0x428
node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d
<< internal code >>
(anon) as socket.ondata at http.js position 92380
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
472
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
now at native date.js line 314
Client at position 1938
<< constructor >>
new_client at position 23886
new_client_wrapper at position 20368
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
(anon) as parser.onIncoming at http.js position 95660
parserOnHeadersComplete at http.js position 4858
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535
node`http_parser_execute+0x428
node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d
<< internal code >>
(anon) as socket.ondata at http.js position 92380
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
472
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
now at native date.js line 314
Client at position 1938
<< constructor >>
new_client at position 23886
new_client_wrapper at position 20368
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
(anon) as parser.onIncoming at http.js position 95660
parserOnHeadersComplete at http.js position 4858
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node6Parser19on_headers_completeEP11http_parser+0x535
node`http_parser_execute+0x428
node`_ZN4node6Parser7ExecuteERKN2v89ArgumentsE+0x23d
<< internal code >>
(anon) as socket.ondata at http.js position 92380
onread at net.js position 17666
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node10StreamWrap12OnReadCommonEP11uv_stream_si8uv_buf_t14uv_handle_type+0x10c
node`_ZN4node10StreamWrap6OnReadEP11uv_stream_si8uv_buf_t+0x2e
node`uv__read+0x28d
node`uv__stream_io+0x14b
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
472
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as ExponentiallyDecayingSample.update at position 2970
local_update at line 181
process_metric at line 247
metric_split at line 314
<< adaptor >>
forEach at native array.js line 1062
<< adaptor >>
handle_dgram_block at line 294
dgram_block_ring at line 502
filter_func at line 477
new_client_wrapper at line 54
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
onMessage at dgram.js position 17038
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node7UDPWrap6OnRecvEP8uv_udp_si8uv_buf_tP8sockaddrj+0xfd
node`uv__udp_recvmsg+0x131
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
626
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as ExponentiallyDecayingSample.update at position 2970
local_update at line 181
process_metric at line 247
metric_split at line 314
<< adaptor >>
forEach at native array.js line 1062
<< adaptor >>
handle_dgram_block at line 294
dgram_block_ring at line 502
filter_func at line 477
new_client_wrapper at line 54
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
onMessage at dgram.js position 17038
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node7UDPWrap6OnRecvEP8uv_udp_si8uv_buf_tP8sockaddrj+0xfd
node`uv__udp_recvmsg+0x131
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
667
libc.so.1`gettimeofday+0x1e
node`_ZN2v88internal23Runtime_DateCurrentTimeENS0_9ArgumentsEPNS0_7IsolateE+0xb
<< internal code >>
0xb4117759
<< adaptor >>
<< constructor >>
(anon) as exports.active at timers.js position 9406
connectionListener at http.js position 90014
(anon) as EventEmitter.emit at events.js line 54
<< adaptor >>
onconnection at net.js position 48958
<< internal >>
<< entry >>
node`_ZN2v88internalL6InvokeEbNS0_6HandleINS0_10JSFunctionEEENS1_INS0_6ObjectEEEiPS5_Pb+0x101
node`_ZN2v88internal9Execution4CallENS0_6HandleINS0_6ObjectEEES4_iPS4_Pbb+0xc9
node`_ZN2v88Function4CallENS_6HandleINS_6ObjectEEEiPNS1_INS_5ValueEEE+0xf0
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_8FunctionEEEiPNS1_INS0_5ValueEEE+0x11e
node`_ZN4node12MakeCallbackEN2v86HandleINS0_6ObjectEEENS1_INS0_6StringEEEiPNS1_INS0_5ValueEEE+0x69
node`_ZN4node7TCPWrap12OnConnectionEP11uv_stream_si+0x14b
node`uv__server_io+0x9f
node`ev_invoke_pending+0x63
node`uv__run+0x94
node`uv_run+0x17
node`_ZN4node5StartEiPPc+0x1c7
node`main+0x1b
node`_start+0x83
1328
mjr@prod-2122:/usr/include$ sudo rc /tmp/repl/prod-metricsserver4.sock
prod-metricsserver4> Date.now()
1368131764224
prod-metricsserver4> Date.now()
1368131764224
prod-metricsserver4> Date.now()
1368131764224
prod-metricsserver4> Date.now().toString()
'1368131764224'
prod-metricsserver4> Date.now().toString()
'1368131764224'
prod-metricsserver4> Date.now().toString()
'1368131764224'
prod-metricsserver4> new Date()
Thu May 09 2013 20:36:04 GMT+0000 (UTC)
prod-metricsserver4> new Date()
Thu May 09 2013 20:36:04 GMT+0000 (UTC)
prod-metricsserver4> new Date()
Thu May 09 2013 20:36:04 GMT+0000 (UTC)
prod-metricsserver4> process.hrtime()
[ 20531491, 624143996 ]
prod-metricsserver4> process.hrtime()
[ 20531492, 286370927 ]
prod-metricsserver4> process.hrtime()
[ 20531492, 905814251 ]
prod-metricsserver4> process.hrtime()
[ 20531494, 267203146 ]
prod-metricsserver4> process.hrtime()
[ 20531494, 896810616 ]
prod-metricsserver4> process.hrtime()
[ 20531495, 830449028 ]
prod-metricsserver4> new Date()
Thu May 09 2013 20:53:32 GMT+0000 (UTC)
prod-metricsserver4> new Date()
Thu May 09 2013 20:55:43 GMT+0000 (UTC)
prod-metricsserver4> new Date()
Thu May 09 2013 20:57:54 GMT+0000 (UTC)
prod-metricsserver4> new Date()
Thu May 09 2013 21:00:06 GMT+0000 (UTC)
@mranney: I should note that when you traced gettimeofday (one of gists above) it returned values different only in usec part. did you actually see it returnning different values in sec part if you call Date.now two times >1s apart?
I looked at all threads across our entire cloud (all DCs); essentially all threads have one of two values in the lower nibble of the top byte of the FP control word:
- 0x2 (precision control set to 53-bit; rounding set to round-to-nearest)
- 0x3 (precision control set to 64-bit; rounding set to round-to-nearest)
These two values account for 1.4 million threads. There are six threads (in six different processes) that do not have these values, but rather have one of two other values:
- 0xc (precision control set to 24-bit; rounding control set to truncate)
- 0x7 (precision control set to 64-bit; rounding control set to round-down)
Of these, there is exactly one process with (the entirely wrong) 0xc (namely, the process with the misbehaving Date.now() that initiated this investigation), and five with (the correct-but-odd) 0x7. Of these, they are (1) on five different physical machines (2) all node processes (3) all linked with the hiredis.node add-on and (4) all from Voxer. It's not clear that all of these are relevant, but it seems that at least one of these observations is likely germane.
So at this point, it seems highly unlikely that this is an OS bug or some other misrestore of the FP control word; the most likely root cause seems to be stack corruption (or other logic error) in either V8 or hiredis.node; more investigation is required.
Looking at hiredis.node's text, we have:
FE850000 40K r-x-- /voxer/deploy/server/node_modules/hiredis/build/Release/hiredis.node
FE869000 8K rwx-- /voxer/deploy/server/node_modules/hiredis/build/Release/hiredis.node
FE870000 64K rwx-- [ anon ]
> d9::ugrep -a fe850000 -A fe880000 -s 1 | ::dis -n 2 -a -w
fe850ce0 flds 0x0
fe850ce6 addb %al,(%eax)
fe850ce8 addb %al,(%eax)
fe854cd9 fsts 0x1(%ecx)
fe854cdc addb %cl,0x8b0c2444(%ecx)
fe854ce2 incl %ebp
fe855012 fprem
fe855014 ***ERROR--unknown op code***
fe855016 movl %eax,0xc(%esp)
fe855043 fprem
fe855045 ***ERROR--unknown op code***
fe855047 movl %eax,0xc(%esp)
fe855075 fprem
fe855077 ***ERROR--unknown op code***
fe855079 movl %eax,0xc(%esp)
fe856043 fcos
fe856045 loopz -0x75 <hiredis.node`redisReaderGetReply+0x3e2>
fe856047 decl %ebp
fe856b51 fldenv -0x41(%esi)
fe856b54 addl %eax,(%eax)
fe856b56 jmp -0x10b <hiredis.node`redisvFormatCommand+0x390>
fe856d50 fldenv -0x42(%esi)
fe856d53 addl %eax,(%eax)
fe856d55 jmp -0x597 <hiredis.node`redisvFormatCommand+0x103>
fe856f99 fldenv -0x42(%esi)
fe856f9c addl %eax,(%eax)
fe856f9e jmp -0x13b <hiredis.node`redisFormatCommandArgv+0x88>
fe856fc1 fldenv -0x42(%esi)
fe856fc4 addl %eax,(%eax)
fe856fc6 jmp -0x1c1 <hiredis.node`redisFormatCommandArgv+0x2a>
fe857fd7 fnstcw 0x558bffff(%edx)
fe857fdd inb $0x80
fe857fdf cmpb (%eax),%al
fe858a23 fcos
fe858a25 loopz -0x77 <hiredis.node`sdssplitargs+0xe0>
fe858a27 divb (%ecx)
fe858ae3 fcos
fe858ae5 loopz -0x3a <hiredis.node`sdssplitargs+0x1dd>
fe858ae7 incl %ebp
Given the interpretation of the surrounding instructions assuming that the instruction beginning with d9 is actually an fldcw or otherwise valid, it's clear that none of these is actually a valid fldcw. Therefore it appears that hiredis.node is exonerated, at least directly. The three possible calls to fldenv look plausible, but upon further inspection are not the actual instructions in those functions. This does however serve as a reminder that fldcw is not the only way this could occur; fldenv is also possible, though it also begins with d9.
There is also the libm function fesetprec(3m), which if called could cause this to occur directly. However, the core contains no text with undefined references to this function (i.e., it's not being called).
dtrace:::BEGIN { printf("Tracing gettimeofday() on PID %d..\n", $target); }
pid$target::gettimeofday:entry
{
self->tp = arg0;
}
pid$target::gettimeofday:return
/self->tp/
{
this->timeval = (struct timeval32 _)copyin(self->tp, sizeof(struct timeval32));
/_this->ms = ((this->timeval->tv_sec * 1000) + (this->timeval->tv_usec / 1000));
printf("%d\n", this->ms);
*/
printf("%d %d", this->timeval->tv_sec, this->timeval->tv_usec);
self->tp = 0;
}