Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
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
@papertigers

This comment has been minimized.

Copy link
Owner Author

papertigers commented May 9, 2013

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;
}

@papertigers

This comment has been minimized.

Copy link
Owner Author

papertigers commented May 9, 2013

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

@mranney

This comment has been minimized.

Copy link

mranney commented May 9, 2013

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

@mranney

This comment has been minimized.

Copy link

mranney commented May 9, 2013

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
@mranney

This comment has been minimized.

Copy link

mranney commented May 9, 2013

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)

@mranney

This comment has been minimized.

Copy link

mranney commented May 9, 2013

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 ]

@mranney

This comment has been minimized.

Copy link

mranney commented May 9, 2013

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)

@mraleph

This comment has been minimized.

Copy link

mraleph commented May 9, 2013

@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?

@bcantrill

This comment has been minimized.

Copy link

bcantrill commented May 10, 2013

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.

@ghost

This comment has been minimized.

Copy link

ghost commented May 10, 2013

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).

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.