Debug往事（二）

字节

天地大观，志存高远

​

目录

收起

背景

问题现象

初步排查

慢请求分析

应用日志深入分析

测试环境压测

首次抓到问题现场

问题再现

持续的 online debug

网络排查

CPU 使用排查

strace 中的发现

最终定位

一个神秘的 IP

一个可怕的写入

相关问题搜索

测试环境复现

最后的方案

经验总结

上一篇文章 中，我们聊了一个关于训练 lgb 模型 hang 住的问题。在日常工作中，很多疑难杂症都跟性能，稳定性相关。功能性的 bug 一般来说都比较好定位和解决，但性能和稳定性的问题很多时候连复现都是一件很头疼的事情。今天我们来聊聊一个 N 年前遇到的性能问题及排查经过。

背景

出现问题的业务系统来自某家兄弟公司，主要做基于云的智能收银系统。整个后端服务部署在阿里云上，在全国有数千家客户，使用各种收银客户端（手机，平板，手持 POS，一体机等）来进行各种点单，支付，后厨通信，外卖平台对接等功能。在用餐高峰期，每秒请求数在数千的级别，我们这次的问题，也主要出现在这个请求量较大的时间段。

整体的后端服务当时是使用 Python 来实现的，架构大体如下所示：

出现性能问题的请求链路是从自助点单客户端 -> 阿里云公网 SLB（负载均衡） -> 某台后端服务器 -> 某 Python 服务的容器 -> RDS/Redis 相关数据请求 -> 再按原路返回客户端。这部分还是相当直观的。

问题现象

在 2017 年 11 月 19 号的用餐午高峰时，我们在监控系统中发现了大量的慢请求告警，不少客户也反馈高峰期偶尔有几单的下单的等待时间很久。在后面持续 N 天的排查中，核心问题一直是这个高并发压力下请求响应变慢的问题。

初步排查

拿到一个性能相关的问题，你一般会如何处理呢？我的习惯性做法是以下几步：

1. 1. 一系列快速的系统情况检查，例如top查看 CPU 内存开销，以及最近的 load average，/var/log/messages和dmesg查看系统日志情况，df查看磁盘使用情况，vmstat或mpstat等查看 CPU 内存的一些具体指标，iostat -xm查看磁盘 IO 相关信息，sar -n DEV和sar -n TCP,ETCP来查看网络情况等。这个方法也成为 USE method，主要查看系统的 utilization, saturation 和 error 情况。
2. 2. 调查系统最近发生的变化，比如是否有做软件的升级发布，环境的各类依赖变更，用户量的变化等等。理论上来说，只有系统变化才会导致问题的出现。
3. 3. 根据前面获取的基本信息，结合历史排查经验，确定一个大致的排查方案，并在后续过程中不断迭代。

针对这个具体问题，我们依次做了这些初步诊断：

1. 1. 高峰期的 CPU 使用率大约在 60%，内存，磁盘 IO 等无异常。系统日志报错无异常。
2. 2. 最近基本没有代码变更，在 15 号的时候升级过一次 RDS。业务用户量最近没有明显变化。
3. 3. 初步看 CPU 并没有成为瓶颈，且 OLTP 类系统一般是 IO 密集型，所以初期的重点会放在 RDS，Redis 等存储系统，以及各个组件之间的网络 IO 分析，对慢请求的全链路做钻取分析。

考虑到这是一个实际线上运行的业务，每一次慢请求都会对用户造成不好的体验，因此我们在排查问题的同时，也要考虑到如何先尽快恢复服务质量。所以我们初步确定的方案是：

1. 1. 问题排查：核心放在慢请求的全链路分析上，找到根源。
2. 2. 问题复现：为了能更高效的定位问题，如果我们能在测试环境复现这个问题，那么就能更频繁的做各种检查，假设与想法验证了。所以我们同步需要做性能问题的复现。
3. 3. 线上预案：为了保障服务质量，我们决定先做集群扩容，看是否能解决问题。例如从 4 台后端服务器扩容到 5 台，理论上能提升 25%的吞吐量。有需要的话同时也可以升级其它组件，如 SLB，RDS 等。

慢请求分析

整个系统的日志都是通过 Fluentd 收集，存放到 ElasticSearch 服务中，前端通过 Kibana 展现和分析。我们第一步先通过各类应用日志来分析是否有性能问题。通过查看 Redis 和 RDS 的相关日志，我们发现高峰期有少量的超过 5s 的慢请求（大约 100 个以内），但是从后端服务的应用日志来看，同时间段超过 5s 响应的请求数量超过 40000 个。从这个现象来看，我们暂时先排除存储层的性能问题，提出假设 1：整体的性能瓶颈主要在 Python 后端。为了快速验证这个假设，我们决定先做后端服务器的扩容。

