strace k8s nfs flock

strace：不仅仅是运维利器，也是定位问题神器

strace: not just a tool for operations, but a tool for locating problems

Posted by Gangzi on November 13, 2019

全文字数：1898个，阅读时长：约5分钟

收获：

在阅读完本篇文章之后，你会得到以下收获：

  1. strace的使用方法和原理
  2. k8s上集群的调试思路

背景：

近期公司内部业务调整，之前的部署在docker上的服务需要迁移到k8s集群上，服务的docker image早已准备好，剩下的就是在k8s集群上面部署了，本以为很简单的事情，没想到还是经历了很多坑，分享给大家，希望大家在遇到的时候，可以避免。

现象：

同样的docker镜像， 在k8s集群上（由4个宿主机组成）上进行性能测试，发现cpu利用率很低（最高5%），导致响应时间长（2s~4s），而在docker上（部署在单台宿主机）用同样的方法测试，结果显示cpu利用率高（30%以上），响应时长短(200ms左右)。

怀疑1：k8s的是否有CPU节流的限制

访问k8s集群上的服务的数据流向为: Client –>VIP:VPort –>负载均衡器 –>NodeIP:NodePort –> kube-proxy(iptables) –> Pod Backend。

经过运维的排查，k8s的网络是没有问题。

怀疑2：经过服务日志耗时，定位到查询数据库返回慢

拿单独的查询数据库语句测试，结果返回很快。

曙光：strace

cpu利用率低，进程变慢，该如何定位呢？没错，轮到本篇的文章的主角登场：strace。

strace是Linux系统调用的追踪工具，可以追踪一个进程产生的所有系统调用，包括参数，返回值，执行消耗时间，而这个功能非常契合，帮助定位我们当前的问题。

strace 的操作是由 ptrace的内核特性实现的。

简单的了解的strace的描述和原理，接下来就是使用它。

坑1：容器里没有安装strace工具

1.进到容器里面，敲入strace，返回bash:strace:command not found ，发现容器里没有安装strace。

2.很自然的想到用yum install -y strace来安装，运行命令后，返回 bash: yum: command not found

查看系统是Debian

1
2

cat /etc/issue
Debian GNU/Linux 10 \n \l

3.对于不同操作系统，会用到不同的包管理工具，在这里简单罗列下各自操作系统对应的包管理工具：

  • apt-get属于ubuntu、Debian的包管理工具

  • yum则属于Redhat、Centos的包管理工具

4.有了上面的认知，我们继续安装strace、lrzsz、lsof，其中最后两个命令后文会用到。

1

apt update;apt intall -y strace lrzsz lsof

坑2：k8s上对于多进程同时写日志文件的服务，使用了网络文件系统（NFS）

根据性能测试的分析得到结果是处理慢，而不是请求慢。

那么让我们进入到容器，定位到底是哪个流程处理慢。

1.在安装strace之后，使用它收集系统调用日志，以下是操作详情：

1
2
3
4
5
6
7
8
9
10

kubectl -n  your-namespace exec -it your-pod /bin/bash
# 查看进程情况，包括进程id
ps aux|grep server
# 在本地可以持续不断的请求容器服务
ab -n 9999999 -c 2 -p post_data.txt -T 'application/json'  http://ip:port/your_service_path
# 开始跟踪进程pid，标记时间和每个调用消耗时间，各自的进程输出到对应文件中，方面后面独立分析
strace -f -T -tt  -ff -p 8 -p 9 -p 10 -p 11 -p 12 -p 13 -p 14 -p 15 -o strace_pids.log
# 下载文件
sz strace_pids.log.8 strace_pids.log.9 strace_pids.log.10 strace_pids.log.11 strace_pids.log.12 
strace_pids.log.13 strace_pids.log.14 strace_pids.log.15

2.得到每个进程的系统调用文件后，开始肉眼分析。

这一个的系统调详情为flock(10, LOCK_EX) = 0 <2.999736>，发现有长达2s的调用，该信息出现在了strace_pids.log.14的文件中，说明是进程14处理，关键系统调用如下：

1
2
3
4
5

12:32:33.565974 getpid()                = 14 <0.000010>
12:32:33.566028 flock(10, LOCK_EX)      = 0 <2.999736>
12:32:36.565840 lseek(9, 0, SEEK_END)   = 350681157 <0.000031>
12:32:36.565922 lseek(9, 0, SEEK_CUR)   = 350681157 <0.000030>
12:32:36.566073 flock(10, LOCK_EX)      = 0 <0.000288>

3.查看linux手册，可以知道，2s的操作花费在了 文件写锁上

1
2
3
4
5
6
7
8
9
10
11
12
13
14

man flock

NAME
     flock -- apply or remove an advisory lock on an open file

SYNOPSIS
     #include <sys/file.h>
     #define   LOCK_SH   1    /* shared lock */
     #define   LOCK_EX   2    /* exclusive lock */
     #define   LOCK_NB   4    /* don't block when locking */
     #define   LOCK_UN   8    /* unlock */

     int
     flock(int fd, int operation);

4.接下来看进程14干了哪些事情：

1
2
3
4
5

lsof -p 14

COMMAND PID USER   FD      TYPE             DEVICE  SIZE/OFF       NODE NAME
python3  14 root   10w      REG              0,119         0 7801615334 your_log_path/log.lock (x.x.x.x:/your_k8s_log_path)

到这里疑团被揭开，问题的真相显现出来。

结论：

由于这边的服务都是多进程，之前都是在单台服务器上写的本地文件，所以会很快，但是到了k8s集群这边，换成了多个机器同时抢占同一个网络文件系统上（nfs）的锁的时候，会等待其他机器释放锁，进而导致请求响应变慢。

1.如果服务是单进程多线程的情况，典型的服务比如Java Web程序，部署k8s集群情况大致如下图所示：

​ 每个宿主机上，会存在多个pod，每个pod上启动一个进程，进程写入的日志文件会通过filebeat或者flume传递给kafka等agent上面，后面会写入统一的平台，供查询日志使用。

2.如果服务是多进程多线程的情况，典型的服务比如Python Web，部署的情况大致如下图所示：

如果没有考虑多个机器同时写入网络文件系统的日志文件锁的问题，就会出现下图情况：

会等待其他机器释放锁，从而导致的处理请求变慢，响应时间变长的问题，而这个在单台机器上是没有问题的。

改进方法可以是：

  1. 写入本地文件系统，之后在同步到日志agent。

  2. 统一写入到统一的日志系统（比如redis）里面，而不是本地文件系统，这个可以根据业务需要来选择。

后记:

对于一个问题我们要持有一颗追查到底的决心和冷静的态度，这样才会有可能找到事情的根本原因。

每次定位到问题后，会不禁地长舒一口气，仿佛全身的气力已用光。但换来的确是身心舒畅！

如果大家遇到类似的系统调用问题，或者有这方面的使用经验，也欢迎大家来分享交流~

（完）

参考：

FEATURED TAGS
Reading notes
FRIENDS