Weird bugs - 1

奇怪的 bug 系列 - 1

Posted by Di Chen on March 25, 2017

“There are two ways to write error-free programs; only the third one works.”

– Alan Perlis, “Epigrams on Programming”

前言

在这几年的开发生涯中,遇到了或多或少的奇怪的BUG。从前端的浏览器兼容到后端的 DNS 解析,从常用的 ssh 到大部分人都不会关心的编译器优化。在排查问题的过程中,我也获益良多。往往为了排查了解一个问题的原因,需要用到多个领域的知识。在此也记录下我在 debug 一些奇怪问题的过程与方法,希望能与大家分享学习。


服务器响应时长由 20ms 变为 5s

问题表象

在开发一个新的 Restful 服务器的时候,我使用了 Django 框架作为服务器的后端框架。为了保证服务的延迟在预期的范围内,我接入了 Datadog 性能监控服务来监控 Django 服务的延迟。

此时,我在 Datadog 的监控板上,发现有一个请求的平均延迟达到了 1000+ ms,这个是远远超过了我定下的 SLA,于是便开始排查到底是什么原因,并且想要怎样优化。

排查方式

确认延迟分布

在监控服务器延迟的时候,单个数字是无法准确地表达出问题的。在 Google 的 Site Reliability Engineering 一书中提过,在监控服务器延迟的时候,监测 50%, 90%, 99% 的请求延迟会更有代表性。如下图。

sre_latency

在查看了服务器请求延迟的分布表后,我发现 90% 的请求都在 100 ms 以内就完成了,但是有 10% 的请求会出现延迟达到 5s 的情况。手动发送 HTTP 请求也证明了,高请求延迟的情况并不是每次都会出现,也就是说这个 bug 是不能 100% 重现的。

偶尔出现的高请求延迟,长达5秒: request-latency-high

大部分时间在 20 ms 内完成: request-latency-low

在这个时候便有两个推测:

  1. 每次延迟增加的时候都是固定增加 5s,这说明延迟增加的事件有一定确定性,5秒这个时间应该是某个配置中的,比如某个 timeout 的时间。
  2. 不是 100% 可重现的事件,第一反应便是线程死锁,或者数据库死锁,第一次操作失败,并且在重试时成功。

推理以及分段排查

Profiling

在解决服务器延迟高的问题时,靠猜显然是不能解决问题的,必须靠 profiling 来帮助我们准确定位具体延迟高的代码。在现阶段已经有了比较完整的 profiling 工具链来帮助我们,从 OS 层的 dtrace, strace,再到框架层的 django-debug-toolbar,我们应该利用这些工具帮助我们排查性能问题。

在这里,由于我是用的服务器框架是 Django,所以利用的是 django-debug-toolbar 自带的 profiling 功能。

在触发了长延时的 bug 之后,django-debug-toolbar 中的 profling 结果显示如下:

django-profile-1

从上图可以看出,在数据库的连接时,建立连接花了5秒钟,这个是导致整体请求延迟的主要原因。

P.S. 在使用 django-debug-toolbar 的时候,如果返回的内容不是 html 格式的,而是 json 格式的,则 toolbar 并不会显示出来,我自定义了一层 django middleware,将 json 格式的 response 转化为 html 格式的,从而触发 toolbar 的显示。

P.S. 对于 POST HTTP 请求来说,不好像 GET 请求一样在浏览器中触发并浏览 toolbar。于是我安装了 Request History Panel for Django Debug Toolbar。这样可以先用 curl 发送一个 POST 请求,然后再用 GET 请求获得 toolbar,在 toolbar 中切换到之前的 POST 请求,查看具体的 profile 结果。

数据库连接排查

在涉及到网络连接时,问题就变得复杂了。数据库的连接时间虽然是5秒,但是并没有失败,说明在数据库连接中应该有某个超时的操作,但是后续重试成功了。这个问题有可能与多个因素相关,比如 Django 服务器的线程冲突导致资源不足,或者宿主主机资源不足,或者 DNS 解析超时,或者虚拟机桥接内核有 bug (我部署在阿里云的容器服务上,应该有两层虚拟化,一层是 ECS 主机的虚拟层,一层是 docker 的虚拟层),也有可能是阿里云版的 PostgreSQL 内配置了某些防火墙,导致连接不稳定。

在这个时候我做了两件事:

  1. 在宿主主机启动一个本地版本的 PostgreSQL,并用 Django 服务器连接宿主主机版本的 PostgreSQL,看看是否有长延迟的情况。发现没有长延迟的情况。初步判定长延迟只出现在与阿里云 RDS 的连接上。
  2. 在开发用的 ECS 上启动 docker 镜像连接阿里云 RDS,发现也不会出现长延迟的情况。初步判定长延迟只出现在阿里云的容器服务与阿里云 RDS 的连接上。

