如何進行 Python效能分析，你才能如魚得水？

OneAPM官方技術部落格發表於2016-05-16
Python

【編者按】本文作者為 Bryan Helmig，主要介紹 Python 應用效能分析的三種進階方案。文章系國內 ITOM 管理平臺 OneAPM 編譯呈現。

我們應該忽略一些微小的效率提升，幾乎在 97% 的情況下，都是如此：過早的優化是萬惡之源。—— Donald Knuth

如果不先想想Knuth的這句名言，就開始進行優化工作，是不明智的。然而，有時你為了獲得某些特性不假思索就寫下了O(N^2) 這樣的程式碼，雖然你很快就忘記它們了，它們卻可能反咬你一口，給你帶來麻煩：本文就是為這種情況而準備的。

本文會介紹用於快速分析Python程式的一些有用工具和模式。主要目標很簡單：儘快發現問題，修復問題，並確認修復是行之有效的。

編寫一個測試

在教程開始前，要先寫一個簡單的概要測試來演示延遲。你可能需要引入一些最小資料集來重現可觀的延遲。通常一或兩秒的執行時間，已經足夠在發現問題時，讓你做出改進了。

此外，進行一些基礎測試來確保你的優化不會修改緩慢程式碼的行為也是有必要的。在分析和調整時，你也可以多次執行這些測試，作為基準。

那麼現在，我們來看第一個分析工具。

簡單的計時器

計時器是簡單、靈活的記錄執行時間的方法。你可以把它放到任何地方，並且幾乎沒有副作用。自己建立計時器非常簡單，並且可以根據你的喜好定製化。例如，一個簡單的計時器可以這麼寫：

import time
def timefunc(f):    
  def f_timer(*args, **kwargs):
        start = time.time()
        result = f(*args, **kwargs)
        end = time.time()        
        print f.__name__, 'took', end - start, 'time'        
        return result    
     return f_timer

def get_number():    
  for x in xrange(5000000):        
      yield x

@timefunc
def expensive_function():    
   for x in get_number():
        i = x ^ x ^ x    
   return 'some result!'
# prints "expensive_function took 0.72583088875 seconds"
result = expensive_function()

當然，你可以用上下文管理器來增強它的功能，新增一些檢查點或其他小功能：

import time

class timewith():    
   def __init__(self, name=''):
        self.name = name
        self.start = time.time()    

   @property    
   def elapsed(self):        
     return time.time() - self.start    

   def checkpoint(self, name=''):        
      print '{timer} {checkpoint} took {elapsed} seconds'.format(
            timer=self.name,
            checkpoint=name,
            elapsed=self.elapsed,
        ).strip()    

    def __enter__(self):        
       return self    

    def __exit__(self, type, value, traceback):
        self.checkpoint('finished')        
        pass

def get_number():    
   for x in xrange(5000000):        
      yield x

def expensive_function():    
   for x in get_number():
        i = x ^ x ^ x    
    return 'some result!'

# prints something like:
# fancy thing done with something took 0.582462072372 seconds
# fancy thing done with something else took 1.75355315208 seconds
# fancy thing finished took 1.7535982132 seconds
with timewith('fancy thing') as timer:
    expensive_function()
    timer.checkpoint('done with something')
    expensive_function()
    expensive_function()
    timer.checkpoint('done with something else')

# or directly
timer = timewith('fancy thing')
expensive_function()
timer.checkpoint('done with something')

有了計時器，你還需要進行一些“挖掘”工作。 封裝一些更為高階的函式，然後確定問題根源之所在，進而深入可疑的函式，不斷重複。當你發現執行特別緩慢的程式碼之後，修復它，然後進行測試以確認修復成功。

提示：不要忘了便捷的 timeit 模組！將它用於小段程式碼塊的基準校驗比實際測試更加有用。

  • 計時器的優點：容易理解和實施，也非常容易在修改前後進行對比，對於很多語言都適用。
  • 計時器的缺點：有時候，對於非常複雜的程式碼庫而已太過簡單，你可能會花更多的時間建立、替換樣板程式碼，而不是修復問題！

內建分析器

內建分析器就好像大型槍械。雖然非常強大，但是有點不太好用，有時，解釋和操作起來比較困難。

你可以點此閱讀更多關於內建分析模組的內容，但是內建分析器的基本操作非常簡單：你啟用和禁用分析器，它能記錄所有的函式呼叫和執行時間。接著，它能為你編譯和列印輸出。一個簡單的分析器用例如下：

import cProfile

def do_cprofile(func):    
  def profiled_func(*args, **kwargs):
        profile = cProfile.Profile()        
        try:
            profile.enable()
            result = func(*args, **kwargs)
            profile.disable()            
            return result        
            finally:
            profile.print_stats()    
        return profiled_func

def get_number():    
   for x in xrange(5000000):          
      yield x

@do_cprofile
def expensive_function():    
   for x in get_number():
        i = x ^ x ^ x    
   return 'some result!'

# perform profiling
result = expensive_function()

在上面程式碼中，控制檯列印的內容如下：

         5000003 function calls in 1.626 seconds

   Ordered by: standard name   
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)  
   5000001    0.571    0.000    0.571    0.000 timers.py:92(get_number)        
   1    1.055    1.055    1.626    1.626 timers.py:96(expensive_function)        
   1    0.000    0.000    0.000    0.000 {method 'disable' of '_lsprof.Profiler' objects}

