2.6 使用模塊cProfile

cProfile是標(biāo)準(zhǔn)庫(kù)內(nèi)置的一個(gè)剖析工具。它通過(guò)潛入CPython虛擬機(jī)來(lái)測(cè)量每個(gè)函數(shù)的執(zhí)行時(shí)間。這引入了更大的開(kāi)銷(xiāo)，但提供的信息也更多。在有些情況下，這些額外的信息可能讓你對(duì)代碼有意外的洞見(jiàn)。

cProfile是標(biāo)準(zhǔn)庫(kù)內(nèi)置的兩個(gè)剖析器之一，另一個(gè)是profile。profile是純Python剖析器，歷史更悠久，但速度更慢；cProfile與profile具有相同的接口，并且是用C語(yǔ)言編寫(xiě)的，因此開(kāi)銷(xiāo)更低。如果你對(duì)這些庫(kù)的歷史感興趣，可參閱Armin Rigo于2005年撰寫(xiě)的文章（參見(jiàn)Bitly公司官網(wǎng)cProfile Request頁(yè)面），該文呼吁將cProfile納入標(biāo)準(zhǔn)庫(kù)中。

對(duì)剖析來(lái)說(shuō)，一種不錯(cuò)的做法是，在剖析前就代碼各部分的速度做出假設(shè)。作者喜歡將代碼打印出來(lái)并進(jìn)行標(biāo)注。預(yù)先做出假設(shè)后，你將發(fā)現(xiàn)有些假設(shè)非常離譜，進(jìn)而加深對(duì)某些編碼風(fēng)格的認(rèn)識(shí)。

警告：不要因?yàn)橹庇X(jué)會(huì)出錯(cuò)，就避免在剖析中依靠直覺(jué)。剖析前做出假設(shè)絕對(duì)是值得的，因?yàn)樗梢詭椭銓W(xué)會(huì)如何找出代碼中運(yùn)行緩慢的部分。但是，你必須用證據(jù)來(lái)證明你的假設(shè)。

務(wù)必以測(cè)量結(jié)果為導(dǎo)向，并首先進(jìn)行粗糙的剖析，確保將勁用對(duì)了地方。你可能巧妙地優(yōu)化了一段代碼，但幾小時(shí)或幾天后卻發(fā)現(xiàn)自己忽視了進(jìn)程中速度最慢的部分，根本沒(méi)有解決真正的問(wèn)題。沒(méi)有什么比這更令人羞愧的了。

我們先假設(shè)函數(shù)calculate_z_serial_purepython是速度最慢的代碼部分。在這個(gè)函數(shù)中，我們執(zhí)行了大量的解引用操作和基本算術(shù)運(yùn)算，還大量地調(diào)用了函數(shù)abs。這些很可能消耗大量的CPU資源。

這里將使用模塊cProfile來(lái)運(yùn)行代碼的一個(gè)版本。輸出雖然簡(jiǎn)單，但可以幫助我們確定該對(duì)哪部分代碼做進(jìn)一步分析。

標(biāo)志-s cumulative讓cProfile根據(jù)占用的累計(jì)時(shí)間對(duì)函數(shù)進(jìn)行排序，這讓我們知道哪部分代碼的運(yùn)行速度最慢。cProfile的輸出被直接顯示到屏幕上，它們位于print語(yǔ)句輸出的后面：

$ python -m cProfile -s cumulative julia1_nopil.py
...
Length of x: 1000
Total elements: 1000000
calculate_z_serial_purepython took 11.498265266418457 seconds
36221995 function calls in 12.234 seconds
　
  Ordered by: cumulative time
　
  ncalls tottime percall cumtime percall filename:lineno(function)
1   0.000   0.000  12.234  12.234 {built-in method builtins.exec}
       1   0.038   0.038  12.234  12.234 julia1_nopil.py:1(<module>)
       1   0.571   0.571  12.197  12.197 julia1_nopil.py:23
                                          (calc_pure_python)
       1   8.369   8.369  11.498  11.498 julia1_nopil.py:9
                                          (calculate_z_serial_purepython)
34219980   3.129   0.000   3.129   0.000 {built-in method builtins.abs}
 2002000   0.121   0.000   0.121   0.000 {method 'append' of 'list' objects}
1   0.006   0.006   0.006   0.006 {built-in method builtins.sum}
3   0.000   0.000   0.000   0.000 {built-in method builtins.print}
2   0.000   0.000   0.000   0.000 {built-in method time.time}
4   0.000   0.000   0.000   0.000 {built-in method builtins.len}
       1   0.000   0.000   0.000   0.000 {method 'disable' of
                                          '_lsprof.Profiler' objects}
　

