Mac上使用DTrace检测MySQL的初步实验

背景知识

BPF是Linux上新兴的性能跟踪工具，其中一项重要的技术是“动态插桩”。关于BPF和动态插桩可以参考BPF相关书籍，比如参考1。在Mac上可以使用DTrace来实现类似的动态插桩功能，这里通过一个小实验向大家介绍这一工具的使用方法，给大家提供一些入门级的感性认识。

步骤

关闭Mac SIP

重启Mac，开机时立刻按住Command + r 不放，进入恢复模式，打开左上角的终端，执行：

csrutil status

如果看到SIP时enable的，需要禁用，执行：

csrutil disable

重启Mac使之生效

编写DTrace脚本

新建一个文件，命名为mystack.d，输入以下内容：

pid$target:mysqld:*dispatch_sql_command*:entry
{
	printf("Query for %s\n", copyinstr(arg2));
	ustack();
}

执行DTrace脚本

执行：

sudo dtrace -s mystack -p `pgrep -x mysqld`

这里pgrep -x mysqld是查找mysqld的进程号，也可以直接输入进程号。
在MySQL中执行一些SQL语句，比如：
select * from test2;
show tables;
就会在dtrace的窗口中如下信息：

dtrace: script 'mystack.d' matched 1 probe

CPU     ID                    FUNCTION:NAME
  6 427700 dispatch_sql_command(THD*, Parser_state*):entry Query for select * from test2

              mysqld`dispatch_sql_command(THD*, Parser_state*)
              mysqld`dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1b40
              mysqld`do_command(THD*)+0x1a4
              mysqld`handle_connection(void*)+0x1a8
              mysqld`pfs_spawn_thread(void*)+0xe6
              libsystem_pthread.dylib`_pthread_start+0xe0
              libsystem_pthread.dylib`thread_start+0xf

  6 427700 dispatch_sql_command(THD*, Parser_state*):entry Query for show tables

              mysqld`dispatch_sql_command(THD*, Parser_state*)
              mysqld`dispatch_command(THD*, COM_DATA const*, enum_server_command)+0x1b40
              mysqld`do_command(THD*)+0x1a4
              mysqld`handle_connection(void*)+0x1a8
              mysqld`pfs_spawn_thread(void*)+0xe6
              libsystem_pthread.dylib`_pthread_start+0xe0
              libsystem_pthread.dylib`thread_start+0xf

^C

工作原理解释

dtrace脚本是放置probe根据predicate触发action，proble的格式是：
PROBIDER:MODULE:FUNCTION:NAME
上面mystack.d例子中的proble是pid$target:mysqld:dispatch_sql_command:entry
predicate是空，action是：
printf(“Query for %s\n”, copyinstr(arg2));
ustack();
printf的语法和C类似，ustack显示线程的调用栈

更多探索

使用gdb工具可以观察到动态插桩是如何工作的，Mac上可以使用类似的lldb工具，执行如下命令反汇编dispatch_sql_command函数，比较DTrace插桩前后的差别，先用lldb -p 143打开调试，143是msqld的进程号，再用disas -n dispatch_sql_command反汇编函数，可以看到，
插桩前：

% sudo lldb -p 143
(lldb) process attach --pid 143
Process 143 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff2046b9ca libsystem_kernel.dylib`poll + 10
libsystem_kernel.dylib`poll:
->  0x7fff2046b9ca <+10>: jae    0x7fff2046b9d4            ; <+20>
    0x7fff2046b9cc <+12>: movq   %rax, %rdi
    0x7fff2046b9cf <+15>: jmp    0x7fff204666bd            ; cerror
    0x7fff2046b9d4 <+20>: retq   
Target 0: (mysqld) stopped.

Executable module set to "/usr/local/mysql/bin/mysqld".
Architecture set to: x86_64h-apple-macosx-.
(lldb) disas -n dispatch_sql_command
mysqld`dispatch_sql_command:
    0x104e46530 <+0>:    pushq  %rbp
    0x104e46531 <+1>:    movq   %rsp, %rbp
    0x104e46534 <+4>:    pushq  %r15
    0x104e46536 <+6>:    pushq  %r14
    0x104e46538 <+8>:    pushq  %r13
    0x104e4653a <+10>:   pushq  %r12
    0x104e4653c <+12>:   pushq  %rbx
    0x104e4653d <+13>:   subq   $0x28, %rsp
    0x104e46541 <+17>:   movq   %rsi, %rbx
    0x104e46544 <+20>:   movq   %rdi, %r15
    0x104e46547 <+23>:   callq  0x104e46220               ; THD::reset_for_next_command()

插桩后：

% sudo lldb -p 143
(lldb) process attach --pid 143
Process 143 stopped
* thread #1, queue = 'com.apple.main-thread', stop reason = signal SIGSTOP
    frame #0: 0x00007fff2046b9ca libsystem_kernel.dylib`poll + 10
libsystem_kernel.dylib`poll:
->  0x7fff2046b9ca <+10>: jae    0x7fff2046b9d4            ; <+20>
    0x7fff2046b9cc <+12>: movq   %rax, %rdi
    0x7fff2046b9cf <+15>: jmp    0x7fff204666bd            ; cerror
    0x7fff2046b9d4 <+20>: retq   
Target 0: (mysqld) stopped.

Executable module set to "/usr/local/mysql/bin/mysqld".
Architecture set to: x86_64h-apple-macosx-.
(lldb) disas -n dispatch_sql_command
mysqld`dispatch_sql_command:
    0x104e46530 <+0>:    int3   
    0x104e46531 <+1>:    movq   %rsp, %rbp
    0x104e46534 <+4>:    pushq  %r15
    0x104e46536 <+6>:    pushq  %r14
    0x104e46538 <+8>:    pushq  %r13
    0x104e4653a <+10>:   pushq  %r12
    0x104e4653c <+12>:   pushq  %rbx
    0x104e4653d <+13>:   subq   $0x28, %rsp
    0x104e46541 <+17>:   movq   %rsi, %rbx
    0x104e46544 <+20>:   movq   %rdi, %r15
    0x104e46547 <+23>:   callq  0x104e46220               ; THD::reset_for_next_command()

注意到插桩后dispatch_sql_command的第一个指令被替换成了int3中断。

参考

本文章和相关实验参考了如下资料，如果想了解更多，也可以阅读：
[1]: 《BPF之巅》[美] Brendan Gregg 著
[2]: https://docs.oracle.com/cd/E24847_01/html/E22192/gcgkk.html#gcgma
[3]: https://www.cnblogs.com/erisen/p/5967194.html