为什么 Docker for Mac 中运行 EXPLAIN ANALYZE 比正常查询慢 60 倍？

你是否在 MacOS 的 PostgreSQL Docker 容器中遇到过这样神奇的情况：用 EXPLAIN ANALYZE 查看一个查询实际的执行计划，竟然比正常执行查询慢 60 倍？！今天让我们一起来研究一下 PostgreSQL 和 Linux 的内部实现，看看到底发生了什么！

clock_gettime 系统调用

首先，我们需要对 EXPLAIN ANALYZE 是如何工作的有一定的理解。让我们一起来看看 PostgreSQL 的代码，我们发现 EXPLAIN ANALYZE 的代码可以大致归结为如下伪代码：

 复制代码

start= clock_gettime()
row =node.nextRow()
node.time+= clock_gettime() -start
return row

由于 generate_series(1, 10000) 会产生 10000 行结果，而对于每一行，PostgreSQL 会在开始和结束的时候各调用一次 clock_gettime syscall，那么这样不难发现 PostgreSQL 一共调用了 20000 个 clock_gettime 的 syscall，并且这个 clock_gettime 的调用不知道为什么在 Docker for Mac 上很慢。那到底为什么慢呢，让我们再深挖一下。

pg_test_timing

让我们先来确保一下我们关于 clock_gettime 是罪魁祸首的猜想方向是正确的，那用 pg_test_timing 来试试吧。 pg_test_timing 是一个用来测量 PostgreSQL 计时到底需要多少开销的工具，它是 PostgreSQL Docker Image 自带的一个工具。查看 pg_test_timing 代码，我们可以知道它也调用了 clock_gettime syscall。

pg_test_timing 的 官方文档 里说到：大多数（超过 90%）的计时本身消耗的时间应该小于 1 微秒，循环计时的平均消耗会更低，低于 100 纳秒。

good results will show most (>90%) individual timing calls take less than one microsecond. Average per loop overhead will be even lower, below 100 nanoseconds.

在 MacOS 上 PostgreSQL Docker 容器里跑 pg_test_timing ，我们得到的结果是每次计时需要 6853 纳秒！那么我们最初的查询调用了 20000 次计时，那就需要 20000*6853ns=137ms，这就能解释我们为什么在 EXPLAIN ANALYZE 里看到的总用时是 157.140ms 了。

同样的 pg_test_timing ，在部署在 MacOS 主机上的 PostgreSQL 上运行的话，只要 65 纳秒，比 Docker 里快 100 多倍。

到这里，我突然意识到 Docker for Mac 的 运行机制 是在后台启动了一个 Linux 虚拟机，那会不会是由于多出来的这层虚拟机带来了多余的开销呢？那可能不仅是 Docker 的问题，如果在 MacOS 上启动一个 Linux 虚拟机，并在虚拟机内运行 PostgreSQL，也许应该可以看到同样的计时高延迟问题。

那让我们来比较一下 Linux 虚拟机和 Docker 的虚拟机开销区别吧。我在 VirtualBox 上运行了 Ubuntu 18.04，运行了同样的查询 EXPLAIN ANALYZE SELECT count(*) FROM generate_series(1, 10000); ，这次运行时长只有 3 毫秒（Docker 的运行时长是 157 毫秒）。 pg_test_timing 在 Ubuntu 18.04 上的结果是单次计时开销为 33 纳秒 (Docker 的单次计时开销是 6853 纳秒，MacOS 主机的单次计时开销是 65 纳秒)。那“虚拟机这层带来了多余开销”这个理论根本说不通:open_mouth:！

数数 clock_gettime 调用

到这里，我们需要做一个合理性检查了。之前我们是根据静态分析（查看代码）的结论提出 clock_gettime 是罪魁祸首的假设，那 clock_gettime 是不是真的如我们所料，在我们的查询期间被调用了 20000 次呢？

那现在让我们用 perf 这个 工具 来查查 clock_gettime 这个系统接口到底被调用了多少次吧。顺便说一句，perf 的功能很强大，是一个值得学习的好工具。

我们用下面这个命令来查看 clock_gettime 在我们的查询运行时，到底被系统调用了多少次：

 复制代码

sudo perfstat-e'syscalls:sys_enter_clock_*'-p <backend_pid>

我们首先通过 SELECT pg_backend_pid(); 来看我们 PostgreSQL 运行的 pid 是什么，之后在 perf 命令运行开始后，运行我们的查询：

这个结果告诉我们 clock_gettime syscall 没有被调用过。什么？！那 pg_test_timing 总该调用 clock_gettime syscall 了吧，试一下：

 复制代码

sudo perf stat -e'syscalls:sys_enter_clock_*'$(which pg_test_timing)