不幸的是，扩容上线后，慢请求的现象几乎没有任何改善，卡顿依旧。

应用日志深入分析

增加了后端服务器的数量，但是系统的性能却没有改善，我们需要进一步来分析应用日志中是否有我们没有关注到的问题。一个理想的情况是我们能获取到一个请求从发出到SLB，到虚拟机，到nginx容器，到Python容器，到业务应用逻辑，到RDS/Redis，再到返回路径等全链路的状态记录，找到具体在哪一段花费了最长的时间。但实际上这个链路的粒度可以被无限地zoom in，想从日志来直接定位往往是很困难且不现实的（日志量太大），我们只能利用日志来做分析，并在必要时进行更多信息的收集。

我们先把高峰期某台服务器的 Python 后端请求数量分布用 Kibana 查看了一下，发现一个比较奇怪的规律：

按理说在高峰期，请求数量应该是一个持续的高峰。但从这个请求数量的分布图来看，后端接受到的请求是“一阵一阵”的，在一个高峰之后，请求数量就会骤减，且每隔几秒就出现这个一个“波”。这难道是转发端的问题？于是我们就有了假设 2：怀疑转发层导致的问题，包括 SLB 和系统内部的 nginx。

进一步查看了 nginx 的日志，发现 nginx 的慢请求中，有些甚至是非常简单的健康检查 API，这些请求在 Python 后端基本就是直接返回，没有任何业务逻辑，为什么也会变得需要 5 秒以上才能返回？这里就会有一个新的假设 3：出现性能问题的应该是相对底层的部分，不涉及某个具体 API。

带着这些问题和假设，我们制订了尝试方案 1：

1. 1. 在测试环境压测 nginx 转发，同时模拟后端快慢请求混合的情况，看是否能复现 nginx 转发快请求时总体响应时间变慢的现象。
2. 2. 将 SLB 从性能共享型升级为性能保障型，同时提工单希望阿里云方面协助排查 SLB 的转发日志。
3. 3. 移除大部分的内部 SLB 使用，改为同进程内处理，减少 SLB 的使用量。这个改动需要发布代码。

测试环境压测

除了 nginx 压测，我们也开始尝试在测试环境进行整体问题的复现。这里的性能测试也有一些困难点需要解决，例如：

• • 系统中有很多涉及线上支付，外卖平台等的请求，有不少需要做 mock 的工作量。
• • 整体系统的部署结构上会有些差异，比如为了达到足够的系统压力，我们一般都会选择绕过公网 SLB 而直接使用内网的机器作为压测客户端。
• • 请求的组成比例与线上很难完全一致，不确定是否会有某些特定的请求组合导致卡顿。

Nginx压测方面，没有复现出慢请求会积压快请求转发的现象。全链路测试方面，我们使用 JMeter 构造各种场景进行了多轮压测尝试，但都没有复现线上这种呈“波动”状的诡异卡顿现象。这里比较难以界定无法复现的原因具体是什么，但感觉应该跟部署结构的差异有关。

首次抓到问题现场

这个性能问题并不是每个用餐高峰期都会出现，而我一开始也只是以帮忙想方案的方式参与，所以一直都还没有见到问题发生的现场。在经过了几天风平浪静的等待后，终于在 11 月 24 号的晚高峰期间，卡顿再次出现了！

赶紧打开vmstat来看下系统资源情况，发现一个奇怪的现象：

前面我们通过 Kibana 看到后端接收到的请求数量有一高一低，这里的 CPU 使用率也对应上了应用日志的“波”。在系统出现大量慢请求时，服务器的 CPU 使用率完全降了下来，我们愈发怀疑是转发方面的问题了。赶紧把上述尝试方案 1中提到的移除内部 SLB 应用的改动上线，然后就发现请求量和 CPU 使用率都上升了，且处于一个相对稳定的状态，看起来问题解决了？

问题再现

之前解决问题其实只是一个假象（在各种 debug 中太常见了），由于周末的业务压力相对小一些，所以卡顿没有出现。到了 11 月 27 号午高峰，问题很快又卷土重来。这时候我们的思考排查重点放在了服务端 CPU 使用率下降这个现象上。到底是因为前端转发请求没有进来导致的 CPU 空闲，还是服务端在等待其它请求的返回导致的空闲？还是说我们应用本身的 bug 导致了 CPU 空闲且请求没有被及时处理？

27 号的晚高峰，我们做了几方面的准备，形成尝试方案 2：

