Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Already on GitHub? Sign in to your account

Add DTrace tracepoints for Erlang/OTP R15 or later #18

Closed
tatsuya6502 opened this Issue Feb 17, 2013 · 15 comments

Comments

Projects
None yet
1 participant
Owner

tatsuya6502 commented Feb 17, 2013

Compare the overhead for DTrace/SystemTap tracepoints (dyntrace:p/1 -- p/8) to the current one for gmt_elog. If the performance is acceptable, add DTrace/SystemTap tracepoints for Erlang/OTP R15 or later to get an unified view between Hibari, Erlang VM, and Unix/Linux kernel. (Keep gmt_elog for R13 and R14)

http://hibari.github.com/hibari-doc/hibari-contributor-guide.en.html#_hibari_internal_tracepoints

Hibari internal tracepoints
The Hibari source code has been annotated with over 400 tracepoints using
macros based on the gmt_elog.erl and gmt_elog_policy.erl modules. These
tracepoints give the developer (and even field support staff) more options
for tracing events through Hibari’s code.

The gmt_elog tracepoints are designed to be extremely lightweight. While
they can be disabled completely at compile-time, their overhead is so low
that they can remain in production code and be enabled only when needed
for debugging.

Owner

tatsuya6502 commented Feb 19, 2013

I noticed the following commit in gmt_util modified gmt_elog.hrl and deleted gmt_elog.erl.

hibari/gmt-util@e258d1d - deprecate gmt legacy components (gmt_{cli,config,config_svr,app,event_h})

gmt_elog contained utilities for Erlang dbg module to enable the tracepoints and create a report. I don't see any reason to delete gmt_elog.erl unless it was broken. I'll see if it's still useful on Erlang R15B03-1 when I debug hibari/gdss-brick#2

@tatsuya6502 tatsuya6502 was assigned Feb 23, 2013

Owner

tatsuya6502 commented Feb 24, 2013

I tried gmt_elog module for debugging. It worked great. I opened #21 and add it back to gmt_util project.

Owner

tatsuya6502 commented Mar 1, 2013