如你所見，它給出了不同函式呼叫的詳細資料。但是，它遺漏了一項關鍵資訊：是什麼原因，導致函式執行如此緩慢？

然而，這對於基礎分析來說是個好的開端。有時，能夠幫你儘快找到解決方案。我經常在開始除錯過程時，把它作為基本測試，然後再深入測試某個不是執行緩慢，就是呼叫頻繁的特定函式。

  • 內建分析器的優點：沒有外部依賴，執行非常快。對於快速的概要測試非常有用。
  • 內建分析器的缺點：資訊相對有限，需要進一步的除錯；報告不太直觀，尤其是對於複雜的程式碼庫。

Line Profiler

如果內建分析器是大型槍械，line profiler就好比是離子炮。它非常的重量級且強大，使用起來也非常有趣。

在這個例子裡，我們會用非常棒的kernprof line-profiler，作為 line_profiler PyPi包。為了方便使用，我們會再次用裝飾器進行封裝，同時也可以防止我們把它留在生產程式碼裡（因為它比蝸牛還慢）。

try:    
   from line_profiler import LineProfiler    

   def do_profile(follow=[]):        
      def inner(func):            
         def profiled_func(*args, **kwargs):                
            try:
                    profiler = LineProfiler()
                    profiler.add_function(func)                    
                    for f in follow:
                        profiler.add_function(f)
                    profiler.enable_by_count()                    
                    return func(*args, **kwargs)                
             finally:
                    profiler.print_stats()            
         return profiled_func        
       return inner

except ImportError:    
  def do_profile(follow=[]):        
    "Helpful if you accidentally leave in production!"        
    def inner(func):            
       def nothing(*args, **kwargs):                
          return func(*args, **kwargs)            
       return nothing        
     return inner

def get_number():    
   for x in xrange(5000000):        
     yield x


@do_profile(follow=[get_number])
def expensive_function():    
   for x in get_number():
        i = x ^ x ^ x    
   return 'some result!'

result = expensive_function()

如果執行上面的程式碼，就會看到以下的報告：

Timer unit: 1e-06 s

File: test.py
Function: get_number at line 43Total time: 4.44195 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================    
43                                           def get_number():    
44   5000001      2223313      0.4     50.1      for x in xrange(5000000):    
45   5000000      2218638      0.4     49.9          yield x

File: test.py
Function: expensive_function at line 47Total time: 16.828 s

Line #      Hits         Time  Per Hit   % Time  Line Contents
==============================================================    
47                                           def expensive_function():    
48   5000001     14090530      2.8     83.7      for x in get_number():    
49   5000000      2737480      0.5     16.3          i = x ^ x ^ x    
50         1            0      0.0      0.0      return 'some result!'

如你所見，這是一個非常詳細的報告，能讓你完全洞悉程式碼的執行情況。和內建的cProfiler不同，它能分析核心語言特性的耗時，比如迴圈或匯入，並且給出不同程式碼行的耗時累計值。

這些細節能讓我們更容易理解函式內部原理。 此外，如果需要研究第三方庫，你可以將其匯入，直接輸到裝飾器中。

提示：將測試函式封裝為裝飾器，再將問題函式作為引數傳進去就好了！

  • Line Profiler 的優點：有非常直接和詳細的報告。能夠追蹤第三方庫裡的函式。
  • Line Profiler 的缺點：因為系統開銷巨大，會比實際執行時間慢一個數量級，所以不要用它進行基準測試。同時，它是外部工具。

結論和最佳方案

你應該使用簡單的工具（比如計時器或內建分析器）對測試用例（特別是那些你非常熟悉的程式碼）進行基本檢查，然後使用更慢但更加細緻的工具，比如 line_profiler，深入檢查函式內部。

十有八九，你會發現一個愚蠢的錯誤，比如在迴圈內重複呼叫，或是使用了錯誤的資料結構，消耗了90%的函式執行時間。在進行快速（且令人滿意的）調整之後，問題就能得到解決。

如果你仍然覺得程式執行太過緩慢，然後開始進行對比屬性訪問(ttribute accessing)方法，或調整相等檢查(equality checking)方法等晦澀的調整，你可能已經適得其反了。你應該考慮如下方法：

1．忍受緩慢或者預先計算/快取 2．重新思考整個實施方法 3．使用更多的優化資料結構(通過 Numpy，Pandas等) 4．編寫一個 C擴充套件

注意，優化程式碼會帶來有罪惡感的快樂！尋找加速Python的合理方法很有趣，但是不要因為加速，破壞了本身的邏輯。易讀的程式碼比執行速度更重要。實施快取，往往是最簡單的解決方法。

教程到此為止，希望你今後的Python效能分析能夠如魚得水！

PS: 點此檢視程式碼例項。此外，點此學習如何如魚得水地除錯 Python 程式。

OneAPM 能幫你檢視 Python 應用程式的方方面面，不僅能夠監控終端的使用者體驗，還能監控伺服器效能，同時還支援追蹤資料庫、第三方 API 和 Web 伺服器的各種問題。想閱讀更多技術文章，請訪問 OneAPM 官方技術部落格。

本文轉自 OneAPM 官方部落格

原文地址：https://zapier.com/engineering/profiling-python-boss/

相關文章