The Missing Semester of Your CS Education (第七課,除錯及效能分析)
程式碼不能完全按照您的想法執行,它只能完全按照您的寫法執行,這是程式設計界的一條金科玉律。
讓您的寫法符合您的想法是非常困難的。在這節課中,我們會傳授給您一些非常有用技術,幫您處理程式碼中的 bug 和程式效能問題。
除錯程式碼
列印除錯法與日誌
“最有效的 debug 工具就是細緻的分析,配合恰當位置的列印語句” — Brian Kernighan, Unix 新手入門。
除錯程式碼的第一種方法往往是在您發現問題的地方新增一些列印語句,然後不斷重複此過程直到您獲取了足夠的資訊並找到問題的根本原因。
另外一個方法是使用日誌,而不是臨時新增列印語句。日誌較普通的列印語句有如下的一些優勢:
- 您可以將日誌寫入檔案、socket 或者甚至是傳送到遠端伺服器而不僅僅是標準輸出;
- 日誌可以支援嚴重等級(例如 INFO, DEBUG, WARN, ERROR等),這使您可以根據需要過濾日誌;
- 對於新發現的問題,很可能您的日誌中已經包含了可以幫助您定位問題的足夠的資訊。
這裡 是一個包含日誌的例程式:
$ python logger.py
# Raw output as with just prints
$ python logger.py log
# Log formatted output
$ python logger.py log ERROR
# Print only ERROR levels and above
$ python logger.py color
# Color formatted output
有很多技巧可以使日誌的可讀性變得更好,我最喜歡的一個是技巧是對其進行著色。到目前為止,您應該已經知道,以彩色文字顯示終端資訊時可讀性更好。但是應該如何設定呢?
ls
和 grep
這樣的程式會使用 ANSI escape codes,它是一系列的特殊字元,可以使您的 shell 改變輸出結果的顏色。例如,執行 echo -e "\e[38;2;255;0;0mThis is red\e[0m"
會列印紅色的字串:This is red
。只要您的終端支援真彩色。如果您的終端不支援真彩色(例如 MacOS 的 Terminal.app),您可以使用支援更加廣泛的 16 色,例如:”\e[31;1mThis is red\e[0m”。
下面這個指令碼向您展示瞭如何在終端中列印多種顏色(只要您的終端支援真彩色)
#!/usr/bin/env bash
for R in $(seq 0 20 255); do
for G in $(seq 0 20 255); do
for B in $(seq 0 20 255); do
printf "\e[38;2;${R};${G};${B}m█\e[0m";
done
done
done
第三方日誌系統
如果您正在構建大型軟體系統,您很可能會使用到一些依賴,有些依賴會作為程式單獨執行。如 Web 伺服器、資料庫或訊息代理都是此類常見的第三方依賴。
和這些系統互動的時候,閱讀它們的日誌是非常必要的,因為僅靠客戶端側的錯誤資訊可能並不足以定位問題。
幸運的是,大多數的程式都會將日誌儲存在您的系統中的某個地方。對於 UNIX 系統來說,程式的日誌通常存放在 /var/log
。例如, NGINX web 伺服器就將其日誌存放於/var/log/nginx
。
目前,系統開始使用 system log,您所有的日誌都會儲存在這裡。大多數(但不是全部的)Linux 系統都會使用 systemd
,這是一個系統守護程序,它會控制您系統中的很多東西,例如哪些服務應該啟動並執行。systemd
會將日誌以某種特殊格式存放於/var/log/journal
,您可以使用 journalctl
命令顯示這些訊息。
類似地,在 macOS 系統中是 /var/log/system.log
,但是有更多的工具會使用系統日誌,它的內容可以使用 log show
顯示。
對於大多數的 UNIX 系統,您也可以使用dmesg
命令來讀取核心的日誌。
如果您希望將日誌加入到系統日誌中,您可以使用 logger
這個 shell 程式。下面這個例子顯示瞭如何使用 logger
並且如何找到能夠將其存入系統日誌的條目。
不僅如此,大多數的程式語言都支援向系統日誌中寫日誌。
logger "Hello Logs"
# On macOS
log show --last 1m | grep Hello
# On Linux
journalctl --since "1m ago" | grep Hello
正如我們在資料整理那節課上看到的那樣,日誌的內容可以非常的多,我們需要對其進行處理和過濾才能得到我們想要的資訊。
如果您發現您需要對 journalctl
和 log show
的結果進行大量的過濾,那麼此時可以考慮使用它們自帶的選項對其結果先過濾一遍再輸出。還有一些像 lnav
這樣的工具,它為日誌檔案提供了更好的展現和瀏覽方式。
偵錯程式
當通過列印已經不能滿足您的除錯需求時,您應該使用偵錯程式。
偵錯程式是一種可以允許我們和正在執行的程式進行互動的程式,它可以做到:
- 當到達某一行時將程式暫停;
- 一次一條指令地逐步執行程式;
- 程式崩潰後檢視變數的值;
- 滿足特定條件時暫停程式;
- 其他高階功能。
很多程式語言都有自己的偵錯程式。Python 的偵錯程式是pdb
.
下面對pdb
支援的命令進行簡單的介紹:
- l(ist) - 顯示當前行附近的11行或繼續執行之前的顯示;
- s(tep) - 執行當前行,並在第一個可能的地方停止;
- n(ext) - 繼續執行直到當前函式的下一條語句或者 return 語句;
- b(reak) - 設定斷點(基於傳入的引數);
-
p(rint) - 在當前上下文對錶達式求值並列印結果。還有一個命令是pp ,它使用
pprint
列印; - r(eturn) - 繼續執行直到當前函式返回;
- q(uit) - 退出偵錯程式。
讓我們使用pdb
來修復下面的 Python 程式碼(參考講座視訊)
def bubble_sort(arr):
n = len(arr)
for i in range(n):
for j in range(n):
if arr[j] > arr[j+1]:
arr[j] = arr[j+1]
arr[j+1] = arr[j]
return arr
print(bubble_sort([4, 2, 1, 8, 7, 6]))
注意,因為 Python 是一種解釋型語言,所以我們可以通過 pdb
shell 執行命令。 ipdb
是一種增強型的 pdb
,它使用IPython
作為 REPL並開啟了 tab 補全、語法高亮、更好的回溯和更好的內省,同時還保留了pdb
模組相同的介面。
對於更底層的程式語言,您可能需要了解一下 gdb
( 以及它的改進版 pwndbg
) 和 lldb
。
它們都對類 C 語言的除錯進行了優化,它允許您探索任意程序及其機器狀態:暫存器、堆疊、程式計數器等。
專門工具
即使您需要除錯的程式是一個二進位制的黑盒程式,仍然有一些工具可以幫助到您。當您的程式需要執行一些只有作業系統核心才能完成的操作時,它需要使用 系統呼叫。有一些命令可以幫助您追蹤您的程式執行的系統呼叫。在 Linux 中可以使用strace
,在 macOS 和 BSD 中可以使用 dtrace
。dtrace
用起來可能有些彆扭,因為它使用的是它自有的 D
語言,但是我們可以使用一個叫做 dtruss
的封裝使其具有和 strace
(更多資訊參考 這裡)類似的介面
下面的例子展現來如何使用 strace
或 dtruss
來顯示ls
執行時,對stat
系統呼叫進行追蹤對結果。若需要深入瞭解 strace
,這篇文章 值得一讀。
# On Linux
sudo strace -e lstat ls -l > /dev/null
4
# On macOS
sudo dtruss -t lstat64_extended ls -l > /dev/null
有些情況下,我們需要檢視網路資料包才能定位問題。像 tcpdump
和 Wireshark 這樣的網路資料包分析工具可以幫助您獲取網路資料包的內容並基於不同的條件進行過濾。
對於 web 開發, Chrome/Firefox 的開發者工具非常方便,功能也很強大:
- 原始碼 -檢視任意站點的 HTML/CSS/JS 原始碼;
- 實時地修改 HTML, CSS, JS 程式碼 - 修改網站的內容、樣式和行為用於測試(從這一點您也能看出來,網頁截圖是不可靠的);
- Javascript shell - 在 JS REPL中執行命令;
- 網路 - 分析請求的時間線;
- 儲存 - 檢視 Cookies 和本地應用儲存。
靜態分析
有些問題是您不需要執行程式碼就能發現的。例如,仔細觀察一段程式碼,您就能發現某個迴圈變數覆蓋了某個已經存在的變數或函式名;或是有個變數在被讀取之前並沒有被定義。 這種情況下 靜態分析 工具就可以幫我們找到問題。靜態分析會將程式的原始碼作為輸入然後基於編碼規則對其進行分析並對程式碼的正確性進行推理。
下面這段 Python 程式碼中存在幾個問題。 首先,我們的迴圈變數foo
覆蓋了之前定義的函式foo
。最後一行,我們還把 bar
錯寫成了baz
,因此當程式完成sleep
(一分鐘)後,執行到這一行的時候便會崩潰。
import time
def foo():
return 42
for foo in range(5):
print(foo)
bar = 1
bar *= 0.2
time.sleep(60)
print(baz)
靜態分析工具可以發現此類的問題。當我們使用pyflakes
分析程式碼的時候,我們會得到與這兩處 bug 相關的錯誤資訊。mypy
則是另外一個工具,它可以對程式碼進行型別檢查。這裡,mypy
會經過我們bar
起初是一個 int
,然後變成了 float
。這些問題都可以在不執行程式碼的情況下被發現。
$ pyflakes foobar.py
foobar.py:6: redefinition of unused 'foo' from line 3
foobar.py:11: undefined name 'baz'
$ mypy foobar.py
foobar.py:6: error: Incompatible types in assignment (expression has type "int", variable has type "Callable[[], Any]")
foobar.py:9: error: Incompatible types in assignment (expression has type "float", variable has type "int")
foobar.py:11: error: Name 'baz' is not defined
Found 3 errors in 1 file (checked 1 source file)
在 shell 工具那一節課的時候,我們介紹了 shellcheck
,這是一個類似的工具,但它是應用於 shell 指令碼的。
大多數的編輯器和 IDE 都支援在編輯介面顯示這些工具的分析結果、高亮有警告和錯誤的位置。 這個過程通常稱為 code linting 。風格檢查或安全檢查的結果同樣也可以進行相應的顯示。
在 vim 中,有 ale
或 syntastic
可以幫助您做同樣的事情。 在 Python 中, pylint
和 pep8
是兩種用於進行風格檢查的工具,而 bandit
工具則用於檢查安全相關的問題。
對於其他語言的開發者來說,靜態分析工具可以參考這個列表:Awesome Static Analysis (您也許會對 Writing 一節感興趣) 。對於 linters 則可以參考這個列表: Awesome Linters。
對於風格檢查和程式碼格式化,還有以下一些工具可以作為補充:用於 Python 的 black
、用於 Go 語言的 gofmt
、用於 Rust 的 rustfmt
或是用於 JavaScript, HTML 和 CSS 的 prettier
。這些工具可以自動格式化您的程式碼,這樣程式碼風格就可以與常見的風格保持一致。 儘管您可能並不想對程式碼進行風格控制,標準的程式碼風格有助於方便別人閱讀您的程式碼,也可以方便您閱讀它的程式碼。
效能分析
即使您的程式碼能夠向您期望的一樣執行,但是如果它消耗了您全部的 CPU 和記憶體,那麼它顯然也不是個好程式。演算法課上我們通常會介紹大O標記法,但卻沒教給我們如何找到程式中的熱點。 鑑於 過早的優化是萬惡之源,您需要學習效能分析和監控工具,它們會幫助您找到程式中最耗時、最耗資源的部分,這樣您就可以有針對性的進行效能優化。
計時
和除錯程式碼類似,大多數情況下我們只需要列印兩處程式碼之間的時間即可發現問題。下面這個例子中,我們使用了 Python 的 time
模組。
import time, random
n = random.randint(1, 10) * 100
# 獲取當前時間
start = time.time()
# 執行一些操作
print("Sleeping for {} ms".format(n))
time.sleep(n/1000)
# 比較當前時間和起始時間
print(time.time() - start)
# Output
# Sleeping for 500 ms
# 0.5713930130004883
不過,執行時間(wall clock time)也可能會誤導您,因為您的電腦可能也在同時執行其他程序,也可能在此期間發生了等待。 對於工具來說,需要區分真實時間、使用者時間和系統時間。通常來說,使用者時間+系統時間代表了您的程序所消耗的實際 CPU (更詳細的解釋可以參照這篇文章)。
- 真實時間 - 從程式開始到結束流失掉的真實時間,包括其他程序的執行時間以及阻塞消耗的時間(例如等待 I/O或網路);
- User - CPU 執行使用者程式碼所花費的時間;
- Sys - CPU 執行系統核心程式碼所花費的時間。
例如,試著執行一個用於發起 HTTP 請求的命令並在其前面新增 time
字首。網路不好的情況下您可能會看到下面的輸出結果。請求花費了 2s 才完成,但是程序僅花費了 15ms 的 CPU 使用者時間和 12ms 的 CPU 核心時間。
$ time curl https://missing.csail.mit.edu &> /dev/null`
real 0m2.561s
user 0m0.015s
sys 0m0.012s
效能分析工具(profilers)
CPU
大多數情況下,當人們提及效能分析工具的時候,通常指的是 CPU 效能分析工具。 CPU 效能分析工具有兩種: 追蹤分析器(tracing)及取樣分析器(sampling)。 追蹤分析器 會記錄程式的每一次函式呼叫,而取樣分析器則只會週期性的監測(通常為每毫秒)您的程式並記錄程式堆疊。它們使用這些記錄來生成統計資訊,顯示程式在哪些事情上花費了最多的時間。如果您希望瞭解更多相關資訊,可以參考這篇 介紹性的文章。
大多數的程式語言都有一些基於命令列的分析器,我們可以使用它們來分析程式碼。它們通常可以整合在 IDE 中,但是本節課我們會專注於這些命令列工具本身。
在 Python 中,我們使用 cProfile
模組來分析每次函式呼叫所消耗的時間。 在下面的例子中,我們實現了一個基礎的 grep 命令:
#!/usr/bin/env python
import sys, re
def grep(pattern, file):
with open(file, 'r') as f:
print(file)
for i, line in enumerate(f.readlines()):
pattern = re.compile(pattern)
match = pattern.search(line)
if match is not None:
print("{}: {}".format(i, line), end="")
if __name__ == '__main__':
times = int(sys.argv[1])
pattern = sys.argv[2]
for i in range(times):
for file in sys.argv[3:]:
grep(pattern, file)
我們可以使用下面的命令來對這段程式碼進行分析。通過它的輸出我們可以知道,IO 消耗了大量的時間,編譯正則表示式也比較耗費時間。因為正則表示式只需要編譯一次,我們可以將其移動到 for 迴圈外面來改進效能。
$ python -m cProfile -s tottime grep.py 1000 '^(import|\s*def)[^,]*$' *.py
[omitted program output]
ncalls tottime percall cumtime percall filename:lineno(function)
8000 0.266 0.000 0.292 0.000 {built-in method io.open}
8000 0.153 0.000 0.894 0.000 grep.py:5(grep)
17000 0.101 0.000 0.101 0.000 {built-in method builtins.print}
8000 0.100 0.000 0.129 0.000 {method 'readlines' of '_io._IOBase' objects}
93000 0.097 0.000 0.111 0.000 re.py:286(_compile)
93000 0.069 0.000 0.069 0.000 {method 'search' of '_sre.SRE_Pattern' objects}
93000 0.030 0.000 0.141 0.000 re.py:231(compile)
17000 0.019 0.000 0.029 0.000 codecs.py:318(decode)
1 0.017 0.017 0.911 0.911 grep.py:3(<module>)
[omitted lines]
關於 Python 的 cProfile
分析器(以及其他一些類似的分析器),需要注意的是它顯示的是每次函式呼叫的時間。看上去可能快到反直覺,尤其是如果您在程式碼裡面使用了第三方的函式庫,因為內部函式呼叫也會被看作函式呼叫。
更加符合直覺的顯示分析資訊的方式是包括每行程式碼的執行時間,這也是行分析器的工作。例如,下面這段 Python 程式碼會向本課程的網站發起一個請求,然後解析響應返回的頁面中的全部 URL:
#!/usr/bin/env python
import requests
from bs4 import BeautifulSoup
# 這個裝飾器會告訴行分析器
# 我們想要分析這個函式
@profile
def get_urls():
response = requests.get('https://missing.csail.mit.edu')
s = BeautifulSoup(response.content, 'lxml')
urls = []
for url in s.find_all('a'):
urls.append(url['href'])
if __name__ == '__main__':
get_urls()
如果我們使用 Python 的 cProfile
分析器,我們會得到超過2500行的輸出結果,即使對其進行排序,我仍然搞不懂時間到底都花在哪了。如果我們使用 line_profiler
,它會基於行來顯示時間:
$ kernprof -l -v a.py
Wrote profile results to urls.py.lprof
Timer unit: 1e-06 s
Total time: 0.636188 s
File: a.py
Function: get_urls at line 5
Line # Hits Time Per Hit % Time Line Contents
==============================================================
5 @profile
6 def get_urls():
7 1 613909.0 613909.0 96.5 response = requests.get('https://missing.csail.mit.edu')
8 1 21559.0 21559.0 3.4 s = BeautifulSoup(response.content, 'lxml')
9 1 2.0 2.0 0.0 urls = []
10 25 685.0 27.4 0.1 for url in s.find_all('a'):
11 24 33.0 1.4 0.0 urls.append(url['href'])
記憶體
像 C 或者 C++ 這樣的語言,記憶體洩漏會導致您的程式在使用完記憶體後不去釋放它。為了應對記憶體類的 Bug,我們可以使用類似 Valgrind 這樣的工具來檢查記憶體洩漏問題。
對於 Python 這類具有垃圾回收機制的語言,記憶體分析器也是很有用的,因為對於某個物件來說,只要有指標還指向它,那它就不會被回收。
下面這個例子及其輸出,展示了 memory-profiler 是如何工作的(注意裝飾器和 line-profiler
類似)。
@profile
def my_func():
a = [1] * (10 ** 6)
b = [2] * (2 * 10 ** 7)
del b
return a
if __name__ == '__main__':
my_func()
$ python -m memory_profiler example.py
Line # Mem usage Increment Line Contents
==============================================
3 @profile
4 5.97 MB 0.00 MB def my_func():
5 13.61 MB 7.64 MB a = [1] * (10 ** 6)
6 166.20 MB 152.59 MB b = [2] * (2 * 10 ** 7)
7 13.61 MB -152.59 MB del b
8 13.61 MB 0.00 MB return a
事件分析
在我們使用strace
除錯程式碼的時候,您可能會希望忽略一些特殊的程式碼並希望在分析時將其當作黑盒處理。perf
命令將 CPU 的區別進行了抽象,它不會報告時間和記憶體的消耗,而是報告與您的程式相關的系統事件。
例如,perf
可以報告不佳的快取區域性性(poor cache locality)、大量的頁錯誤(page faults)或活鎖(livelocks)。下面是關於常見命令的簡介:
-
perf list
- 列出可以被 pref 追蹤的事件; -
perf stat COMMAND ARG1 ARG2
- 收集與某個程序或指令相關的事件; -
perf record COMMAND ARG1 ARG2
- 記錄命令執行的取樣資訊並將統計資料儲存在perf.data
中; -
perf report
- 格式化並列印perf.data
中的資料。
視覺化
使用分析器來分析真實的程式時,由於軟體的複雜性,其輸出結果中將包含大量的資訊。人類是一種視覺動物,非常不善於閱讀大量的文字。因此很多工具都提供了視覺化分析器輸出結果的功能。
對於取樣分析器來說,常見的顯示 CPU 分析資料的形式是 火焰圖,火焰圖會在 Y 軸顯示函式呼叫關係,並在 X 軸顯示其耗時的比例。火焰圖同時還是可互動的,您可以深入程式的某一具體部分,並檢視其棧追蹤(您可以嘗試點選下面的圖片)。
呼叫圖和控制流圖可以顯示子程式之間的關係,它將函式作為節點並把函式呼叫作為邊。將它們和分析器的資訊(例如呼叫次數、耗時等)放在一起使用時,呼叫圖會變得非常有用,它可以幫助我們分析程式的流程。 在 Python 中您可以使用 pycallgraph
來生成這些圖片。
資源監控
有時候,分析程式效能的第一步是搞清楚它所消耗的資源。程式變慢通常是因為它所需要的資源不夠了。例如,沒有足夠的記憶體或者網路連線變慢的時候。
有很多很多的工具可以被用來顯示不同的系統資源,例如 CPU 佔用、記憶體使用、網路、磁碟使用等。
-
通用監控 - 最流行的工具要數
htop
,了,它是top
的改進版。htop
可以顯示當前執行程序的多種統計資訊。htop
有很多選項和快捷鍵,常見的有:<F6>
程序排序、t
顯示樹狀結構和h
開啟或摺疊執行緒。 還可以留意一下glances
,它的實現類似但是使用者介面更好。如果需要合併測量全部的程序,dstat
是也是一個非常好用的工具,它可以實時地計算不同子系統資源的度量資料,例如 I/O、網路、 CPU 利用率、上下文切換等等; -
I/O 操作 -
iotop
可以顯示實時 I/O 佔用資訊而且可以非常方便地檢查某個程序是否正在執行大量的磁碟讀寫操作; -
磁碟使用 -
df
可以顯示每個分割槽的資訊,而du
則可以顯示當前目錄下每個檔案的磁碟使用情況( disk usage)。-h
選項可以使命令以對人類(human)更加友好的格式顯示資料;ncdu
是一個互動性更好的du
,它可以讓您在不同目錄下導航、刪除檔案和資料夾; -
記憶體使用 -
free
可以顯示系統當前空閒的記憶體。記憶體也可以使用htop
這樣的工具來顯示; -
開啟檔案 -
lsof
可以列出被程序開啟的檔案資訊。 當我們需要檢視某個檔案是被哪個程序開啟的時候,這個命令非常有用; -
網路連線和配置 -
ss
能幫助我們監控網路包的收發情況以及網路介面的顯示資訊。ss
常見的一個使用場景是找到埠被程序佔用的資訊。如果要顯示路由、網路裝置和介面資訊,您可以使用ip
命令。注意,netstat
和ifconfig
這兩個命令已經被前面那些工具所代替了。 -
網路使用 -
nethogs
和iftop
是非常好的用於對網路佔用進行監控的互動式命令列工具。
如果您希望測試一下這些工具,您可以使用 stress
命令來為系統人為地增加負載。
專用工具
有時候,您只需要對黑盒程式進行基準測試,並依此對軟體選擇進行評估。 類似 hyperfine
這樣的命令列可以幫您快速進行基準測試。例如,我們在 shell 工具和指令碼那一節課中我們推薦使用 fd
來代替 find
。我們這裡可以用hyperfine
來比較一下它們。
例如,下面的例子中,我們可以看到fd
比 find
要快20倍。
$ hyperfine --warmup 3 'fd -e jpg' 'find . -iname "*.jpg"'
Benchmark #1: fd -e jpg
Time (mean ± σ): 51.4 ms ± 2.9 ms [User: 121.0 ms, System: 160.5 ms]
Range (min … max): 44.2 ms … 60.1 ms 56 runs
Benchmark #2: find . -iname "*.jpg"
Time (mean ± σ): 1.126 s ± 0.101 s [User: 141.1 ms, System: 956.1 ms]
Range (min … max): 0.975 s … 1.287 s 10 runs
Summary
'fd -e jpg' ran
21.89 ± 2.33 times faster than 'find . -iname "*.jpg"'
和 debug 一樣,瀏覽器也包含了很多不錯的效能分析工具,可以用來分析頁面載入,讓我們可以搞清楚時間都消耗在什麼地方(載入、渲染、指令碼等等)。 更多關於 Firefox 和 Chrome的資訊可以點選連結。