Erlang/Elixir: 在OSX上通过DTrace对Erlang进行运行时的动态追踪

基本配置

OSX是默认支持DTrace的, 所以不需要什么修改就可以使用, 只需要在配置Erlang的时候添加 --with-dynamic-trace=dtrace 选项即可. 这里为了方便我使用了 kerl 作为Erlang构建的管理工具. 并在 ~/.kerlrc 配置文件中指定了Erlang的编译选项, 其内容如下:

KERL_CONFIGURE_OPTIONS="--with-dynamic-trace=dtrace --disable-debug --without-javac --enable-shared-zlib --enable-dynamic-ssl-lib --enable-hipe --enable-smp-support --enable-threads --enable-kernel-poll --with-wx"

关于 kerl 的详细使用说明,请参考Github上的 项目主页 . 或 Erlang版本管理工具: Kerl 这篇文章

开始构建

$ kerl build 18.3 18.3_dtrace

安装

$ kerl install 18.3_dtrace ~/.kerl/installs/18.3_dtrace

激活, 把下面的代码添加到 .bashrc ,或 .zshrc (如果使用了 oh-my-zsh )

$ . ~/.kerl/installs/18.3_dtrace/activate

输入 iex 验证一下, 我们看到了标记行上面多了一个 [dtrace]

试着开始第一步

下面我们来创建一个名为 process_signal_trace.d DTrace文件, 内容如下

#!/usr/sbin/dtrace -qs erlang*:::process-spawn {   printf("pid %s mfa %s/n", copyinstr(arg0), copyinstr(arg1)); } erlang*:::process-exit {   printf("pid %s reason %s/n", copyinstr(arg0), copyinstr(arg1)); } erlang*:::process-exit_signal {   printf("sender %s -> pid %s reason %s/n", copyinstr(arg0), copyinstr(arg1), copyinstr(arg2)); }

修改执行权限

$ chmod +x /tmp/process_signal_trace.d

运行该脚本(运行dtrace需要root权限)

$ sudo /tmp/process_signal_trace.d 

然后在另一个终端启动IEx会话, 并输入一些创建进程的代码:

iex(8)> f = fn() -> :timer.sleep(2000) end    #Function<20.50752066/0 in :erl_eval.expr/5> iex(9)> spawn(fn() -> :timer.sleep(2000) end) #PID<0.71.0> iex(10)> spawn(fn() -> :timer.sleep(2000) end) #PID<0.73.0> iex(11)> spawn(fn() -> :timer.sleep(2000) end) #PID<0.75.0>

然后回到运行 DTrace 的终端, 我们看到了探测点的输出了. (IEx会话中的进程ID和下图的进程ID是相对应的)

深入一点: 系统调用追踪

有了上面的基础之后, 我们来分析与一下, 这篇 几天前我没怎么看懂的文章

首先下载文章中使用的脚本, 并修改执行权限, 并启动 DTrace:

# 下载 wget https://raw.githubusercontent.com/evanmiller/tracewrite/master/tracewrite.d -O /tmp/tracewrite.d # 修改执行权限 chmod +x /tmp/tracewrite.d # 启动, 其中-p参数是IEx的进程ID, 可以通过 ps aux|grep iex 查找 sudo -s /tmp/tracewrite.d -p 60838

在IEx会话中执行

{:ok, file} = :file.open("/tmp/something.txt", [:write, :raw]) :file.write(file, :re.replace("Hello & Goodbye", "&", "&"))

代码本身没什么特别, 只是打开一个文件,向其中写入一些文字而已. 回到 DTrace 输出终端, 我们看到:

iex(5)> :re.replace("Hello & Goodbye", "&", "&") ["Hello ", ["&", "amp;"] | " Goodbye"]

:re.replace("Hello & Goodbye", "&", "&") 会创建一个嵌套列表 ["Hello ", ["&", "amp;"] | " Goodbye"] , 因此,对于 write(0x3, "Hello & goodbye/0", 0x13) 会被展开为 writev(0x1A, 0x1A5405F8, 0x4) , 0x1A5405F8 这个十六进制的东西是个什么鬼? 它实际上是这个向量的地址, 这个地址包含了另外4个地址, 如下所示:

# amp; 0x0b49 'a'  0x0b4a 'm' 0x0b4b 'p' 0x0b4c ';'  # Hello & Goodbyte 0x0d78 'H' 0x0d79 'e' 0x0d7a 'l' 0x0d7b 'l' 0x0d7c 'o' 0x0d7d ' ' 0x0d7e '&' 0x0d7f ' ' 0x0d80 'G' 0x0d81 'o' 0x0d82 'o' 0x0d83 'o' 0x0d84 'd' 0x0d85 'b' 0x0d86 'y' 0x0d87 'e'

从地址我们可以看出, 这个 :re 生成的嵌套列表, 只是包含三个 原始字符串 , 和一个额外的 替换串 的地址指针, 它并没有创建或修改字符串. 这样的数据结构被称为 I/O 列表, 它的设计目的是: 当向磁盘或网络写入的时候, 利用 writev 系统调用来最小化数据的复制.

当然, 指针并不是万能药, 有的时候, 复制要比指针的连接更高效. 让我用 DTrace 来探索 Erlang 虚拟机的实现.

追踪限制(Limit)

:file.write(file, Enum.map(1..14, fn(_) -> "Foobar" end)) :file.write(file, Enum.map(1..15, fn(_) -> "Foobar" end))

两行代码都是向文件中写入一个I/O列表. 第一行代码重复14次, 第二行重复15次, 你可能猜这两行代码可能会调用相同的系统调用, 实际上却不是这么回事的. 第一行代码用14个元素的向量调用 writev, 第二行代码把单个 I/O 列表扁平化为一个单独的内存大对象, 然后调用 write 写入数据.

DTrace 的输出可以证明这一点

在来看一下 14 个 "Foobar" 字符串的地址

  0    393                    writev:return Writev data 1/14: (6 bytes): 0x0000000021942ec0 Foobar   0    393                    writev:return Writev data 2/14: (6 bytes): 0x0000000021940f50 Foobar   0    393                    writev:return Writev data 3/14: (6 bytes): 0x0000000021941710 Foobar   0    393                    writev:return Writev data 4/14: (6 bytes): 0x0000000021941750 Foobar   0    393                    writev:return Writev data 5/14: (6 bytes): 0x0000000021941790 Foobar   0    393                    writev:return Writev data 6/14: (6 bytes): 0x0000000021942fb8 Foobar   0    393                    writev:return Writev data 7/14: (6 bytes): 0x0000000021942ff8 Foobar   0    393                    writev:return Writev data 8/14: (6 bytes): 0x0000000021941988 Foobar   0    393                    writev:return Writev data 9/14: (6 bytes): 0x00000000219419c8 Foobar   0    393                    writev:return Writev data 10/14: (6 bytes): 0x0000000021941a08 Foobar   0    393                    writev:return Writev data 11/14: (6 bytes): 0x0000000021941a48 Foobar   0    393                    writev:return Writev data 12/14: (6 bytes): 0x0000000021943038 Foobar   0    393                    writev:return Writev data 13/14: (6 bytes): 0x0000000021943078 Foobar   0    393                    writev:return Writev data 14/14: (6 bytes): 0x00000000219430b8 Foobar

注意到内存地址了么? 14 个字符串 "Foobar" 分布在内存的不同位置, 如果我们把字符串 "Foobar" 移动到 Elixir 闭包的外面, 又是如何呢?

0    393                    writev:return Writev data 1/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 2/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 3/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 4/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 5/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 6/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 7/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 8/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 9/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 10/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 11/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 12/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 13/14: (6 bytes): 0x0000000021940b98 Foobar 0    393                    writev:return Writev data 14/14: (6 bytes): 0x0000000021940b98 Foobar

嗯哈,14 个同样的地址, 你应该懂了. 对于闭包内的字符串, 闭包每次执行的时候创建一个新的字符串, 当在闭包内引用外部的变量时, 每次执行闭包, 它只是创建了指向同一个字符串的引用.

