昨天部署系统，准备重新测试一下 TiKV，不过令我比较吃惊的是，之前能顺畅跑出来的测试现在无论怎样都跑不出来，当时就吓出一身冷汗，觉得 TiKV 是不是最近有啥改动导致性能下降非常厉害。
翻了日志，发现每隔一分钟，TiKV 就收到了一个 signal 15 的信号，被 kill 掉了，如下：
2017/11/29 22:11:14.593 signal_handler.rs:68: [INFO] receive signal 15, stopping server...
2017/11/29 22:12:34.629 signal_handler.rs:68: [INFO] receive signal 15, stopping server...
2017/11/29 22:13:54.669 signal_handler.rs:68: [INFO] receive signal 15, stopping server...
但到底是谁干的呢？因为这台机器是公用的开发机器，上面有一些其他同学跑的进程，所以即使全部 ps 列出来，一个一个排查，这个时间也会比较久，幸好，我们有 systemtap。
首先写了一个 systemtap 脚本，给 signal kill 的处理加上 probe，直接从 systemtap 官网抄了一个例子：
probe nd_syscall.kill
{
target[tid()] = uint_arg(1);
signal[tid()] = uint_arg(2);
}
probe nd_syscall.kill.return
{
if (target[tid()] != 0) {
printf("%-6d %-12s %-5d %-6d %6d\n", pid(), execname(),
signal[tid()], target[tid()], int_arg(1));
delete target[tid()];
delete signal[tid()];
}
}
上面的脚本就是监控系统调用 kill 命令，毕竟你要 kill 进程，就得发送这个命令的，然后执行，看到了如下的输出：
118620 killall 15 118179 582
118620 killall 15 118180 582
118620 killall 15 118183 582
上面 118179 就是 TiKV 进程，也就是进程 118620 干了这个事情，于是立刻看这个进程，发现竟然不在了，也就是说，这个进程也是一个临时被启动的进程，干完了 kill 的事情，就功成身退了。于是，继续用上 systemtap，probe 进程的创建，仍然是从网上抄的代码：
probe kprocess.create
{
printf("%-25s: %s (%d) created %d\n",
ctime(gettimeofday_s()), execname(), pid(), new_pid)
}
probe kprocess.exec
{
printf("%-25s: %s (%d) is exec'ing %s\n",
ctime(gettimeofday_s()), execname(), pid(), filename)
}
跟之前的 systemtap 脚本放在一起跑，发现：
Wed Nov 29 15:16:36 2017 : bash (117037) created 138912
Wed Nov 29 15:16:36 2017 : bash (138912) is exec’ing “/usr/bin/killall”
138912 killall 15 138108 582
138912 killall 15 138109 582
138912 killall 15 138112 582
上面清楚的说明有一个 bash 进程 117037 创建了一个子进程 138912，然后这个进程执行了 killall，干掉了所有的 TiKV，于是看进程，找到对应的脚本，发现里面赫然干了一件事情：
for t in $(seq 1000000); do
killall tikv-server
sleep 80s
done;
原来是一个同事之前测试 TiKV 的时候，想通过定期的 kill TiKV 发现一些问题，结果他忘记结束这个测试脚本了，于是我再用这台机器的时候就悲催了。
这次问题排查通过 systemtap 很快就定位了问题，现在越来越觉得 systemtap 是一个非常强大的工具，后面需要多多学习，多尝试在系统曾名用系统工具，譬如 systemtap，eBPF 等来解决问题。
网友评论