《Python高性能程式設計》——2.6 使用cProfile子產品

本節書摘來自異步社群《python高性能程式設計》一書中的第2章，第2.6節，作者[美] 戈雷利克 （micha gorelick），胡世傑，徐旭彬 譯，更多章節内容可以通路雲栖社群“異步社群”公衆号檢視。

cprofile是一個标準庫内建的分析工具。它鈎入cpython的虛拟機來測量其每一個函數運作所花費的時間。這一技術會引入一個巨大的開銷，但你會獲得更多的資訊。有時這些額外的資訊會給你的代碼帶來令人驚訝的發現。

分析工作的一個好的實踐是在開始分析之前先對你的代碼各部分的運作速度進行假設。ian喜歡将有問題的代碼列印出來并加以标注。提前生成一個假設意味着有可能測出你錯的有多離譜（而且真的會測出！）并提升你對于某種程式設計風格的直覺。

始終基于你的測量結果，用一些既快且髒的分析手段確定你正在分析正确的地方。沒有什麼比在聰明地優化了一段代碼之後（可能過了幾小時或幾天）才意識到你其實漏掉了程序最慢的部分且根本沒有找到真正的問題所在更令人羞愧的了。

那麼我們的假設是什麼呢？我們知道calculate_z_serial_purepython可能是代碼最慢的部分。我們在那個函數裡做了大量的解引用并多次調用基本的算術操作和abs函數。這些可能都是耗cpu資源的大戶。

這裡，我們用cprofile子產品運作我們的代碼的一個變種。其輸出是格式化的，友善我們搞清去哪裡做進一步分析。

-s cumulative開關告訴cprofile對每個函數累計花費的時間進行排序，這能讓我們看到代碼最慢的部分。cprofile會将輸出直接列印到螢幕：

對累計時間排序能告訴我們大部分的執行時間花在了哪。這個結果顯示出在僅僅19秒的時間裡一共發生了36 221 992次函數調用（這個時間包括了使用cprofile的開銷）。之前我們的代碼需要13秒執行時間——為了測量每個函數執行所花費的時間，我們增加了一個5秒的懲罰。

我們可以看到第一行，julia1_cprofile.py的代碼入口點總共花費了19秒。這是通過__main__調用calc_pure_python。ncalls為1,意味着這行僅執行了一次。

在calc_pure_python内部，calculate_z_serial_purepython的調用花費了18.6秒。這兩個函數都隻執行了一次。我們可以推測出有大約1秒的時間花在了calc_pure_python内部，是調用calculate_z_serial_purepython以外的代碼。不過我們用cprofile沒法知道是哪些行花掉了這些時間。

在calculate_z_serial_purepython内部，花在（那些沒有調用其他函數的）代碼行上的時間是14.1秒。該函數調用了34 219 980次abs，總共花了4.4秒，另外還有其他一些不怎麼花時間的調用。

那個{abs}是什麼東西？這一行測量的是calculate_z_serial_purepython對abs函數的調用。per-call的代價可以忽略（0.000秒），34219980次調用總共花了4.4秒。我們無法預測會調用多少次abs，因為julia函數具有不可預測的動态特性（這也是為什麼對它的分析如此有趣）。

我們隻能說它最少會被調用1 000 000次，因為我們需要計算1000×1000個像素點。它最多會被調用300 000 000次，因為我們對1 000 000個像素點最多進行300次疊代。是以三千四百萬次調用僅是最差情況的10%。

如果我們看原始的灰階圖（圖2-3），并在想象中将白色部分擠壓進角落，我們可以估算出耗時的白色區域大概占了全圖的10%。

接下來的分析輸出，{method 'append' of 'list' objects}，表示了對2 002 000個清單項的建立。

2 002 000個清單項的建立發生在calc_pure_python的設定階段。

清單zs和cs分别有1000×1000個項目，而它們是根據1000個x坐标和1000個y坐标建立的。是以總共要調用2 002 000次append。

需要注意的是cprofile的輸出并不以父函數排序，它總結了執行代碼塊的全部函數。用cprofile很難搞清楚函數内的每一行發生了什麼，因為我們隻拿到了函數自身調用的分析資訊，而不是函數内的每一行。

在calculate_z_serial_purepython内，我們可以對{abs}和{range}進行分析，這兩個函數總計花了大約4.5秒。我們知道calculate_z_serial_purepython自身總共花費了18.6秒。

性能分析輸出的最後一行提到了lsprof，這是本工具進化到cprofile之前的原始名字，可以忽略。

為了獲得對cprofile結果的更多控制，我們可以生成一個統計檔案然後通過python進行分析：

我們可以這樣将其調入python，它會輸出跟之前一樣的累計時間報告：

為了追溯我們分析的函數，我們可以列印調用者的資訊。在下面的兩個清單中，我們可以看到calculate_z_serial_purepython是最耗時的函數，且隻在一個地方被調用。如果它被多個地方調用，這些清單也許能幫助我們定位到最耗時的父函數：

我們還可以反過來顯示哪個函數調用了其他函數：

cprofile輸出的資訊很多，你需要有一個副螢幕才能避免整字換行。它是内建的用于快速定位瓶頸的便利工具。然後我們在本章後面讨論的line_profiler、heapy和memory_profiler等工具才能幫助你深入定位到需要你加以注意的具體代碼行。