绝了！这个MySQL故障定位方法太好用了

2022-05-23 15:53:29

来源：Java后端编程

我们都知道，MySQL 中的错误日志，慢查询日志可以帮你快速定位问题。

但有时候，日志记录的信息过少，或者是你感兴趣信息被没有被记下来，有时候又记录了过多问题，大量信息干扰你排查问题。

因此，这篇文章介绍一种新的思路——探针技术，这种技术可以在不影响 MySQL 运行，不破现场环境的前提下，在系统中的关键节点插入一些探针来收集信息。

理论上，探针可以插入 MySQL 或者 Linux 内核任意函数进出口，轻松访问参数等其他详细信息，资源损失很少，一旦移除探针后没有任何损失。就像医生给病人拍片子一样，在不影响病人健康前提下，实时观察病人体内情况，为分析病因提供依据和支撑。

Part1 探针的原理

这篇文章介绍的探针像调试程序时候打断点一样，只不过打断点是有交互的，同时是以字节码形式运行在内核虚拟机(BPF)中的。

一、异常

异常（exception）就是控制流中的突变，用来响应处理器状态中的某些变化。理解异常有助于理解探针技术。下图所示处理器在执行时执行时，发生了一个重要的变化，我们把它称为事件（event）。事件可能与当前指令直接相关，如缺页异常，算术溢出，尝试除以 0 。也有可能无关如定时器产生信号，I/O 完成。在任何情况下处理器通过异常表进行一个间接过程调用到专门的异常处理程序来处理。

异常可以分成四类：中断（interrupt)，陷阱（trap），故障（fault）和终止（abort）。

中断是异步发生的，是来自处理器外部 I/O （鼠标，键盘，网卡等）设备信号的结果。硬件中断不是由任何一条专门的指令造成，从这个意义讲它是异步的。剩下的异常类型（陷阱，故障，终止）是同步发生的，是执行当前指令的结果。我们把这种指令称为故障指令。

陷阱是有意的异常，是程序员“主动”触发的，就像是自己在代码埋下一个陷阱一样。陷阱常见的用户是进程发起系统调用，通过 INT 从用户态 trap 进内核态。

故障由错误情况引起，能够被故障处理程序修正。当故障发生时，处理器讲控制转移给故障处理程序。例如当缺页异常发生时，故障处理程序可以从磁盘中间对应的页 swap 进物理内存。

终止，是不可恢复的致命错误造成的结果，通常是一些硬件错误。程序员平常调试代码时，给程序添加断点，让程序在我们想要的地方停住。调试器能够随心所欲控制程序运行，主要靠软件中断。软件断点在 X86 系统中就是指令 INT 3。当程序执行到 INT 3 指令时，会引发软件中断。这就是上文提到的陷阱。不同于我们在 Visual Studio 和 GDB 中交互式的断点，如果程序在 trap 发生时，自动执行预定义和 handle 记录和统计运行情况，不影响程序的正常运行，达到观察 MySQL 的目的。

二、探针

为了捕捉程序运行情况，我们在程序中设置一些 “ 陷阱 ”，并设置处理程序，我们称之为探针。有的探针是在代码中预定义的，有的是在运行时动态添加的。

1. 静态探针

静态探针是事先在程序中定义好，并编译到程序或者内核的探针。

静态探针只有被开启时才会运行，不开启就不会运行，常见的静态探针包括内核中的跟踪点（tracepoints）和 USDT（Userland Statically Defined Tracing）探针。tracepoints 在代码中埋下钩子，在运行时调用相连接的探针。

它有“打开”（已连接探针）和“关闭”（未连接探针）两种状态。

当跟踪点处于“关闭”状态时，它没有任何作用，只增加微小的时间损失（检查分支的条件）和空间损失。当跟踪点为“ 打开”时，每次在调用者的执行上下文中执行跟踪点时，都会调用相连接的探针。探针函数执行完后，将返回到调用方。USDT和tracepoint类似，只不过是用户态的，在代码中插入DTRACE_PROBE()即可。

2. 动态探针

动态探针是应用程序没有定义，在程序运行时动态添加的探针。

动态探针类似于异常处理机制，当系统产生一个异常，就会跳转去执行对应的 handle。动态探针会在函数入口和出口插入一些断点，程序执行到断点时候会去执行对应的 handle，从而达到观测应用程序的目的。这里的中断是指 trap（陷阱)，在X86体系是int3指令。

KProbes 是 Linux 内核探针，可以用于监视生产系统中的事件。您可以使用它来解决性能瓶颈，记录特定事件，跟踪问题等。

KProbes 能实时在内核代码中插入中断指令，虽然这听上去有点不可思议，实际上 KProbes 做了很多安全性保证，例如 stop_machine 用于确保其他CPU在被修改时停止执行。

实际上 kprobes 大风险是给一些调用十分频繁的函数加上探针，如在网络模块中，频繁中断可能造成一定的性能风险。KProbe需要定义 pre-handler 和 post-handler，当被探测的指令要被执行时，先执行pre-handler程序。同样，当被探测指令执行之后立即执行post-handler。

uprobes 是Linux提供用户态的动态探针，合并于2012年7月发布的 Linux 3.5 内核中。uprobes 和 kprobes 十分相似，用于用户态。

三、BPF

BPF(Berkeley Packet Filter) 早开发在 BSD 操作系统中，是 TCP/IP 包过滤的工业标注，被 tcpdump 使用。

