Skip to content

7.md

Latest commit

 

History

History
556 lines (416 loc) · 20.1 KB

7.md

File metadata and controls

556 lines (416 loc) · 20.1 KB
Raw

eBPF 跟踪容器内部署的 MySQL 慢查询

引出问题

对于 Mysql 来说， 慢查询日志是一个非常重要的日志，它可以找到慢查询的 SQL 语句，从而进行优化. 但是，慢查询日志的开启会对数据库的性能产生影响，需要在合适的时候开启慢查询日志（可以通过设置 slow_query_log 参数来开启）， 但是如果通过一些技术来筛选慢查询 SQL呢 ?

这里 eBPF 就是一个合适的技术，它可以跟踪 Mysql 的 SQL 执行情况，从而找到慢查询 SQL.

bpftrace 探索

在 mysqld 的实现中， dispatch_command 就是需要关注的函数，它是 Mysql 的命令分发函数，会根据客户端发送的命令，调用不同的处理函数. 现在通过 eBPF 来跟踪 dispatch_command 函数，从而找到慢查询 SQL, 很轻松的就能打印出来进行分析.

利用 bpftrace 的脚本，可以跟踪 dispatch_command 函数，帮助定位慢查询 SQL.

这里使用的 docker 部署 Mysql

# 拉取MySQL 5.7镜像
docker pull mysql:5.7

# 运行MySQL容器
docker run --name mysql57 -e MYSQL_ROOT_PASSWORD=my-secret-pw -p 3306:3306 -d mysql:5.7

首先需要获取容器内 Mysql 的宿主机 Pid

docker ps
CONTAINER ID   IMAGE       COMMAND                   CREATED             STATUS             PORTS                                                  NAMES
3c1970c2e86f   mysql:5.7   "docker-entrypoint.s…"   About an hour ago   Up About an hour   0.0.0.0:3306->3306/tcp, :::3306->3306/tcp, 33060/tcp   mysql57

docker inspect 3c1970c2e86f | grep -m1 Pid
            "Pid": 196336,

然后使用 bpftrace 脚本来定位 dispatch_command 函数,这里新建脚本 mysql_dispath.bt

#!/usr/bin/env bpftrace

// 跟踪 MySQL 中的 dispatch_command 函数
uprobe:/sbin/mysqld:dispatch_command
{
    // 将命令执行的开始时间存储在 map 中
    @start_times[tid] = nsecs;

    // 打印进程 ID 和命令字符串
    printf("MySQL command executed by PID %d: ", pid);

    // dispatch_command 的第三个参数是 SQL 查询字符串
    printf("%s\n", str(arg3));
}

uretprobe:/sbin/mysqld:dispatch_command
{
    // 从 map 中获取开始时间
    $start = @start_times[tid];

    // 计算延迟，以毫秒为单位
    $delta = (nsecs - $start) / 1000000;

    // 打印延迟
    printf("Latency: %u ms\n", $delta);

    // 从 map 中删除条目以避免内存泄漏
    delete(@start_times[tid]);
}

执行这个脚本后

sudo bpftrace -p 196336 ./mysql_dispath.bt
No probes to attach

这踏马怎么回事,不对劲,这里先别急,只要修改一下 mysql_dispath.bt 脚本里的 dispatch_command 为 _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command 就行了,可以再试试

执行一些 SQL 查询后,最终结果还是差强人意:

sudo bpftrace -p 196336 ./mysql_dispath.bt
Attaching 2 probes...
MySQL command executed by PID 196336: 
Latency: 1 ms
MySQL command executed by PID 196336: 
Latency: 0 ms
MySQL command executed by PID 196336: 
Latency: 0 ms

SQL 貌似没有打印出来, 也许在某些 Linux 版本上，针对某些 Mysql 起作用，但是在某些版本上，可能会出现问题，就像咱们实践，会发现 dispatch_command 函数并没有被跟踪、SQL 语句没有被打印出来, 可能还有其他问题也尚未可知.

谷歌了一下,了解到在 Mysql 5.6 版本中，SQL 语句是 dispatch_command 函数的第三个参数，自 Mysql 5.7 版本开始，SQL 语句是 ``dispatch_command函数的第二个参数. 但是即使修改了参数的位置，还是会发现dispatch_command`函数并没有被跟踪、`SQL` 语句没有被打印出来.

当前测试用的 MySQL 版本是 5.7， dispatch_command 函数并没有被跟踪，sql 语句没有被打印出来. 我尝试了很多方法，但是都没有解决问题.

排查了半天，才发现这个版本是用 C++ 编译的，因为名字改写规则(mangled)，dispatch_command 函数的名字被编译成符号_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command.

修改之后是可以 attach 上的，但是还是没有打印出 sql 语句，这是因为 str(arg3) 函数并不能正确的解析 sql 语句，使用 str(arg2) 也不可以. 根据网上的教程，这个方法应该是可以打印出 sql 语句的，但是结果也是没有成功.

解决方案

只能自己造轮子咯,实现一下 eBPF 程序.

还是基于上面的分析，跟踪 _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command 这个 uprobe 探针. 可以基于以下方式获取:

一种方式是 bpftrace -l 'u:/usr/sbin/mysqld:*'|grep dispatch_command, 根据关键字找到这个探针：

sudo bpftrace -p 196336 -l 'u:/usr/sbin/mysqld:*' | grep dispatch_command
uprobe:/proc/196336/root/usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command

另一种方式是通过 objdump 查看符号表：

sudo objdump -T /var/lib/docker/overlay2/270506fa70024c98a81543a6a274e9f03258f39471655b69fa22fce5fada6d13/merged/sbin/mysqld | grep dispatch_command
0000000000cd5920 g    DF .text	00000000000023ad  Base        _Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command

当前的方案就是利用 uprobe 跟踪 dispatch_command 函数，记录开始时间和 SQL 语句，然后在 uretprobe 中计算时间，打印 sql 语句和时间. 通过 TID 做主键保存信息.

#include "vmlinux.h"
#include "event.h"
#include <bpf/bpf_helpers.h>
#include <bpf/bpf_core_read.h>
#include <bpf/bpf_tracing.h>


char LICENSE[] SEC("license") = "Dual BSD/GPL";

// 定义开始时间的哈希表，键为线程 ID（TID），值为开始时间
struct {
    __uint(type, BPF_MAP_TYPE_HASH);
    __uint(max_entries, 10240);
    __type(key, u32);
    __type(value, u64);
} start_times SEC(".maps");

// 定义查询字符串的哈希表，键为线程 ID（TID），值为查询字符串
struct {
    __uint(type, BPF_MAP_TYPE_HASH);
    __uint(max_entries, 10240);
    __type(key, u32);
    __type(value, char[256]);
} comm_sql SEC(".maps");

// 定义 ringbuffer，用于向用户空间传递数据
struct {
    __uint(type, BPF_MAP_TYPE_RINGBUF);
    __uint(max_entries, 1 << 24); // 16 MiB
} events SEC(".maps");



// uprobe：在 dispatch_command 函数入口时触发
SEC("uprobe//var/lib/docker/overlay2/270506fa70024c98a81543a6a274e9f03258f39471655b69fa22fce5fada6d13/merged/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command")
int uprobe_mysql_dispatch_command(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() >> 32;
    u64 ts = bpf_ktime_get_ns();

    void* st = (void*) PT_REGS_PARM2(ctx);
    char query[256];
    char* query_ptr;
    bpf_probe_read_user(&query_ptr, sizeof(query_ptr), st);
    bpf_probe_read_user_str(query, sizeof(query), query_ptr);

    bpf_printk("slowsql: query=%s, query_ptr=%s\n", query,query_ptr);

    // 记录comm_sql
    bpf_map_update_elem(&comm_sql, &tid, query, BPF_ANY);

    // 记录开始时间
    bpf_map_update_elem(&start_times, &tid, &ts, BPF_ANY);

    return 0;
}

// uretprobe：在 dispatch_command 函数返回时触发
SEC("uretprobe//var/lib/docker/overlay2/270506fa70024c98a81543a6a274e9f03258f39471655b69fa22fce5fada6d13/merged/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command")
int uretprobe_mysql_dispatch_command(struct pt_regs *ctx) {
    u32 tid = bpf_get_current_pid_tgid() >> 32;

    char *query = bpf_map_lookup_elem(&comm_sql, &tid);
    if (!query) {
        // 未找到查询字符串，可能是因为在进入时未记录
        return 0;
    }

    // 删除查询字符串记录，防止内存泄漏
    bpf_map_delete_elem(&comm_sql, &tid);



    u64 *start_ts = bpf_map_lookup_elem(&start_times, &tid);
    if (!start_ts) {
        // 未找到开始时间，可能是因为在进入时未记录
        return 0;
    }

    u64 delta = bpf_ktime_get_ns() - *start_ts;
    // 删除开始时间记录，防止内存泄漏
    bpf_map_delete_elem(&start_times, &tid);

    // 如果延迟小于等于 10 毫秒（10000000 纳秒），则不处理
    if (delta <= 10000000) {
        return 0;
    }

    // 分配事件数据
    struct event *e;
    e = bpf_ringbuf_reserve(&events, sizeof(*e), 0);
    if (!e) {
        // 分配失败
        return 0;
    }

    // 填充事件数据
    e->pid = bpf_get_current_pid_tgid() & 0xFFFFFFFF;
    e->tid = tid;
    e->delta_ns = delta;

    if (query) {
        bpf_probe_read_kernel_str(e->query, sizeof(e->query), query);
    } else {
        // 未能获取查询字符串
        e->query[0] = '\0';
    }

    bpf_printk("slowsql: pid=%d, tid=%d, delta=%lld, query=%s\n", e->pid, e->tid, e->delta_ns, e->query);

    // 提交事件到 ringbuffer
    bpf_ringbuf_submit(e, 0);


    return 0;
}

首先定义了 event 结构体，用于记录单个 SQL 的信息. 然后定义了两个哈希表，一个用于存储开始时间，一个用于存储 SQL 语句. 在 uprobe 中，我们记录开始时间和 SQL 语句，然后在 uretprobe 中计算时间，打印 SQL 语句和时间. 重要的是获取 SQL 语句的方法，这里使用 bpf_probe_read_user_str，这个函数可以读取用户空间的字符串. 在uretprobe 中，我们将事件数据提交到 ringbuffer 中，然后用户空间程序可以读取这些数据.

现在可以使用 ecc 编译，ecli 运行就可以了.

sudo ./ecli run ./eBPF/bpftrace/mysql_trace/package.json
INFO [ecc_rs::bpf_compiler] Compiling bpf object...
INFO [ecc_rs::bpf_compiler] Generating package json..
INFO [ecc_rs::bpf_compiler] Packing ebpf object and config into ./eBPF/bpftrace/mysql_trace/package.json...

sudo ./ecli run ./eBPF/bpftrace/mysql_trace/package.json

然后执行一个 SQL 查询,抓取一下日志看看

sudo cat /sys/kernel/debug/tracing/trace_pipe | grep "slowsql"
          mysqld-202117  [001] ...11 24019.871833: bpf_trace_printk: slowsql: pid=202117, tid=196336, delta=814091882, query=SELECT * FROM `fy`.`org_knowledge`
          mysqld-197718  [001] ...11 24019.872553: bpf_trace_printk: slowsql: pid=197718, tid=196336, delta=128909, query=SELECT * FROM `fy`.`org_knowledge` LIMIT 0
          mysqld-197718  [001] ...11 24019.873182: bpf_trace_printk: slowsql: pid=197718, tid=196336, delta=350723, query=SHOW COLUMNS FROM `fy`.`org_knowledge`
          mysqld-202117  [001] ...11 24037.962547: bpf_trace_printk: slowsql: pid=202117, tid=196336, delta=145623, query=SELECT * FROM `fy`.`org_knowledge` LIMIT 0
          mysqld-197718  [001] ...11 24037.963580: bpf_trace_printk: slowsql: pid=197718, tid=196336, delta=143019, query=SELECT * FROM `fy`.`org_knowledge` LIMIT 0

下面使用 Go 来开发这个能力, 只打印延迟大于 10ms 的 SQL 语句的代码.

Go 程序读取 ringbuffer 中的数据，然后打印出来. 但是首先还是通过 go generate 生成 cilium/ebpf 桩代码.

主要的代码如下:

//go:generate go run github.com/cilium/ebpf/cmd/bpf2go -cc clang -cflags "-O2 -g -Wall -Werror" -target amd64 --go-package tool -output-dir tool Tool mysql_trace/mysql_trace.c -- -I/usr/include/bpf -I/usr/include/linux

package main

import (
	"bytes"
	"encoding/binary"
	"fmt"
	"log"
	"os"
	"os/signal"
	"syscall"
	"time"

	"github.com/767829413/advanced-go/eBPF/bpftrace/tool"

	"github.com/cilium/ebpf/link"
	"github.com/cilium/ebpf/ringbuf"
	"github.com/cilium/ebpf/rlimit"
)

// Event 对应 eBPF 程序中定义的 struct event
type Event struct {
	Pid     uint32    // 进程 ID
	Tid     uint32    // 线程 ID
	DeltaNs uint64    // 执行时间（纳秒）
	Query   [256]byte // SQL 查询字符串，最大长度为 256 字节
}

// GetQuery 返回查询字符串，去除末尾的空字节
func (e *Event) GetQuery() string {
	return string(bytes.TrimRight(e.Query[:], "\x00"))
}

func main() {
	// Allow the current process to lock memory for eBPF resources.
	if err := rlimit.RemoveMemlock(); err != nil {
		log.Fatal(err)
	}

	// 加载编译的 eBPF 程序
	spec, err := tool.LoadTool()
	if err != nil {
		log.Fatalf("loading BPF program: %v", err)
	}

	// Load pre-compiled programs and maps into the kernel.
	objs := tool.ToolObjects{}
	if err := spec.LoadAndAssign(&objs, nil); err != nil {
		log.Fatalf("loading objects: %v", err)
	}
	defer objs.Close()

	// Open a uretprobe for the runtime.casgstatus function.
	ex, err := link.OpenExecutable(
		"/var/lib/docker/overlay2/270506fa70024c98a81543a6a274e9f03258f39471655b69fa22fce5fada6d13/merged/sbin/mysqld",
	)
	if err != nil {
		log.Fatalf("opening executable: %v", err)
	}

	up, err := ex.Uprobe(
		"_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command",
		objs.UprobeMysqlDispatchCommand,
		nil,
	)
	if err != nil {
		log.Fatalf("creating uretprobe: %v", err)
	}
	defer up.Close()

	upret, err := ex.Uretprobe(
		"_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command",
		objs.UretprobeMysqlDispatchCommand,
		nil,
	)
	if err != nil {
		log.Fatalf("creating uretprobe: %v", err)
	}
	defer upret.Close()

	// Open a ring buffer to receive events from the eBPF program.
	rb, err := ringbuf.NewReader(objs.Events)
	if err != nil {
		log.Fatalf("opening ringbuf reader: %v", err)
	}
	defer rb.Close()

	// 捕获 SIGINT 和 SIGTERM 信号以正确退出
	sig := make(chan os.Signal, 1)
	signal.Notify(sig, syscall.SIGINT, syscall.SIGTERM)

	fmt.Println("listening for events...")

	// 读取 ring buffer 中的数据
	go func() {
		for {
			// 读取事件
			record, err := rb.Read()
			if err != nil {
				log.Printf("reading from ringbuf: %v", err)
				return
			}

			// 将事件解析为 Event 结构
			var data Event
			err = binary.Read(bytes.NewReader(record.RawSample), binary.LittleEndian, &data)
			if err != nil {
				log.Printf("parsing event: %v", err)
				return
			}

			// 输出 goroutine 信息
			fmt.Printf("PID: %d, TID: %d, Latency: %v, SQL: %s\n",
				data.Pid, data.Tid, time.Duration(data.DeltaNs), data.GetQuery())
		}
	}()

	// 等待退出信号
	<-sig
	fmt.Println("Exiting...")
}

要先生成桩代码

go generate
Compiled /home/fangyuan/code/go/src/github.com/767829413/advanced-go/eBPF/bpftrace/tool/tool_x86_bpfel.o
Stripped /home/fangyuan/code/go/src/github.com/767829413/advanced-go/eBPF/bpftrace/tool/tool_x86_bpfel.o
Wrote /home/fangyuan/code/go/src/github.com/767829413/advanced-go/eBPF/bpftrace/tool/tool_x86_bpfel.go

可以执行一下看看效果

sudo go run main.go
listening for events...
PID: 164368, TID: 163504, Latency: 918.573759ms, SQL: SELECT * FROM `fy`.`org_knowledge`

综上所述,这样一个完整监控容器内的 Mysql 慢查询的程序就完成了.

运行这个 Go 程序，并在其他窗口中登录 Mysql，执行一些查询，就可以看到慢查询 SQL 了.

讨论

bpftrace

bpftrace 是一个强大的工具，用于基于 BPF（Berkeley Packet Filter）技术的动态追踪和观察 Linux 内核及其应用程序的行为. 它提供了一种简单的高级语言，用户可以用来编写追踪脚本，而不需要深入了解 BPF 的底层细节.

比如 sudo bpftrace -p <container-host-pid> -e 'uprobe:/usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command { printf("%s\n", str(arg2)); }'.

主要特性：

  • 动态追踪：bpftrace 可以实时捕获和分析系统事件，帮助开发人员和系统管理员进行性能调优和故障排查.

  • 简单的语法：使用类似于 awk 的语法，bpftrace 使得编写追踪脚本变得更加直观和易于理解.

  • 内置函数：提供了丰富的内置函数，可以轻松访问系统信息、计算统计数据等.

  • 多种事件类型：支持跟踪函数调用、内核事件、用户空间事件、以及网络数据包等.

  • 高效：由于其基于 BPF 技术，bpftrace 在追踪时对系统性能的影响非常小.

使用场景：

  • 性能监控和分析

  • 故障排查

  • 系统行为分析

但是 bpftrace 的安装依赖相对较多，为了使用它，你不得不安装这些依赖：

  • BPF 支持的内核：需要运行支持 BPF 的 Linux 内核（通常是 4.1 及以上版本）.

  • 工具链：需要安装 clang 和 llvm，bpftrace 依赖这些工具进行代码生成和编译.

  • libbpf：一些版本可能需要 libbpf 库，用于与 BPF 相关的功能.

  • 其他依赖：还可能需要其他库和开发工具, 具体依赖可能因系统和版本而异.

bpf 辅助函数

像本文中使用的 bpf_probe_read_user_str 函数，还有 bpf_probe_read_kernel_str 函数，这些函数可以帮助我们读取用户空间和内核空间的字符串. 这些函数是非常有用的，可以帮助我们获取用户空间和内核空间的数据，从而进行分析. 想要了解这些函数，可以查看 https://man7.org/linux/man-pages/man7/BPF-HELPERS.7.html

修复 bpftrace 脚本

不管怎么样，针对这个场景，使用 bpftrace 脚本是最简单的方法，继续 AI 了一下不能执行的原因并修复.

首先这个脚本在先前的 Mysql 版本上是可以执行的，但是在新版本上不能执行，这是因为 Mysql 的 dispatch_command 函数的参数位置和类型发生了变化. 、

在抄袭别人的相关做法后,改动了一下脚本，尝试打印出 sql 语句了.

#!/usr/bin/env bpftrace

// 只关注第一个字段
struct COM_DATA {
    char *query;
};


// 跟踪 MySQL 中的 dispatch_command 函数
uprobe:/usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command
{
    // 将命令执行的开始时间存储在 map 中
    @start_times[tid] = nsecs;

    // 打印进程 ID 和命令字符串
    printf("MySQL command executed by PID %d: ", pid);

    // dispatch_command 的第二个参数是 SQL 查询字符串
    printf("%s\n", str(((struct COM_DATA *)arg1)->query));
}

uretprobe:/usr/sbin/mysqld:_Z16dispatch_commandP3THDPK8COM_DATA19enum_server_command
{
    // 从 map 中获取开始时间
    $start = @start_times[tid];

    // 计算延迟，以毫秒为单位
    $delta = (nsecs - $start) / 1000000;

    // 打印延迟
    printf("Latency: %u ms\n", $delta);

    // 从 map 中删除条目以避免内存泄漏
    delete(@start_times[tid]);
}

测试一下效果:

sudo bpftrace -p 163504 ./eBPF/bpftrace/mysql_dispath_new.bt
Attaching 2 probes...
MySQL command executed by PID 163504: SET NAMES utf8mb4
Latency: 0 ms
MySQL command executed by PID 163504: SHOW VARIABLES LIKE 'lower_case_%'; SHOW VARIABLES LIKE 'sql_mo..
Latency: 3 ms
MySQL command executed by PID 163504: SELECT SCHEMA_NAME, DEFAULT_CHARACTER_SET_NAME, DEFAULT_COLLATI..
Latency: 0 ms
MySQL command executed by PID 163504: fy
Latency: 0 ms
MySQL command executed by PID 163504: SELECT COUNT(*) FROM information_schema.TABLES WHERE TABLE_SCHE..
Latency: 1 ms
MySQL command executed by PID 163504: SELECT TABLE_SCHEMA, TABLE_NAME, TABLE_TYPE FROM information_sc..
Latency: 0 ms
MySQL command executed by PID 163504: SELECT TABLE_SCHEMA, TABLE_NAME, COLUMN_NAME, COLUMN_TYPE FROM ..
Latency: 0 ms
MySQL command executed by PID 163504: SELECT DISTINCT ROUTINE_SCHEMA, ROUTINE_NAME, PARAMS.PARAMETER ..
MySQL command executed by PID 163504: SET NAMES utf8mb4
Latency: 0 ms
MySQL command executed by PID 163504: fy
Latency: 0 ms
MySQL command executed by PID 163504: SHOW FULL TABLES WHERE Table_type != 'VIEW'
Latency: 0 ms
Latency: 2 ms
MySQL command executed by PID 163504: SHOW TABLE STATUS
Latency: 0 ms
MySQL command executed by PID 163504: fy
Latency: 0 ms
MySQL command executed by PID 163504: SELECT * FROM `fy`.`org_knowledge` LIMIT 0,500
Latency: 0 ms
MySQL command executed by PID 163504: SHOW TABLE STATUS LIKE 'org_knowledge'
Latency: 0 ms
MySQL command executed by PID 163504: SET NAMES utf8mb4
Latency: 0 ms
MySQL command executed by PID 163504: fy
Latency: 0 ms
MySQL command executed by PID 163504: SHOW COLUMNS FROM `fy`.`org_knowledge`
Latency: 0 ms
MySQL command executed by PID 163504: SHOW CREATE TABLE `fy`.`org_knowledge`
Latency: 0 ms
MySQL command executed by PID 163504: SHOW INDEX FROM `org_knowledge`
Latency: 0 ms
MySQL command executed by PID 163504: SHOW FULL COLUMNS FROM `org_knowledge`