Erlang 把字符串长度大于等于64字节的认为是比较大的二进制对象, (这是由 ERL_ONHEAP_BIN_LIMIT 魔数控制的. 如果大常量出现在已编译模块中, 他们将会被分配在 共享堆 上面, 并重新计数(re-counted)

少就是多

ERL_SMALL_IO_BIN_LIMIT 被硬编码为 ERL_ONHEAP_BIN_LIMIT 的4倍, 即为: 256字节.

在 writev 向量中的元素小于 ERL_SMALL_IO_BIN_LIMIT 的会被连接为一个大的字符串, 大于 ERL_SMALL_IO_BIN_LIMIT 会保留不变. 比如如向量中的每个元素的字节长度刚好小于 256 字节, 那么该向量会被连接成一个更大的单个字符串, 否则保持不变, 据此可以对代码中的二进制处理进行优化.

探测点

这里是对 官方文档 探测点的的简单说明. 详细的探测点信息可以通过命令 sudo dtrace -l | grep erlang 得到.

列表比较长, 首先通过 sudo dtrace -l | head -n 10 命令得到四个列的名字.

在我的系统上, 目前提供了 1086 个探测点, 通过下面的命令可以得到

sudo dtrace -l|grep beam.smp |wc -l

探测点列表

# 所有非用户追踪的探测点, 目前有 133 个, 可以通过下面的命令查看完整的列表 ➜ sudo dtrace -l | grep beam.smp | head -n 133

# 用户追踪的探测点 953 个, 可以通过下面的命令获取 ➜ sudo dtrace -l | grep beam.smp | grep user_trace

# 进程相关的探测点 ➜ sudo dtrace -l | grep beam.smp | grep process- | head -n 133  35811 erlang60838          beam.smp              erts_do_exit_process process-exit 35812 erlang60838          beam.smp                  send_exit_signal process-exit_signal 35813 erlang60838          beam.smp            erts_dsig_send_exit_tt process-exit_signal-remote 35814 erlang60838          beam.smp                     grow_new_heap process-heap_grow 35815 erlang60838          beam.smp                          do_minor process-heap_grow 35816 erlang60838          beam.smp                  major_collection process-heap_grow 35817 erlang60838          beam.smp                   shrink_new_heap process-heap_shrink 35818 erlang60838          beam.smp                    erts_hibernate process-hibernate 35819 erlang60838          beam.smp                begin_port_cleanup process-port_unblocked 35820 erlang60838          beam.smp            erts_port_resume_procs process-port_unblocked 35821 erlang60838          beam.smp                      process_main process-scheduled 35822 erlang60838          beam.smp                erl_create_process process-spawn 35823 erlang60838          beam.smp                          schedule process-unscheduled

# 分布式相关的探测点  ➜ sudo dtrace -l | grep beam.smp | grep dist- | head -n 133  35697 erlang60838          beam.smp               send_nodes_mon_msgs dist-monitor 35698 erlang60838          beam.smp                 dist_port_command dist-output 35699 erlang60838          beam.smp                dist_port_commandv dist-outputv 35700 erlang60838          beam.smp                    erts_dsig_send dist-port_busy 35701 erlang60838          beam.smp           erts_dist_port_not_busy dist-port_not_busy 35702 erlang60838          beam.smp                    erts_dsig_send dist-port_not_busy

# 消息相关的探测点  ➜ sudo dtrace -l | grep beam.smp | grep message- | head -n 133  35792 erlang60838          beam.smp                     queue_message message-queued 35793 erlang60838          beam.smp           erts_queue_dist_message message-queued 35794 erlang60838          beam.smp                      process_main message-receive 35795 erlang60838          beam.smp            erts_dsig_send_reg_msg message-send 35796 erlang60838          beam.smp                erts_dsig_send_msg message-send 35797 erlang60838          beam.smp                 erts_send_message message-send 35798 erlang60838          beam.smp            erts_dsig_send_reg_msg message-send-remote 35799 erlang60838          beam.smp                erts_dsig_send_msg message-send-remote

# 端口相关的探测点  ➜ sudo dtrace -l | grep beam.smp | grep port- | head -n 133  35802 erlang60838          beam.smp                     set_busy_port port-busy 35803 erlang60838          beam.smp                set_port_connected port-command 35804 erlang60838          beam.smp            call_deliver_port_exit port-command 35805 erlang60838          beam.smp                  erts_port_output port-command 35806 erlang60838          beam.smp                set_port_connected port-connect 35807 erlang60838          beam.smp               call_driver_control port-control 35808 erlang60838          beam.smp            erts_deliver_port_exit port-exit 35809 erlang60838          beam.smp                     set_busy_port port-not_busy 35810 erlang60838          beam.smp                         open_port port-open

参考资料

• Elixir RAM and the Template of Doom

• Profiling Erlang Applications using DTrace

• http://dtracehol.com/

• http://www.amazon.com/dp/0132091518

• http://dtrace.org/guide

• http://dtracebook.com/index.php/Main_Page