日拱一卒,麻省理工教你效能分析,火焰圖、系統呼叫棧,黑科技滿滿

語言: CN / TW / HK

大家好,日拱一卒,我是樑唐。

今天我們繼續麻省理工missing smester,消失的學期的學習。這一次我們繼續上一節課的內容,來看看效能分析的部分。

B站視訊連結

和之前一樣,這節課的note質量同樣非常高。

note筆記原文

這次的內容相對來說使用的頻率會比debug稍微低一些,可能更多的是後端工程師應用得比較多。經常需要檢視系統的效能,以及執行情況,方便做出分析以及優化。前端和演算法/資料工程師相對來說用得很少。

日拱一卒,歡迎大家打卡一起學習。

效能分析(profiling)

Profile這個單詞原本是畫像、側寫的意思,這裡指的是對計算機的執行情況做一個畫像和側寫,用來了解當前系統的狀態。

有的時候,可能我們的程式碼功能是正確的,但是效能上出了問題。比如說耗光了系統所有的CPU或者是記憶體。在演算法課上,我們會學習使用O這個記號來代表程式複雜度的方法。倉促的開發,簡陋的優化是萬惡之源。你可以參考這篇文章關於倉促優化的說明:http://wiki.c2.com/?PrematureOptimization。

你需要學習一些profiler(側寫工具)以及監控工具。它們可以幫助你理解你程式的哪一個部分消耗了太多時間/資源,這樣你就可以迅速鎖定問題以及確定優化方案。

計時

和debug的案例一樣,在許多場景當中,打印出程式當中兩處位置的時間就足夠發現問題。這裡是Python當中使用time模組的一個例子:

```python import time, random n = random.randint(1, 10) * 100

Get current time

start = time.time()

Do some work

print("Sleeping for {} ms".format(n)) time.sleep(n/1000)

Compute time between start and now

print(time.time() - start)

Output

Sleeping for 500 ms

0.5713930130004883

```

但是,這裡有一個問題,執行時間(wall clock time)很容易誤導人。因為你的計算機同時還在執行其他程序或者是在等待阻塞/事件。對於工具來說,它需要區分真實時間、使用者時間以及系統時間。總體上來說使用者時間和系統時間告訴你,你的程序實際佔用了多少CPU時間,你可以參考這篇文章獲得更多解釋:https://stackoverflow.com/questions/556405/what-do-real-user-and-sys-mean-in-the-output-of-time1

  • 真實時間 - 從程式開始到結束流失掉的真實時間,包括其他程序的執行時間以及阻塞消耗的時間(例如等待 I/O或網路)
  • User - CPU 執行使用者程式碼所花費的時間
  • Sys - CPU 執行系統核心程式碼所花費的時間

舉個例子,試著在命令列執行一個獲取HTTP請求的命令,並且在命令之前加上time關鍵字。在網路不好的時候,你可能會得到下面這樣的結果。程序花費了2秒鐘才執行結束,然而僅僅只有15毫秒的CPU使用者時間,以及12毫秒的CPU核心時間,剩餘的時間全部都在等待網路。

側寫工具(Profilers)

CPU

大多數時候,當人們提到側寫工具的時候,通常是在指CPU側寫工具。CPU側寫工具有兩種:追蹤側寫(tracing)和取樣側寫(sampling)。

追蹤側寫會記錄你程式的每一個函式呼叫,而取樣側寫只會週期性的檢測你的程式棧(通常是毫秒級)。它們使用這些記錄來進行聚合分析,找出程式在哪些事情上花費了時間。關於這個話題,可以參考這篇文章獲取更多細節:

https://jvns.ca/blog/2017/12/17/how-do-ruby---python-profilers-work-

大多數程式語言擁有一些命令列側寫工具,可以用來進行程式碼分析。它們通常會被整合在IDE當中,但這節課上我們只會聚焦在命令列工具上。

在Python當中,我們可以使用cProfile模組來完成每個函式呼叫的耗時分析。這裡有一個簡單的例子,它實現了grep命令:

```python

!/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消耗了最多的時間,但IO部分通常無法優化。另外我們可以發現,編譯正則表示式也非常耗時。但正則表示式只需要編譯一次,我們可以把它移動到for迴圈外來進行優化。

```python $ python -m cProfile -s tottime grep.py 1000 '^(import|\sdef)[^,]$' *.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()

[omitted lines] ```

python中的cProfile(以及其他的一些分析器)可以展示每一個函式呼叫的時間。這些工具執行的時候非常快,並且如果你在程式碼當中使用了一些第三方庫,那麼這些庫中的內部函式的呼叫也會被統計進來。

側寫的時候對每行程式碼的執行時間進行計時會更加符合直覺,這就是line profiler的功能。

比如,接下來這段Python程式碼會向這門課的官網發起請求,並且解析返回結果,獲取當中所有的URL:

```python

!/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的話,我們會得到每一行程式碼執行的時間:

```shell $ 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++這樣的語言,記憶體洩漏會導致你程式當中有一塊記憶體始終無法釋放。為了更好地解決我們debug記憶體問題,我們可以使用一些像是Valgrind這樣的工具來定位記憶體洩漏問題。

對於一些垃圾回收語言,比如Python,使用記憶體側寫器同樣非常有用。因為可以幫助我們定位一些一直沒有被回收的物件。下面這個例子展示了memory-profiler是如何工作的(注意裝飾器和line-profiler類似)

```python @profile def my_func(): a = [1] * (10 6) b = [2] * (2 * 10 7) del b return a