1. 1. 通过sar，netstat等工具构建相关脚本，重点关注网络 IO 方面的问题。
2. 2. 增加全链路的日志信息，希望挖掘慢请求链路的共通点。
3. 3. 准备一系列动态追踪工具，计划做 on-cpu，尤其是 off-cpu 的分析，看服务端 Python 进程到底因为什么被“赶下”了 CPU。

但是……27 号的晚高峰并没有出现卡顿。

持续的 online debug

28 号，继续严阵以待。这里我们会逐渐深入到服务端逻辑的全链路排查中，补充一些相关的背景信息：

1. 1. Python 总体的各类排查工具远没有 JDK 生态那么丰富（如强大的arthas，visualvm等），这方面可以做 profiling 的工具感觉很少。
2. 2. 我们的 Web 框架使用了 Tornado + Greenlet，单进程，使用协程实现异步操作，从而支撑高并发。
3. 3. 由于异步库的不完善，我们在数据库交互等方面又引入了 thread pool，把一些同步操作给异步化。
4. 4. 由于请求量太大，全量请求的日志粒度无法做的很细，对慢请求的 drill down 造成一定困难。

到了 28 号的午高峰，卡顿如期而至……由于线下暂时无法复现，每次吃饭高峰期的这一个小时就成了我们最重要的观察，尝试的时间窗口。

网络排查

通过ping和nicstat进行观察，整体的延迟和流量带宽都比较正常，不超过 10Mbps。

通过ss -s查看网络端口情况，发现 timewait 的占用卡在了 5000：

于是我们又有了假设 4：是否是因为 timewait 达到上限而导致网络层面卡顿？不过我们后续查看了系统的内核参数，已经设置了tcp_tw_reuse和tcp_tw_recycle，且网络端口占用量也远远没有达到系统上限，这个假设被排除。

CPU 使用排查

为何服务器的 CPU 使用率会在高峰期反而暴降？考虑到我们使用了云服务部署，提出了假设 5：是否我们的虚拟机在高峰期无法抢占到 CPU 使用权？这里我们快速做了个测试，在 CPU 使用率降低的时候启动一些计算密集型测试程序，发现使用率一下子就上去了，所以也不是虚拟化方面的问题。

由于 SLB 是阿里云的服务，我们无法直接排查关于转发层的假设 2，所以我们先把精力投入到假设 1的后端应用 CPU 开销分析中去。我们分别在 CPU 使用率高和使用率低的时候使用strace来观察一下系统调用情况。在 CPU 使用率高时：

在 CPU 使用率降下来时：

可以明显看到系统在空闲时有大量的 stat 调用。这里是因为我们没有关闭 Tornado 的自动热部署功能，导致系统不断在检测相关 Python 文件是否有改动。根据这个观察提出假设 6：是否由于文件监控导致系统 IO 开销过高？但从磁盘 IO 的情况来看，这部分并没有多大开销，整体的 IO 使用率远没有到达瓶颈。

对于高 CPU 使用率的问题，基于 perf 工具生成的火焰图 是一种非常好的性能 profiling 手段。对于我们遇到的 CPU 使用率下降问题，理论上也可以用 off-cpu 火焰图来进行排查。对于 on-cpu 的火焰图，我们分别在 CPU 使用率高和低的时候进行火焰图抓取，对比来看是否能找到 CPU 空闲时的系统问题：

初步看不出啥问题来，而且因为缺少 debug symbol，Python 部分的火焰图也无法完全显示。

再看下 off-cpu 的火焰图，看看进程到底在等待啥？

看起来也是正常的系统调度和 IO。

为了看到 Python 部分的调用栈，我们又引入了 Pyflame：

为什么会有大段的 idle 呢？这会不会跟我们的 CPU 空闲有关？查看了下 Pyflame 的文档，发现这部分的 idle 可能涉及到 IO 操作，或者是一些不占用 GIL 的代码，例如 numpy 之类的库。在我们的系统中，用到了 Greenlet 来替代 Tornado 默认的协程实现，这部分由于很多逻辑使用底层的 C 实现的，会被计入 idle 部分中去。所以我们结合之前的假设 1和假设 3，进一步缩小范围到假设 7：是否是 Greenlet 相关代码导致了 CPU 等待？

顺着这个方向，我们又集中排查了 Greenlet 相关的 issue，我们的代码实现，以及近期 Greenlet 版本的变更说明。仍然没有什么新的发现……

strace 中的发现

到了 28 号晚高峰，我们根据之前的一系列探索，又制订了一套尝试方案 3：

1. 1. 使用 Pyflame 抓取 Python 进程中所有 threads 的 callstack 火焰图，观察是否在 thread pool 的调用中导致了卡顿。
2. 2. 尝试把代码回滚到问题出现几周前的稳定版本。
3. 3. 高峰期服务降级，把一些数据分析，web 管理等非点单核心功能关闭。
4. 4. 针对上面怀疑的 greenlet 问题，增加相应的协程切换性能日志。
5. 5. 增加每台服务器的 Python 进程数，以此降低每个进程中 greenlet 的切换频率。
6. 6. 抓取若干 strace 日志，再深入分析。

从晚高峰的监控来看，greenlet.switch方法的确会带来一些性能开销，但是更底层的 callstack 我们获取不到了。从两个观察我们暂时排除了假设 7对 greenlet 的怀疑：

1. 1. 从具体慢请求日志判断，greenlet 的额外开销应该不会到达 5 秒以上的程度。
2. 2. 在线下环境压测无法复现，理论上来说 greenlet 这部分的代码线上线下是完全一致的。

无奈之下我们只好对海量的 strace 日志做人肉观察分析，通过线程号来串联各个系统调用的前后关系，并重点关注耗时长的系统调用。果不其然，发现了一些奇怪的 futex 调用，耗时长达 10 秒以上：

在 18:24:13 时 25588 线程执行了 futex wait:

然后直到 18:24:26 时 25221 线程才唤醒了 25588 的 futex wait，耗时 13 秒，与我们发现的典型慢请求时长类似：

我们对这个 futex wait 现象进行了一番搜索，发现有人碰到过类似问题：

这就又形成了一个假设 8：是否是我们代码中的 queue.get 之类的操作导致了 Python 进程长时间等待？我们立刻搜索了一下代码中使用队列或者其它线程安全类数据结构的使用，果然发现了一处可疑点：

不过经过一番分析，这个假设也被推翻了，原因与 greenlet 的怀疑类似：

1. 1. 线下压测环境中并没有复现。
2. 2. 仔细看 strace 日志，服务端调用 accept 之后，立刻调用了 futex wake，所以这个长时间的 futex 并不是在等待内部队列，而是在等待外部请求。我们在测试环境通过一个简单的测试就能复现类似的 strace 日志：先启动服务，等待 10 秒后再发送第一个请求。

在分析 strace 日志中，又发现 epoll 调用的奇怪现象，服务端经常出现长时间的 epoll 调用没有任何事件进来：

但后面突然涌入 11 个事件：

这个现象又回到了我们之前的假设 2。我们联系了阿里云的工程师协助帮忙排查了 SLB 的转发，不过从他们那边的观察来看，却是我们的服务没有响应他们转发过来的请求。排查又陷入了僵局。

最终定位

29 号午高峰之前，我们准备了尝试方案 4，主要方向仍然是假设 2，其内容结合了之前一天的发现以及阿里云工程师对内核参数修改的一些建议：

1. 1. 把假设 8中的执行队列获取进行了超时控制，确保这部分不会出问题。
2. 2. 内核参数调整，包括tcp_max_syn_backlog，somaxconn等。
3. 3. 增大 Python 服务中的 backlog size。
4. 4. 增大 nginx 配置的 worker size，review 其它相关配置。
5. 5. 开始寻找系统中除了 SLB 和 nginx 之外的转发层，例如从虚拟机到 docker 层面的请求传递。

虽然改了代码和相关参数，但这天中午的卡顿仍然照常出现了。我们抓住时机快速进行了一些验证：

1. 1. 使用 tcpdump 抓包，查看 SLB 是否有请求转发积压问题。很快我们就排除了 SLB 的嫌疑。
2. 2. 卡顿出现时使用 docker exec 在容器内部做服务的健康检查，绕过所有其它网络层，发现在容器内访问 localhost 也会卡顿！

现在我们又缩小了排查范围，聚焦到以下两个假设：

• • 假设 9：是否问题出在 Docker 相关的进程层面？
• • 假设 10：是否问题出在 Python 依赖的某些通用外部服务层面？

一个神秘的 IP

先从假设 10入手，继续深挖 Python 应用的 strace 信息，重点关注各类外部服务请求。很快我们就找到了一个神秘的 IP：

