Categories
程式開發

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍?


你是否在MacOS的PostgreSQL Docker容器中遇到過這樣神奇的情況:用EXPLAIN ANALYZE查看一個查詢實際的執行計劃,竟然比正常執行查詢慢60倍? !今天讓我們一起來研究一下PostgreSQL和Linux的內部實現,看看到底發生了什麼!

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 1

clock_gettime系統調用

首先,我們需要對EXPLAIN ANALYZE是如何工作的有一定的理解。讓我們一起來看看PostgreSQL的代碼,我們發現EXPLAIN ANALYZE的代碼可以大致歸結為如下偽代碼:

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

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 2

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 3

由於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了。

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 4

同樣的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納秒)。那“虛擬機這層帶來了多餘開銷”這個理論根本說不通😮!

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 5

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 6

數數clock_gettime調用

到這裡,我們需要做一個合理性檢查了。之前我們是根據靜態分析(查看代碼)的結論提出clock_gettime是罪魁禍首的假設,那clock_gettime是不是真的如我們所料,在我們的查詢期間被調用了20000次呢?

那現在讓我們用perf這個工具來查查clock_gettime這個系統接口到底被調用了多少次吧。順便說一句,perf的功能很強大,是一個值得學習的好工具。

我們用下面這個命令來查看clock_gettime在我們的查詢運行時,到底被系統調用了多少次:

sudo perf stat -e 'syscalls:sys_enter_clock_*' -p 

我們首先通過SELECT pg_backend_pid();來看我們PostgreSQL運行的pid是什麼,之後在perf命令運行開始後,運行我們的查詢:

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 7

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 8

這個結果告訴我們clock_gettime syscall沒有被調用過。什麼? !那pg_test_timing總該調用clock_gettime syscall了吧,試一下:

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

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 9

沒有,竟然還是沒有clock_gettime syscall被調用。計算機太難了😩

好吧,是時候拿出秘密武器了。查看EXPLAIN ANALYZE的代碼,我們知道InstrStartNode是計時開始時調用的方法,我們用gdb來反彙編一下,看看我們是不是真的調用了clock_gettime syscall:

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 10

我們看到了callq 0xafc10 ,這裡的@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 

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 11

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 12

vDSO優化

接下來,我又繼續嘗試用gdb了解更多,並且閱讀了一些libc的源代碼,我終於發現了vDSO這個東西。簡而言之vDSO是避免調用syscall的一個優化。而對於clock_gettime的優化更是寫在了文檔中:

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 13

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 14

譯:一個會被經常調用到的syscall是gettimeofday()。這個syscall既被用戶空間的應用所直接調用,也間接地被一些C庫所調用。比如時間戳,循環計時,或者輪詢,都需要準確地得到當前時間。時間信息並不是秘密,任何應用,任何有無權限的人都會得到相同的時間答案。所以內核把回答時間問題所需要的信息都放在用戶進程可以讀到的地方。從而gettimeofday()本來是一個系統調用,現在變成了一個正常的函數調用,並且只需訪問內存即可得到時間。

罪魁禍首:clock_gettime系統調用沒有使用vDSO優化

現在讓我們回到我們最初的問題,為什麼clock_gettime在Docker for Mac上很慢?當我到處google這個問題的時候,我在這篇博客中發現“時間偏移”問題會改變時鐘脈衝源(clocksource)。運行如下命令,你會發現一開始的TSC時鐘脈衝源由於被認為不穩定而自動切換到了hpet時鐘脈衝源:

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

為什麼Docker for Mac中運行EXPLAIN ANALYZE比正常查詢慢60倍? 15

根據Linux vDSO的維護者所述hpet這個時鐘脈衝源太差了,所以他決定在vDSO中完全禁用對hpet的支持。

至此,我們終於找到了根源問題

在MacOS主機和Docker虛擬機的時間偏移太大時,Docker後台的虛擬機決定把時鐘脈衝源從TSC切換至hpet。原本TSCgettimeofday調用非常快,因為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