通過(guò)對(duì)累計(jì)時(shí)間排序，我們能夠知道執(zhí)行時(shí)間主要花在什么地方。上述結(jié)果表明，在僅僅12 s多點(diǎn)的時(shí)間（其中包括cProfile的開(kāi)銷(xiāo)）內(nèi)，發(fā)生了36 221 995次函數(shù)調(diào)用。而以前，代碼的執(zhí)行時(shí)間大約8 s，換句話(huà)說(shuō)，為測(cè)量每個(gè)函數(shù)的執(zhí)行時(shí)間，增加了4 s的開(kāi)銷(xiāo)。

從上述輸出可知，代碼入口（julia1_nopil.py的第1行）花費(fèi)的時(shí)間為12 s。這行代碼位于主函數(shù)中，它調(diào)用calc_pure_python。ncalls為1，表明這行代碼只執(zhí)行了一次。

在calc_pure_python內(nèi)部，調(diào)用calculate_z_serial_purepython的代碼耗費(fèi)了11 s。函數(shù)calc_pure_python和calculate_z_serial_purepython都只調(diào)用了一次，由此可以推斷，在函數(shù)calc_pure_python中，除調(diào)用CPU密集型函數(shù)calculate_z_serial_ purepython外的其他代碼耗費(fèi)的時(shí)間大約為1 s。但是，僅使用cProfile無(wú)法推斷出這些時(shí)間是函數(shù)中的哪些代碼消耗的。

在函數(shù)calculate_z_serial_purepython中，花在非函數(shù)調(diào)用代碼上的時(shí)間為8 s。這個(gè)函數(shù)調(diào)用了函數(shù)abs 34 219 980次，總共花費(fèi)了3 s；它還調(diào)用了其他一些開(kāi)銷(xiāo)不高的函數(shù)。

abs調(diào)用的情況如何呢？輸出指出了在calculate_z_serial_purepython中每次調(diào)用abs花費(fèi)的時(shí)間。雖然每次調(diào)用的開(kāi)銷(xiāo)微不足道（顯示的結(jié)果為0.000 s），但34 219 980次調(diào)用花費(fèi)的總時(shí)間為3 s。我們無(wú)法預(yù)測(cè)abs到底將被調(diào)用多少次，因?yàn)橹炖麃喓瘮?shù)具有不可預(yù)測(cè)性，這也是人們對(duì)它感興趣的原因所在。

我們只能說(shuō)它至少會(huì)被調(diào)用100萬(wàn)次，因?yàn)槲覀円?jì)算1000像素×1000像素的值；它最多會(huì)被調(diào)用3億次，因?yàn)槲覀円?jì)算100萬(wàn)像素的值，而計(jì)算每個(gè)像素時(shí)最多迭代300次。上述輸出表明，調(diào)用了大約3400萬(wàn)次，這意味著需要迭代300次的像素大約占10%。

如果我們查看灰度圖（圖2-3），并將其中的白色區(qū)域都移到一個(gè)角落中，將發(fā)現(xiàn)該區(qū)域的面積大約占整幅圖像其余部分的10%。

剖析輸出的下一行{method 'append' of 'list' objects}，它指出創(chuàng)建了2 002 000個(gè)列表項(xiàng)。

提示：為何是2 002 000個(gè)列表項(xiàng)呢？在繼續(xù)閱讀之前，想一想創(chuàng)建了多少個(gè)列表項(xiàng)。
　

這2 002 000個(gè)列表項(xiàng)的創(chuàng)建工作是在calc_pure_python的設(shè)置階段完成的。

列表zs和cs都包含1000項(xiàng)×1000項(xiàng)（調(diào)用次數(shù)為1 000 000 × 2），這些元素是由1000個(gè)x坐標(biāo)和1000個(gè)y坐標(biāo)的列表創(chuàng)建的，因此需要追加總共2 002 000次調(diào)用。

需要注意的是，cProfile的輸出并不是按父函數(shù)排序的，它總結(jié)了被執(zhí)行的代碼塊中所有函數(shù)的開(kāi)銷(xiāo)。使用cProfile很難搞明白每行代碼的情況，因?yàn)樗惶峁┝擞嘘P(guān)函數(shù)調(diào)用的剖析信息，而沒(méi)有提供函數(shù)中各行代碼的剖析信息。

在函數(shù)calculate_z_serial_purepython中，我們可獲悉有關(guān)函數(shù)abs的信息，這個(gè)函數(shù)總共消耗了大約3.1 s。我們還知道，calculate_z_serial_purepython總共消耗了大約11.4 s。

上述剖析輸出的最后一行包含字樣lsprof，這是cProfile前身的名稱(chēng)，其占用的時(shí)間可忽略不計(jì)。

為更好地展現(xiàn)cProfile的結(jié)果，可將其寫(xiě)入一個(gè)統(tǒng)計(jì)文件，再使用Python對(duì)這個(gè)文件進(jìn)行分析：

$ python -m cProfile -o profile.stats julia1.py

可以像下面這樣將這個(gè)文件載入Python，這將提供與前面一樣的累計(jì)時(shí)間報(bào)告：

In [1]: import pstats
In [2]: p = pstats.Stats("profile.stats")
In [3]: p.sort_stats("cumulative")
Out[3]: <pstats.Stats at 0x7f77088edf28>
In [4]: p.print_stats()
Fri Jun 14 17:59:28 2019   profile.stats
　
36221995 function calls in 12.169 seconds
　
   Ordered by: cumulative time
　
   ncalls tottime percall cumtime percall filename:lineno(function)
1   0.000   0.000  12.169  12.169 {built-in method builtins.exec}
        1   0.033   0.033  12.169  12.169 julia1_nopil.py:1(<module>)
        1   0.576   0.576  12.135  12.135 julia1_nopil.py:23
                                           (calc_pure_python)
        1   8.266   8.266  11.429  11.429 julia1_nopil.py:9
                                           (calculate_z_serial_purepython)
34219980   3.163   0.000  3.163    0.000 {built-in method builtins.abs}
  2002000   0.123   0.000  0.123    0.000 {method 'append' of 'list' objects}
1   0.006   0.006  0.006    0.006 {built-in method builtins.sum}
3   0.000   0.000  0.000    0.000 {built-in method builtins.print}
4   0.000   0.000  0.000    0.000 {built-in method builtins.len}
2   0.000   0.000  0.000    0.000 {built-in method time.time}
        1   0.000   0.000  0.000    0.000 {method 'disable' of
                                           '_lsprof.Profiler' objects}

為追蹤我們剖析了哪些函數(shù)，可將調(diào)用者信息打印出來(lái)。從下面的輸出可知，calculate_z_serial_purepython是開(kāi)銷(xiāo)最高的函數(shù)，但只在一個(gè)地方調(diào)用了它。如果在很多地方都調(diào)用了它，這些輸出可幫助我們找出開(kāi)銷(xiāo)最高的父函數(shù)：

In [5]: p.print_callers()
   Ordered by: cumulative time
　
Function                                       was called by...
　
                                             ncalls tottime cumtime
{built-in method builtins.exec}      <-
julia1_nopil.py:1(<module>)          <-     1    0.033    12.169
{built-in method builtins.exec}
julia1_nopil.py:23(calc_pure_python)  <-     1    0.576   12.135
                                             :1(<module>)
julia1_nopil.py:9(...)               <-       1    8.266   11.429
                                              :23(calc_pure_python)
{built-in method builtins.abs}       <-  34219980   3.163   3.163
                                           :9(calculate_z_serial_purepython)
{method 'append' of 'list' objects}  <-   2002000   0.123   0.123
                                               :23(calc_pure_python)
{built-in method builtins.sum}       <-        1    0.006   0.006
                                               :23(calc_pure_python)
{built-in method builtins.print}     <-        3     0.000  0.000
                                               :23(calc_pure_python)
{built-in method builtins.len}       <-        2     0.000  0.000
                                            :9(calculate_z_serial_purepython)
                                               2     0.000  0.000
                                               :23(calc_pure_python)
{built-in method time.time}          <-        2     0.000  0.000
                                               :23(calc_pure_python)

也可以反過(guò)來(lái)，顯示哪些函數(shù)調(diào)用了其他函數(shù)：

In [6]: p.print_callees()
   Ordered by: cumulative time
　
Function                                          called...
                                              ncalls tottime cumtime
{built-in method builtins.exec}      ->       1    0.033  12.169
                                              julia1_nopil.py:1(<module>)
julia1_nopil.py:1(<module>)          ->       1    0.576  12.135
                                              julia1_nopil.py:23
                                                (calc_pure_python)
julia1_nopil.py:23(calc_pure_python) ->        1   8.266  11.429
                                              julia1_nopil.py:9
                                            (calculate_z_serial_purepython)
                                              2    0.000   0.000
{built-in method builtins.len}
                                              3    0.000   0.000
{built-in method builtins.print}
                                              1    0.006   0.006
{built-in method builtins.sum}
                                              2    0.000   0.000
{built-in method time.time}
                                        2002000    0.123   0.123
                                           {method 'append' of 'list' objects}
julia1_nopil.py:9(...)              -> 34219980    3.163   3.163
{built-in method builtins.abs}
{built-in method builtins.len}

cProfile的輸出非常詳細(xì)，為避免在大量單詞中間換行，我們可能需要兩個(gè)顯示器。cProfile是內(nèi)置的，為你快速找出瓶頸提供了極大的便利。本章后面將介紹line_profiler和memory_profiler，它們可以幫助你深入剖析需要關(guān)注的代碼行。