# strace -p 3653
Process 3653 attached
connect(28, {sa_family=AF_INET, sin_port=htons(25), sin_addr=inet_addr("42.120.226.4")}, 16

查了一下发现这个是阿里云邮的 IP，我们的服务会调用它来实现告警，客户通知邮件等功能。查看了下代码逻辑，这部分的实现有些问题，如果发送失败会导致进程 hang！于是我们立刻下掉了所有线上的邮件相关服务，观察了一会，卡顿依旧……

一个可怕的写入

继续追查 strace 日志（请求量大时这个日志是真的很大，可以看半天），发现了一个可怕的 write 操作：

这个写入竟然花了 23 秒才完成，但写入内容只有 79 个字节，太奇怪了！

我们对这个 fd 5 进行了追踪：

readlink /proc/[pid]/fd/[fd]

发现是个 pipe: [36133104]，然后再用lsof查看这个 pipe 的使用者：

这里有 docker 进程，感觉跟假设 9也联系上了。继续查看docker-containerd-shim的 strace 日志，发现有同样的卡顿情况：

同样用readlink追踪 fd：

# readlink /proc/19834/fd/16
/run/docker/libcontainerd/ceb3e92789d0a229d57abd4ef11a942877617a1fdff1c10eb0a9ee9fa261677a/init-stdout

标准输出！这时候已经有怀疑对象了。不知大家有没有猜到 🙂

继续用lsof查看谁使用了这个 stdout：

最后再看看 dockerd 的 strace 以及相应的 fd 信息：

而上面最终找到的这个服务地址，就是我们的 fluentd 服务。这时候的现象已经比较明确了，我们提出最后一个假设 11：容器日志收集的 fluentd 是整体的瓶颈，导致 docker 容器在写入 stdout 时阻塞，导致服务的卡顿。

相关问题搜索

通过一番搜索，发现网上也有一些类似问题，例如 k8s 的这个 PR：

即使到 4 年后的今天，moby 项目中还有 相关的 issue 处于 open 状态。

测试环境复现

有了明确的定位，复现问题也更加方便了：

• • 在测试环境部署 fluentd。
• • 配置 nginx/python 服务的日志输出到 fluentd。
• • 使用非常长的 url 来进行压测，制造大量日志。

很快 CPU 使用率忽增忽降的现象就得到了重现。

最后的方案

29 号的晚高峰，我们准备了尝试方案 5，主要针对上面发现的日志服务问题：

1. 1. 临时方案：部署的 5 台服务器中，只保留其中一台的日志，其它全部关闭（不能全关，那样啥都看不见了）。
2. 2. 精简了一系列服务端的日志。
3. 3. 修复了之前发现的邮件服务的阻塞问题。
4. 4. 仔细复查其它各处操作的超时设置。
5. 5. 在代码注释中加入虔诚的信仰 🙂

晚高峰开始之后，我们开始了紧张的人肉监控（因为大多数的日志被下掉了）。终于，CPU 的使用率稳定了，慢请求也随之消失，持续了 1 周的排查终于找到了罪魁祸首。

经验总结

所以最终这个问题的原因是因为我们的 EFK 套件是个系统单点。正常情况下一天的日志量超过了 30GB，而我们在性能问题的排查中又额外增加了很多日志，无形中反而加剧了这个问题。

从问题排查层面来说，我们应该更早针对系统整体架构中的各个单点进行深入排查。一开始的确没有想到一个小小的日志写入，充其量也就是多占点磁盘和 IO 带宽，竟然可以让整个服务都不可用。此外排查的过程中在前端转发层和 CPU profiling 方面走了一些弯路，这部分的排查效率及方法论应该需要提升。

从工具层面来看，对于这类系统hang的问题，strace的确是一个非常优秀的排查工具，帮助我们最终定位到了原因。当然strace的性能overhead是很大的，所以对于很多涉及CPU使用优化类的场景，perf之类的工具会更实用。跟strace类似的还有像ltrace, ftrace等。近两年还有很多新的工具涌现，例如LTTng，基于eBPF的bcc, bpftrace等，值得关注学习。

从质量保障层面看，我们的复杂性能，稳定性测试非常欠缺，只能依赖线上出问题时候的 online debug，对于整体尝试迭代效率来说影响非常大。当然复杂测试场景的构建本身也是需要研发资源的投入的，这里面需要做一定的权衡取舍。

从服务预案层面看，我们除了加机器，升级 SLB 服务等，缺少在找到问题根源之前快速消除对客户使用影响的方案。过程中我们有同步考虑例如额外部署一套腾讯云的服务，迁移一部分用户到新环境的方案，但一些业务和系统部署的耦合点导致这个方案难以推进，例如涉及到客户端的升级，第三方服务的白名单配置，回调服务注册等等。对于比较关键的业务系统，各类容灾，降级的方案必须要提前思考与设计。

最后，如果大家对这个性能问题的排查过程有任何想法，欢迎留言讨论！

编辑于 2021-10-07 18:05

编程

软件调试

性能优化