I implemented a prototype of dyntrace (DTrace/SystemTap) tracepoints. Tested with DTrace on Mac OS X 10.8.2 and SmartOS (package set http://pkgsrc.joyent.com/sdc6/2012Q2/x86_64/All). It looks good on Mac OS X. But on SmartOS, dtrace can't find the probe user_trace-i4s4 and user_trace-s1 so it can't trace dyntrace:p/{1-8} calls.

Mac OS X 10.8.2

$ uname -a
Darwin mini2012.local 12.2.1 Darwin Kernel Version 12.2.1: Thu Oct 18 12:13:47 PDT 2012; root:xnu-2050.20.9~1/RELEASE_X86_64 x86_64

$ erl
Erlang R15B03 (erts-5.9.3.1) [source] [64-bit] [smp:8:8] [async-threads:0] [kernel-poll:false] [dtrace]

Eshell V5.9.3.1  (abort with ^G)
1> 
User switch command
 --> q

$ ./tmp/hibari/bin/hibari ping
pong

$ dtrace -V
dtrace: Sun D 1.6.2

$ sudo dtrace -l -m beam.smp | wc -l
    1085

$ sudo dtrace -l -n user_trace-i4s4
   ID   PROVIDER            MODULE                          FUNCTION NAME
 9192 erlang38169          beam.smp           erl_nif_user_trace_i4s4 user_trace-i4s4

$ sudo dtrace -l -n user_trace-s1
   ID   PROVIDER            MODULE                          FUNCTION NAME
19515 erlang38169          beam.smp             erl_nif_user_trace_s1 user_trace-s1

$ cd ~/erlang/r15b03-1_dtrace/lib/runtime_tools-1.8.9/examples/
$ sudo dtrace -qs efile_drv.d
async I/O pool port #Port<0 queue len 4294967295
async I/O worker tag={4,89178} | FSTAT (5) | efile_drv-int_entry
async I/O worker tag={4,89178} | FSTAT (5) | efile_drv-int_entry
async I/O pool port #Port<0 queue len 4294967295
async I/O worker tag={4,89175} | LSEEK (3) | efile_drv-int_entry
async I/O worker tag={4,89175} | LSEEK (3) | efile_drv-int_return
async I/O pool port #Port<0 queue len 4294967295
async I/O worker tag={4,89176} | READDIR (7) | efile_drv-int_entry
async I/O worker tag={4,89176} | READDIR (7) | efile_drv-int_return
async I/O pool port #Port<0 queue len 4294967295
async I/O worker tag={4,89177} | OPEN (1) | efile_drv-int_entry
async I/O worker tag={4,89177} | OPEN (1) | efile_drv-int_return
efile_drv enter tag={4,89175}  | LSEEK (3) | args:   , 20 0 (port #Port<0.17538>)
async I/O pool port #Port<0 queue len 4294967295
efile_drv return tag={4,89175}  | LSEEK (3) ok
efile_drv enter tag={4,89176}  | READDIR (7) | args: data/brick/hlog.commonLogServer/s  , 0 0 (port #Port<0.1028>)
...
^C

$ sudo dtrace -qs user-probe.d
<0.783.0>  1 0 0 0 'brick_ets' '' 'trace' '{debug,tab1_ch2_b1,logging_op_serial,42}'
<0.783.0>  1 0 0 0 'brick_ets' '' 'trace' '{debug,tab1_ch2_b1,logging_op_q,{[],[]}}'
<0.783.0>  1 0 0 0 'brick_ets' '' 'trace' '{debug,tab1_ch2_b1,wait_on_dirty_q,{[],[]}}'
<0.783.0>  1 0 0 0 'brick_ets' '' 'trace' '{debug,tab1_ch2_b1,dirty_tab,[]}'
<0.8380.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{do_sync_writeback,end_seq_and_offset,3,12}'
...

<0.8380.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{gmt_hlog_fold2,shortterm,"data/brick/hlog.commonLogServer",[3]}'
<0.8380.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{open_log_file,"data/brick/hlog.commonLogServer",3,
               [read],
               "data/brick/hlog.commonLogServer/s/000000000003.HLOG",
               {ok,{file_descriptor,prim_file,{#Port<0.31932>,36}}}}'
<0.8380.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{fold_a_file,3,bof,12}'
<0.8380.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{fold_a_file,3,eof}'
<0.8380.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{gmt_hlog_fold2,done,3,{wb,0,[],0,[]}}'
<0.8380.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{write_back_to_local_log,empty_close,undefined}'
<0.8380.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{do_sync_writeback,counts,0,0}'
...

<0.8381.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{gmt_hlog_fold2,shortterm,"data/brick/hlog.commonLogServer",[3]}'
<0.8381.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{open_log_file,"data/brick/hlog.commonLogServer",3,
               [read],
               "data/brick/hlog.commonLogServer/s/000000000003.HLOG",
               {ok,{file_descriptor,prim_file,{#Port<0.31933>,36}}}}'
<0.8381.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{fold_a_file,3,bof,12}'
<0.8381.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{fold_a_file,3,eof}'
<0.8381.4>  8 0 0 0 'gmt_hlog' '' 'trace' '{gmt_hlog_fold2,done,3,{wb,0,[],0,[]}}'
<0.8381.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{write_back_to_local_log,empty_close,undefined}'
<0.8381.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{do_sync_writeback,counts,0,0}'
<0.8381.4>  8 0 0 0 'gmt_hlog_common' '' 'trace' '{do_sync_writeback,end_seq_and_offset,3,12}'
...

<0.677.0>  2 0 0 0 'brick_server' '' 'trace' '{do,bootstrap_copy1,
    [{get_many,<<131,100,0,15,36,115,116,97,114,116,95,111,102,95,116,97,98,
                 108,101>>,
               [{max_num,100},witness]}]}'
<0.677.0>  2 0 0 0 'brick_ets' '' 'trace' '{do,{1362,178406,331353},
    [{get_many,<<131,100,0,15,36,115,116,97,114,116,95,111,102,95,116,97,98,
                 108,101>>,
               [{max_num,100},witness]}],
    []}'
<0.677.0>  8 0 0 0 'brick_ets' '' 'trace' '{brick_ets,do,bootstrap_copy1,goahead,
           {do,{1362,178406,331353},
               [{get_many,<<131,100,0,15,36,115,116,97,114,116,95,111,102,95,
                            116,97,98,108,101>>,
                          [{max_num,100},witness]}],'
<0.677.0>  2 0 0 0 'brick_ets' '' 'trace' '{bootstrap_copy1,send_downstream}'
<0.677.0>  8 0 0 0 'brick_ets' '' 'trace' ''
<0.677.0>  32 0 0 0 'brick_server' '' 'trace' ''
<0.677.0>  32 0 0 0 'brick_server' '' 'trace' '{chain_role,bootstrap_copy1,standalone}'
...
^C

SmartOS (package set http://pkgsrc.joyent.com/sdc6/2012Q2/x86_64/All) in guest zone

$ uname -a
SunOS 2c820100-2b63-4468-b98d-a5c89c89c597.local 5.11 joyent_20130207T202554Z i86pc i386 i86pc Solaris

$ cat /opt/local/etc/pkgin/repositories.conf
http://pkgsrc.joyent.com/sdc6/2012Q2/x86_64/All

$ erl
Erlang R15B01 (erts-5.9.1) [source] [64-bit] [smp:4:4] [async-threads:0] [kernel-poll:false] [dtrace]

Eshell V5.9.1  (abort with ^G)
1> 
User switch command
 --> q

$ ./tmp/hibari/bin/hibari ping
pong

$ dtrace -V
dtrace: Sun D 1.11

$ sudo dtrace -l -m beam.smp | wc -l
132

$ sudo dtrace -l -n user_trace-i4s4
   ID   PROVIDER            MODULE                          FUNCTION NAME
dtrace: failed to match :::user_trace-i4s4: No probe matches description

$ sudo dtrace -l -n user_trace-s1
   ID   PROVIDER            MODULE                          FUNCTION NAME
dtrace: failed to match :::user_trace-s1: No probe matches description

$ cd /opt/local/lib/erlang/lib/runtime_tools-1.8.9/examples/
/opt/local/lib/erlang/lib/runtime_tools-1.8.8/examples/
$ sudo dtrace -qs efile_drv.d
dtrace: failed to compile script efile_drv.d: line 75: syntax error near "args"

$ sudo emacs efile_drv.d
$ diff efile_drv.d~ efile_drv.d
66c66
<     printf("efile_drv enter tag={%d,%d} %s%s | %s (%d) | args: %s %s , %d %d (port %s)\n",
---
>     printf("efile_drv enter tag={%d,%d} %s%s | %s (%d) | args: %s %s , %d %d\n",
72,75c72
<          arg5 == NULL ? "" : copyinstr(arg5), arg6, arg7,
<            /* NOTE: port name in args[10] is experimental */
<            (args[10] == NULL) ? 
<              "?" : copyinstr((user_addr_t) args[10]));
---
>          arg5 == NULL ? "" : copyinstr(arg5), arg6, arg7);

$ sudo dtrace -qs efile_drv.d
efile_drv enter tag={0,230308}  | LSEEK (3) | args:   , 19 0
async I/O pool port #Port<0 queue len 4294967295
async I/O pool port #Port<0 queue len 4294967295
async I/O worker tag={0,230308} | LSEEK (3) | efile_drv-int_entry
async I/O worker tag={0,230308} | LSEEK (3) | efile_drv-int_return
efile_drv return tag={0,230308}  | LSEEK (3) ok
efile_drv enter tag={3,97154}  | READDIR (7) | args: data/brick/hlog.commonLogServer/s  , 0 0
async I/O pool port #Port<0 queue len 4294967295
async I/O pool port #Port<0 queue len 4294967295
...
^C

$ sudo dtrace -qs user-probe.d
dtrace: failed to compile script user-probe.d: line 21: probe description erlang*:::user_trace-s1 does not match any probes

I installed Erlang/OTP from the binary package by pkgin in erlang. I tried to run dtrace in the global zone too but got the same result.

Owner

tatsuya6502 commented Mar 2, 2013

Pushed the implementation to the dev branch. I'll measure the performance impact to enable those tracepoints when I have more time. But I added the global switch dtrace_support in sys.config, so it shouldn't spoil the performance when disabled. I think this will be good enough for now.

Commits:

Owner

tatsuya6502 commented Mar 2, 2013

But I added the global switch dtrace_support in sys.config, so it shouldn't spoil the performance when disabled.

Oops, this wasn't true in the earlier commits. I made one more commit to address the bug.

Commit:

Owner

tatsuya6502 commented Mar 2, 2013

I think there will be time to enable 'dtrace_support' on-the-fly. The current implementation caches the config in the process dictionary forever so this cannot be done for long-live processes like brick server. Maybe it's better to invalidate the config cache every few minutes?

Owner

tatsuya6502 commented Mar 4, 2013

I have to update Hibari internal tracepoints section of Hibari Contributor’s Guide.

I think the Administrator Guide will be more appropriate for this topic but I'll leave this for the documentation rework task in Hibari v0.6.

Owner

tatsuya6502 commented Mar 4, 2013

I think there will be time to enable 'dtrace_support' on-the-fly. The current implementation caches the config in the process dictionary forever so this cannot be done for long-live processes like brick server. Maybe it's better to invalidate the config cache every few minutes?

I'll leave this for a future enhancement. It will be easy to implement such cache expiration feature, but changing sys.config file on every cluster nodes will be awkward. Hibari will need a central place to manage this kind of dynamic configurations -- perhaps, a Mnesia based config manager?

Owner

tatsuya6502 commented Mar 5, 2013

I have to update Hibari internal tracepoints section of Hibari Contributor’s Guide.

Done. Commit: hibari/hibari-doc@fc8733a

I think the Administrator Guide will be more appropriate for this topic but I'll leave this for the documentation rework task in Hibari v0.6.

In the above commit, I added "Examining Latency in Production (Internal Event Tracing)" chapter to the Administrator's Guide. That chapter contains a brief descriptions about Hibari's internal tracing mechanism and a pointer to the "Hibari internal tracepoints" secion of Hibari Contributor's Guide.

Owner

tatsuya6502 commented Mar 16, 2013

More commits.

Owner

tatsuya6502 commented Mar 18, 2013

One more commit.

hibari/gmt-util@af8f84c

hibari >> GH18 - Add DTrace tracepoints for Erlang/OTP R15 or later:

  • Update -spec for dtrace.
  • Add the microbenchmark code back.
Owner

tatsuya6502 commented Mar 19, 2013

hibari/gdss-brick@9c78aa7

hibari >> GH18 related. Reformat trace logs in brick_server module.

Owner

tatsuya6502 commented Mar 19, 2013

hibari/gdss-brick@ebc7d38

hibari >> GH18 related. Reformat trace logs in brick_hash module.

hibari/gdss-admin@e398223

hibari >> GH18 related. Reformat trace logs in brick_chainmon module.

Owner

tatsuya6502 commented Mar 27, 2013

As for SmartOS issue on this comment #18 (comment),

But on SmartOS, dtrace can't find the probe user_trace-i4s4 and user_trace-s1 so it can't trace dyntrace:p/{1-8} calls.

I found I was using older SmartOS package repo. Once I upgraded Erlang/OTP from the latest package repo, the issue was resolved.

  • SmartOS base64 1.9.1
  • package repo: 2012Q4 x86_64
  • Erlang/OTP R15B02, from the package repo
% uname -a
SunOS hibari-smartos1 5.11 joyent_20130321T213641Z i86pc i386 i86pc Solaris

% cat /opt/local/etc/pkgin/repositories.conf 
http://pkgsrc.joyent.com/packages/SmartOS/2012Q4/x86_64/All

% erl
Erlang R15B02 (erts-5.9.2) [source] [64-bit] [smp:8:8] [async-threads:0] [kernel-poll:false] [dtrace]

Eshell V5.9.2  (abort with ^G)
1> 
User switch command
 --> q

% sm-summary 
* Gathering SmartMachine summary..
SM UUID             78c849af-be16-4463-a90a-4e85bbdef5eb
SM ID               1
Hostname            hibari-smartos1
SmartOS build       joyent_20130321T213641Z 
Image               base64 1.9.1
Base Image          NA
Documentation       http://wiki.joyent.com/jpc2/SmartMachine+Base
Pkgsrc              http://pkgsrc.joyent.com/packages/SmartOS/2012Q4/x86_64/All
Processes           28
Memory (RSS) Cap    2048M
Memory (RSS) Used   134M
Memory (RSS) Free   1914M
Swap Cap            2048M
Swap Used           118M
/tmp Used           12K
Disk Quota          21G
% Disk Used         22%

% ./tmp/hibari/bin/hibari ping
pong

% dtrace -V
dtrace: Sun D 1.11

% sudo dtrace -l -m beam.smp | wc -l
1085

% sudo dtrace -l -n user_trace-i4s4
   ID   PROVIDER            MODULE                          FUNCTION NAME
 4463 erlang4623          beam.smp           erl_nif_user_trace_i4s4 user_trace-i4s4

% sudo dtrace -l -n user_trace-s1
   ID   PROVIDER            MODULE                          FUNCTION NAME
 5415 erlang4623          beam.smp             erl_nif_user_trace_s1 user_trace-s1

% cd /opt/local/lib/erlang/lib/runtime_tools-1.8.9/examples

% sudo dtrace -qs user-probe.d                                        
<0.661.0>  8 507 0 0 'trace' 'gmt_hlog_common' 'do_sync_writeback: end_seq 3, end_offset 12' ''
<0.661.0>  8 991 0 0 'trace' 'gmt_hlog' 'fold2: shortterm, data/brick/hlog.commonLogServer [3]' ''
<0.661.0>  8 1109 0 0 'trace' 'gmt_hlog' 'open_log_file [read] data/brick/hlog.commonLogServer/s/000000000003.HLOG' ''
<0.661.0>  8 1077 0 0 'trace' 'gmt_hlog' 'fold_a_file: seq 3, bof, new_offset 12' ''
<0.661.0>  8 1080 0 0 'trace' 'gmt_hlog' 'fold_a_file: seq 3, eof' ''
<0.661.0>  8 1001 0 0 'trace' 'gmt_hlog' 'fold2: done (3) -> {wb,0,[],0,[]}' ''
<0.661.0>  8 705 0 0 'trace' 'gmt_hlog_common' 'write_back_to_local_log [empty_close] undefined' ''
<0.661.0>  8 513 0 0 'trace' 'gmt_hlog_common' 'do_sync_writeback: counts 0, 0' ''
<0.589.0>  0 66 0 0 'info' 'brick_admin_event_h' 'init: []' ''
<0.666.0>  8 507 0 0 'trace' 'gmt_hlog_common' 'do_sync_writeback: end_seq 3, end_offset 12' ''
<0.666.0>  8 991 0 0 'trace' 'gmt_hlog' 'fold2: shortterm, data/brick/hlog.commonLogServer [3]' ''
<0.666.0>  8 1109 0 0 'trace' 'gmt_hlog' 'open_log_file [read] data/brick/hlog.commonLogServer/s/000000000003.HLOG' ''
Owner

tatsuya6502 commented Oct 14, 2014

All development work was done in March 2013, and this feature will be tested in release candidates of v0.3.0 (scheduled for early 2015).

Release Note:

- hibari >> GH18 - Add DTrace tracepoints for Erlang/OTP R15 or later

Notes About Supported Versions:

  • Hibari Server: R16 and 17.x
  • Hibari Erlang Native Client: R14, R15, R16 and 17.x

For v0.3.0, I dropped support for R15 or older Erlang/OTP releases from Hibari server components as the port driver C codes for h2leveldb doesn't support these older releases. Hibari Erlang native client components will continue support R14 or newer, but I'll probably drop support for R13 because I think Travis doesn't support it.

@tatsuya6502 tatsuya6502 modified the milestone: v0.1.11, v0.3 Mar 11, 2015

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment