自定义 Trace 日志格式

2023-12-23 18:02:14

之前在添加 IO 的 Trace 日志时，由于每一次 open、close、read、write 都去打日志，同时会通过 fd 参数去获取真正的文件名（使用 readlink 去读取 /proc/self/fd/<fd>），导致异常卡顿。优化点之一就是只去记录主线程的 IO 行为，也就是只记录由主线程创建的文件句柄的行为。

trace 日志功能的一个核心是通过 trace 日志去理解主线程的 IO 行为，发现 IO 异常，以及慢查询的根因。trace 日志最理想的方式是，在主线程里通过 fd 拿到文件名，以及记录 IO 操作的属性，这与内核 trace 机制契合度最高。

IO 的内核 trace 也是在 IO 创建的时候，将文件名和 IO 操作属性一起记录下来，而不是记录 fd。记录 fd 只是为了将 fd 和真实文件名联系在一起。因此，我们在 trace 日志中只记录 fd，文件名和 IO 属性则直接由内核 trace 机制获取。这样就不用通过 readlink 去读取真实文件名了，从而避免了在内核态下的字符串复制开销。

Trace 日志输出格式

在 trace 日志里，每个 IO 操作的格式如下：

[FD]xxxx: yyyy:  zz:  {operation}[OBJNAME]

其中：

FD：文件符，4 位长度
xxxx：IO 操作所属进程ID，4 位长度
yyyy：IO 操作所属线程ID，4 位长度
zz：IO 类型，1 位长度
operation：IO 操作，至少 1 位长度
OBJNAME：IO 操作的对象，长度不定

比如：

[ 10]:  10:  0: r /tmp/t.txt

表示进程 10 的线程 10 执行了一个 read 操作，操作的对象是 /tmp/t.txt 文件。

Trace 日志输出类型

IO 类型

IO 类型有以下几种：

0：read 操作
1：write 操作
2：lseek 操作
3：fsync 操作
4：truncate 操作
5：open 操作
6：close 操作
7：dup 操作
8：ftruncate 操作

操作对象

操作对象有多种：

文件，以/开头
管道，以|开头
套接字，以@开头
终端，以>开头
共享内存，以$开头

文件状态

文件状态有以下几种：

r：可读
w：可写
x：可执行
rw：可读写
rx：可读执行
wx：可写执行
rwx：可读写执行

Trace 日志输出示例

以下是一些 Trace 日志输出示例：

[ 10]:  10:  0: r /tmp/t.txt
[ 10]:  10:  1: w /tmp/t.txt
[ 10]:  10:  2: l /tmp/t.txt
[ 10]:  10:  3: f /tmp/t.txt
[ 10]:  10:  4: t /tmp/t.txt
[ 10]:  10:  5: o /tmp/t.txt
[ 10]:  10:  6: c /tmp/t.txt
[ 10]:  10:  7: d /tmp/t.txt
[ 10]:  10:  8: f /tmp/t.txt