if name == 'main': my_func() ```

shell $ 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這樣的工具進行debug的時候,你可能會想要忽視特定的一些程式碼,把它們當做是黑盒進行處理。perf命令通過各種方式對CPU進行抽象,它不會報告時間和記憶體的消耗,但是他會報告你程式當中的系統事件。比如說,perf會報告低快取區域性性(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分析資料的方式是火焰圖:https://www.brendangregg.com/flamegraphs.html。它會在Y軸上展示函式呼叫的層次結構,在X軸上顯示耗時的比例。火焰圖同時還是可互動的,你可以放大特定的部分並檢視堆疊資訊。

可以點選這個連結進行嘗試:https://www.brendangregg.com/FlameGraphs/cpu-bash-flamegraph.svg

呼叫圖或者是控制流圖可以展示子程式之間的關係,它將函式當做是節點,函式之間的呼叫當做是有向邊進行展示。結合側寫資訊,比如呼叫次數、耗時等資訊,呼叫關係圖對於闡釋程式的流程非常有用。在python當中,你可以使用pycallgraph庫來生成它。

資源監控

很多時候,分析程式效能的第一步就是理解它到底消耗了多少資源。程式跑得慢通常是因為資源限制,比如沒有足夠的記憶體了,或者是網路連線很慢。

有很多命令列工具可以來展示不同的系統資源,比如CPU使用率、記憶體使用率、網路、磁碟使用率等等。

  • 通用監控 - 最流行的工具要數 htop,了,它是 top的改進版。htop 可以顯示當前執行程序的多種統計資訊。htop 有很多選項和快捷鍵,常見的有: 程序排序、 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 這兩個命令已經被前面那些工具所代替了
  • 網路使用 - nethogsiftop 是非常好的用於對網路佔用進行監控的互動式命令列工具

如果你想要測試這些工具,你可以手動使用stress命令來為機器增加負載。

專用工具

有時候,你會想要對黑盒進行效能測試,從而決定應該使用什麼工具。像是hypterfine這樣的工具可以幫你進行快速測試。比如,我們在shell工具那一課當中推薦使用fd而不是find。我們可以使用hyperfine來對比一下它們。

比如在下面的例子當中,fd執行速度是find的20倍以上。

```shell $ 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一樣,瀏覽器也提供了非常好的頁面分析工具。讓你能夠發現時間都消耗在了什麼地方(載入、渲染、指令碼等等)。可以在使用的瀏覽器幫助當中查詢這部分資訊。

練習

  1. 這裡有很多已經實現好的排序演算法:https://missing.csail.mit.edu/static/files/sorts.py。使用cProfileline_profiler來對比插入排序和快速排序的耗時。每一個演算法的瓶頸是多少?使用memory_profiler來檢查記憶體使用,為什麼插入排序更優?然後再檢視快排的inplace版本。挑戰:使用perf來檢視每個演算法迴圈次數以及快取命中和和沒命中的情況
  2. 這裡有一些計算斐波那契數列的Python程式碼,對計算每個數字定義了一個函式:

```python

!/usr/bin/env python

def fib0(): return 0

def fib1(): return 1

s = """def fib{}(): return fib{}() + fib{}()"""

if name == 'main':

for n in range(2, 10):
    exec(s.format(n, n-1, n-2))
# from functools import lru_cache
# for n in range(10):
#     exec("fib{} = lru_cache(1)(fib{})".format(n, n))
print(eval("fib9()"))

```

把程式碼拷貝進入檔案,然後執行它。首先安裝依賴pycallgraphgraphviz(如果你能執行dot,說明你已經有了GraphViz)。使用pycallgraph graphviz -- ./fib.py命令執行程式碼,檢視pycallgraph.png檔案。fib0被呼叫了多少次?我們可以通過記憶化對演算法進行優化。放開註釋的程式碼,重新生成圖片,現在,對於每個fibN函式,分別呼叫了多少次?

  1. 想要使用的埠被佔用是一個非常常見的問題。現在讓我們看看怎麼樣發現是被什麼程式佔用了。首先,執行python -m http.server 4444來啟動一個mini web伺服器監聽埠4444。在另外一個終端當中執行lsof | grep LISTEN打印出所有正在監聽的程序以及埠。找到監聽4444的程序id,並使用kill幹掉
  2. 限制程序能夠使用的資源也是一個很好的辦法。試著使用stree -c 3並使用htop對CPU消耗進行視覺化。執行taskset --cpu-list 0,2 stress -c 3來進行視覺化。stress佔用了3個CPU嗎?為什麼沒有?閱讀一下man taskset來找答案。挑戰:使用cgroups命令來實現同樣的效果,試著使用stress -m來限制記憶體消耗
  3. (進階)curl ipinfo.io命令發起一個HTTP請求並獲取你的公共IP。開啟Wireshark:https://www.wireshark.org/嘗試抓取curl發起的請求和受到的結果。(提示:可以使用http進行過濾只顯示HTTP包)