没有，竟然还是没有 clock_gettime syscall 被调用。计算机太难了:weary:

好吧，是时候拿出秘密武器了。查看 EXPLAIN ANALYZE 的代码，我们知道 InstrStartNode 是计时开始时调用的方法，我们用 gdb 来反汇编一下，看看我们是不是真的调用了 clock_gettime syscall：

我们看到了 callq 0xafc10 <clock_gettime@plt> ，这里的 @plt 表示 Procedure Linkage Table，这代表我们调用了 libc 的接口！我们再快速用 perf 工具的动态追踪功能确认一下，确认了有 20016 次 clock_gettime libc 调用：

 复制代码

sudo perf probe -x /lib/x86_64-linux-gnu/libc.so.6 'clock_gettime'
sudo perf stat -e'probe_libc:clock_gettime'-p <backend_pid>

vDSO 优化

接下来，我又继续尝试用 gdb 了解更多，并且阅读了一些 libc 的源代码，我终于发现了 vDSO 这个东西。简而言之 vDSO 是避免调用 syscall 的一个优化。而对于 clock_gettime 的优化更是写在了文档中：

译：一个会被经常调用到的 syscall 是 gettimeofday() 。这个 syscall 既被用户空间的应用所直接调用，也间接地被一些 C 库所调用。比如时间戳，循环计时，或者轮询，都需要准确地得到当前时间。时间信息并不是秘密，任何应用，任何有无权限的人都会得到相同的时间答案。所以内核把回答时间问题所需要的信息都放在用户进程可以读到的地方。从而 gettimeofday() 本来是一个系统调用，现在变成了一个正常的函数调用，并且只需访问内存即可得到时间。

罪魁祸首：clock_gettime 系统调用没有使用 vDSO 优化

现在让我们回到我们最初的问题，为什么 clock_gettime 在 Docker for Mac 上很慢？当我到处 google 这个问题的时候，我在 这篇博客 中发现“时间偏移”问题会改变时钟脉冲源(clocksource)。运行如下命令，你会发现一开始的 TSC 时钟脉冲源由于被认为不稳定而自动切换到了 hpet 时钟脉冲源：

 复制代码

dockerrun--privileged -it postgres dmesg | egrep'(tsc|hpet)'

根据 Linux vDSO 的 维护者所述 ， hpet 这个时钟脉冲源太差了，所以他决定在 vDSO 中完全禁用对 hpet 的支持。

至此，我们终于找到了 根源问题 ：

在 MacOS 主机和 Docker 虚拟机的时间偏移太大时，Docker 后台的虚拟机决定把时钟脉冲源从 TSC 切换至 hpet 。原本 TSC 的 gettimeofday 调用非常快，因为 gettimeofday 调用的并不是 syscall，而是通过 vDSO 发生在用户空间。在 vDSO 中，当系统当前的时钟脉冲源不支持通过 vDSO 调用时， gettimeofday 就会退而求其次调用 syscall，其中包括发生内核调用和各种其他开销。而 hpet 不支持通过 vDSO 调用，所以每个 gettimeofday 都是一个 syscall，最终 20000 个 syscall 的多余开销使得性能差强人意。

主机和 Docker 之间的时间偏移问题，曾经在 Docker 18.05 的版本中被 尝试修复 过。这个修复本应该解决时间偏移问题，所以理论上没有时间偏移就不会有切换时钟脉冲源的事情发生。然而，他们的修复看上去仍然是有缺陷的，尤其是在虚拟机 sleep 的时候仍会发生时间偏移问题。可惜的是，尽管这个问题对很多应用产生了影响，用户在 github 上提出的问题却并没有得到太多的关注， 这里 是一个用户说 PHP 请求由于 Docker 时间偏移的问题响应慢了 3 倍。当我在 google 上到处浏览的时候，发现 vDSO 不支持某些时钟脉冲源的问题过去 严重影响 了如 AWS 的一些云厂商。

解决方案

重启 Docker for Mac 是一个变通的方法，但是时钟脉冲源自动切换的问题再次发生只是时间问题。在我工作的团队里，同事们一致同意在做性能测试方面的工作时，直接在 MacOS 主机上使用 PostgreSQL，而不用 Docker。

收获

无论如何，这次重要的收获是，现代的技术栈既复杂又脆弱，作为一个应用开发者，你也许不能完全掌握这些难点，但是你会经常需要解释为什么你的应用性能不好。所以，增强你的调试技能吧。学习足够的 C 语言让自己有能力阅读源代码，使用足够的 gdb 去设置断点，掌握足够的 perf 功能去追踪系统调用和方法调用。这样的话，不久那些最令人生畏的 PostgreSQL 性能谜题将得到解答。

原文链接：

https://twitter.com/felixge/status/1221512507690496001