由于我对阿里云的容器服务和 RDS 的内部架构配置不了解,我提交了一个工单请求阿里云 RDS 组协助排查。

在工单排查中,使用了 tcpdump 来抓包在建立连接时,数据库连接端口的所有 tcp 包。在 wireshark 中可以看到所有 tcp 连接都成功建立了,并且没有出现超时的现象。RDS 数据库的问题便被暂时排除了。

docker 网络状态排查

由于这个问题只会在阿里云的容器服务上出现,便将工单移交至阿里云的容器服务组进行进一步排查。

此时,我想起了在设置服务器监控时,我将 docker 镜像的网络连接方式由 bridge 模式切换到了 host 模式,以便将 docker 中的数据直接发送至 8125 端口 (datadog agent 的默认数据收集端口)。会不会是由于 docker 镜像的网络连接方式改变而导致的问题呢?

此时,我将 docker 镜像的网络连接方式调回了 bridge 模式,数据库连接长延时的问题便消失了!

在同一时间,阿里云的容器服务组将问题反馈给了阿里云的溪恒,在研究后发现是 DNS 解析数据库地址时超时了,DNS 连接超时时间的配置在 /etc/resolv.conf,如果将 timeout 的时间改为 1 秒,则长延迟只会有1秒。阿里云容器服务组提供的建议是使用 nscd 模块缓存 DNS 解析结果:

$ sudo apt-get install -y nscd
$ service nscd start

由于宿主 ECS 服务器使用了 nscd 缓存 DNS 的解析结果,所以如果直接在宿主上运行 Django 服务器,则不会出现连接超时的情况,但是如果在 docker 内运行 Django 服务器,由于 docker 内没有安装 nscd,则会出现连接长延时的情况。

这个也解释了为什么之前抓包数据库连接的时候看不出问题:由于 DNS 解析是发生在 tcp 连接建立之前,tcp 连接信息只包含了 ip 地址,所以在 tcp 包中看不出连接有问题。

同时,由于 DNS 解析超时之后会再进行重试,所以虽然一次解析超时,但是第二次解析成功后,数据库连接仍然可以正常建立。

解决方法

解决方法包含两部分:

  1. 在容器的 Dockerfile 中增加 nscd 的安装。这个模块理论上应该安装在所有 docker 容器中以优化 DNS 解析速度。
  2. 降低 DNS 解析超时配置。将 /etc/resolv.conf 中的 timeout 时间改为 1 秒,以避免由于 DNS 解析超时时,有不必要的长延迟。
  3. docker 容器使用 bridge 模式。

经验总结

在这个事件中,学到了这么几点:

  1. 性能监控应该及早安装。

    从开发的早期,就应该安装性能监控,从而每一次小的改变对性能有怎样的影响都可以清晰地看出来。若是到了开发的后期才安装性能监控,要优化时就需要 profile 代码才能找到性能瓶颈。

  2. DNS 解析是属于网络基础架构底层的服务,但是往往对上层的应用有极大的影响。

    大部分开发者往往会忽视 DNS 解析在网络应用中的影响,但是,DNS 是网络中非常脆弱的一环。从近期多次 DNS 服务器遭受 DDOS 攻击导致的互联网瘫痪可以看出,DNS 的容灾和安全性也是服务架构中需要考虑的。同时,DNS 缓存在大部分场合也都是需要的。只不过 DNS 缓存也同时伴随着一定的风险。比如在 Name Server 的配置修改之后,往往需要等待缓存过期才能在客户端生效。

  3. 遇到问题的时候,先思考最近修改了什么。

    这个其实是在 Bloomberg 时 Team Leader 教的第一课。只是在这次事件中,长连接延时是由于安装监控服务而引入的 (将 docker 网络模式改为 host 模式)。就如同薛定谔的猫一样,在没有测量之前,它没有这个问题,在测量之后,我也不确定这个问题是原本存在的,还是由于测量导致的。这个也是排查困难的主要原因之一。

下一步

到目前为止,服务器的请求延迟已经恢复正常,但是仍然有几个问题不得其解:

  1. 为什么这个问题只会在 docker 网络模式为 host 模式时出现,host 模式理应使用宿主的网络栈,也就是说,在 host 模式时,应该会使用宿主的 nscd 来缓存 DNS 解析结果。
  2. 当 nscd 缓存 miss 时,nscd 同样会使用 DNS 服务器进行 DNS 解析,也有一定几率会出现 DNS 解析长延迟的情况,那么我们只是降低了问题出现的概率和时间,但并没有根本上解决问题的所在,即为什么 DNS 解析会出现超时的情况。

以上两个问题已经在阿里云的工单中提供,我将在容器和宿主上抓包检测 DNS 解析的过程,进一步了解问题的所在。


如果你看到这里,一定是真爱!欢迎看看我的其他 blog。O(∩_∩)O