进程异常退出，服务耗时异常，分享我的两个命令

一、背景

工作中经常遇到一些问题，一般使用一些常用命令一轮排查下来，就可以发现原因，进而针对问题提出解决方案，最后执行解决问题。

但是，实际情况，不管是高级工程师，还是专家工程师，也许由于专注方向不一样，他们可能并不知道这些命令。

所以，这里记录两个实际问题，以及使用哪个命令找到原因的。

二、进程异常退出

前段时间，有个高级工程师找我，说自己遇到一个神奇的问题。

原来，他的服务进程会异常退出，但是没生成 core 文件。
他定位了好久，找不到原因，没有任何头绪。

我要到对应的容器，登陆，输入一条命令，就找到了原因。

具体命令是 dmesg。

通过这条命令，可以查询系统的部分操作日志。

tiankonguse:~> dmesg  | tail  -1
[24419533.393616] Out of memory: kill process pid (xxx) score 13488918 or a child

可以明显看到，系统把那个同事的进程杀死了，原因是 OOM。

一个专家听说 OOM 了，跑过来，问前面那个数字啥意思？能查到什么时间被杀死的吗？

我回答，前面那串数字就是时间，但是以系统启动时间为偏移量开始计算的。

我这有资料，有个脚本命令，可以把这个时间计算转换为具体日期。

于是我把资料也分享给他们了。

这个资料是我 2014 年刚毕业的时候整理的，现在也分享给大家。

地址：https://github.tiankonguse.com/blog/2014/09/30/linux-command.html

三、服务耗时异常

有天中午，业务突然反馈服务耗时异常。

具体是有一个机器耗时异常，其他机器都正常。

我简单的看下监控，发现这台机器上的容器都有问题，不仅我的服务耗时异常，其他服务的耗时也异常。

于是可以得出结论：机器有问题。

本来我想马上分析为啥异常的。

但是想起之前有人告诉我，我马上把问题解决了，其他人都没机会展示自己了。

于是，那天一个下午和晚上，我都没去看这个问题，忙自己的工作去了。

当天晚上，一个专家问我这个问题进度怎么样了。

原来其他人都没解决这个问题。

我回复：今天下午在忙其他项目，第二天上午我优先看下这个问题。

第二天上午，我看了主被调监控、机器基础信息监控。
这些监控收集到的信息只能证明机器有问题，但是不能说明原因在哪里。

之后，我登陆机器，查看了连接数和 FD，也都正常。

然后执行了 strace 命令，就发现了问题。

这是 strace 的统计结果，不看后面的结论，你能看出问题在哪里吗？

% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 58.15 1050.585521        5488    191433           epoll_wait
 13.34  241.069793        6877     35054           nanosleep
 11.08  200.227059       25009      8006      2970 futex
  7.36  132.953537         312    424934           gettimeofday
  2.36   42.647595     1470606        29        13 restart_syscall
  2.08   37.599044         323    116377           clock_gettime
  1.37   24.825312         313     79307           epoll_ctl
  1.13   20.398439         318     64119           getpid
  0.41    7.491618         324     23079           write
  0.37    6.692929         320     20874           setsockopt

是的，如果没有一些知识储备，即使使用 strace 命令，也无法找到问题的原因。

我看了一眼，发现有一个蹊跷的地方。

具体来说， gettimeofday 这个 syscall 有问题。

很多年前， linux 内核就进行了优化， gettimeofday 不再走系统调用了，速度应该和访问内存差不多。

而这里，gettimeofday 却进行系统调用，明显不正常。

框架中的时间都是通过 gettimeofday 获取的，如果这个变成系统调用，一个高性能服务的性能瞬间就变得无限低了。

此时，服务耗时异常的原因找到了。

另一个专家提出疑问， gettimeofday 会导致卡顿？

我回答：是的， gettimeofday 走系统调用了，系统调用会切换到内核态，从而造成用户态的卡顿。

之后，我随手把多年前测试 gettimeofday 性能的小程序找出来，在正常机器与异常机器上运行了下。

正常机器运行一次需要 30 纳秒，异常的机器需要 3000 纳秒，相差 100 倍。

看到数据，才说服大家 gettimeofday 确实有问题。

于是，我给昨天咨询进度的专家汇报了进度，原因找到了。

至于机器为啥有这个问题，原因可能有三个：服务器硬件问题、内核配置问题、此版本内核不支持。
至于具体是啥问题，我就转给 linux 内核的同事了，让他们去进一步查看吧。

对了，strace 命令我多年前也写过简单的教程。
在这里：https://github.tiankonguse.com/blog/2016/08/28/strace.html

四、最后

总结一下。

第一个问题，通过 dmesg 系统日志，可以查看到服务进行被 OOM KILL 的日志。

第二个问题，通过 strace 统计，发现 gettimeofday 走系统调用了，从而导致服务卡顿，耗时异常。

我猜想，看这个文章的你都知道这两个知识点。
我这里只是记录下过程，你有什么要补充的吗？

《完》

-EOF-

本文公众号：天空的代码世界
个人微信号：tiankonguse
公众号ID：tiankonguse-code