它的工作方法有点特别：用户自定义包过滤表达式，然后注入内核中的 BPF 中运行，这样的好处就是在内核进行过滤而不是将包拷贝到用户态，避免大量数据从内核态拷贝到用户态，因此具有较好的性能。

后来出现了eBPF(extend BPF), eBPF 有自己的语言，用户自己编写程序编译后通过 BPF 调用注入到内核的 BPF 虚拟机中运行，可以安全访问内核内存，它使得内核变成可编程。运行在内核中因为不需要把数据拷贝到用户空间往往具有比较高的性能，因此 BPF 被很多性能追踪工具使用。

Part2 使用探针观测MySQL

上文介绍了相关的技术背景，接下来介绍使用追踪工具观测 bpftrace, 它是一种使用 BPF 进行性能分析的前端工具，使用起来很方便，类似与 awk 语言。由于 MySQL 是运行在用户态态的，要追踪 MySQL 本身只能使用** USDT** 和** uprobes**。

一、使用 USDT 观测 MySQL

MySQL 在系统中一些关键位置定义了 USDT, 参考文档 mysqld DTrace Probe Reference(DTrace 是 Solaris 中的动态追踪工具，bpftrace 是 Linux 版本的 DTrace) 下面展示一下记录追踪到的慢查询的脚本。

#!/usr/bin/bpftrace
BEGIN{        printf("Tracing mysqld queries slower than %d ms. Ctrl-C to end.\n",            $1);        printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");}
usdt:/usr/sbin/mysqld:mysql:query__start{        @query[tid] = str(arg0);        @start[tid] = nsecs;}
usdt:/usr/sbin/mysqld:mysql:query__done/@start[tid]/{        $dur = (nsecs - @start[tid]) / 1000000;        if ($dur > $1) {                printf("%-10u %-6d %6d %s\n", elapsed / 1000000,                    pid, $dur, @query[tid]);        }        delete(@query[tid]);        delete(@start[tid]);}

（左右滑动查看代码）

解读一下 ** BEGIN** 是这个脚本刚开始运行时候的执行的，打印一些提示信息。usdt:/usr/sbin/mysqld:mysql:query__start 是给** query__start ** 这个函数加的探针，当程序执行到这里时，记录一下个参数 arg0(query), 和当前时间时间戳，并把这些信息保存在 BPF 的 map 中。query__done 探针被执行时，记录当前时间，减去开始时间（从 BPF 的 map 中获取），就是这个查询的花费时间，如果超过阈值就打印出来。如果你会说 MySQL 有慢查询日志啊，不过这里优势是不需要重启 MySQL，可以实时修改阈值。而且 usdt 在版本MySQL 会被移除，同时需要编译时设置参数 -DENABLE_DTRACE=1 才能支持 usdt。

二、使用 uprobes 观测 MySQL

不同与 usdt 需要事先在代码中设置观测点，uprobes 可以在程序中动态添加，可以插入到任意函数的进口和出口位置。下面展示是使用 uprobes 探针对 dispatch_command 进行追踪，打印出慢查询语句。

#!/usr/bin/bpftrace
BEGIN{        printf("Tracing mysqld queries slower than %d ms. Ctrl-C to end.\n",            $1);        printf("%-10s %-6s %6s %s\n", "TIME(ms)", "PID", "MS", "QUERY");}
uprobe:/usr/sbin/mysqld:*dispatch_command*{        $COM_QUERY = 3;           if (arg2 == $COM_QUERY) {                @query[tid] = str(*arg1);                @start[tid] = nsecs;        }}
uretprobe:/usr/sbin/mysqld:*dispatch_command*/@start[tid]/{        $dur = (nsecs - @start[tid]) / 1000000;        if ($dur > $1) {                printf("%-10u %-6d %6d %s\n", elapsed / 1000000,                    pid, $dur, @query[tid]);        }        delete(@query[tid]);        delete(@start[tid]);}

（左右滑动查看代码）

运行一下这里使用参数 10，表示慢查询阈值是 10 ms.

sudo ./mysql_uprobe_slow.bt 10Attaching 3 probes...Tracing mysqld queries slower than 10 ms. Ctrl-C to end.TIME(ms)   PID        MS QUERY35976      1083      742 select employees.first_name, employees.last_name, titles.title 93145      1083      224 select * from employees125348     1083     1727 select * from salaries

（左右滑动查看代码）

bpftrace 还提供了直方图工具，可以将所有查询耗时记录下来，后打印出耗时分布直方图。

#!/usr/bin/bpftrace
BEGIN{  printf("Tracing MySQL query... Hit Ctrl-C to end.\n");}
uprobe:/usr/sbin/mysqld:*dispatch_command*{  @start[tid] = nsecs;}
uretprobe:/usr/sbin/mysqld:*dispatch_command*/@start[tid]/{  @usecs = hist((nsecs - @start[tid]) / 1000000);        delete(@start[tid]);}
END{  clear(@start);}

（左右滑动查看代码）

sudo ./histo.bt Attaching 4 probes...Tracing MySQL query... Hit Ctrl-C to end.^C

@usecs: []                   10 |@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@@|[1]                     |                                                    |[2, 4)                  |                                                    |[4, 8)                  |                                                    |[8, 16)                 |                                                    |[16, 32)                |                                                    |[32, 64)                |                                                    |[64, 128)               |                                                    |[128, 256)             1 |@@@@@                                               |[256, 512)             1 |@@@@@                                               |[512, 1K)               |                                                    |[1K, 2K)               1 |@@@@@                                               |