最近發(fā)現(xiàn)項(xiàng)目API請求比較慢，通過抓包發(fā)現(xiàn)主要是response時(shí)間太長叭首，于是就開始進(jìn)行優(yōu)化工作徙垫。優(yōu)化工作的關(guān)鍵一步是定位出問題的瓶頸，對于優(yōu)化速度來說放棒，從優(yōu)化函數(shù)執(zhí)行時(shí)間這個(gè)維度去切入是一個(gè)不錯(cuò)的選擇姻报。
本文側(cè)重分析，不展開如何優(yōu)化
利器
工欲善其事间螟，必先利其器吴旋，我們需要一套方便高效的工具記錄函數(shù)運(yùn)行時(shí)間。說是一套工具厢破，但對于一個(gè)簡單項(xiàng)目或者日常開發(fā)來說荣瑟，實(shí)現(xiàn)一個(gè)工具類足矣，由于實(shí)現(xiàn)比較簡單摩泪，直接上代碼：
from functools import wraps
import cProfile
from line_profiler import LineProfiler
import time
def func_time(f):
"""
簡單記錄執(zhí)行時(shí)間
:param f:
:return:
"""
@wraps(f)
def wrapper(*args, **kwargs):
start = time.time()
result = f(*args, **kwargs)
end = time.time()
print f.__name__, 'took', end - start, 'seconds'
return result
return wrapper
def func_cprofile(f):
"""
內(nèi)建分析器
"""
@wraps(f)
def wrapper(*args, **kwargs):
profile = cProfile.Profile()
try:
profile.enable()
result = f(*args, **kwargs)
profile.disable()
return result
finally:
profile.print_stats(sort='time')
return wrapper
try:
from line_profiler import LineProfiler
def func_line_time(follow=[]):
"""
每行代碼執(zhí)行時(shí)間詳細(xì)報(bào)告
:param follow: 內(nèi)部調(diào)用方法
:return:
"""
def decorate(func):
@wraps(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 decorate
except ImportError:
def func_line_time(follow=[]):
"Helpful if you accidentally leave in production!"
def decorate(func):
@wraps(func)
def nothing(*args, **kwargs):
return func(*args, **kwargs)
return nothing
return decorate
原始代碼可以參考gist
如下笆焰，實(shí)現(xiàn)了3個(gè)裝飾器函數(shù)func_time,func_cprofile,func_line_time,分別對應(yīng)
- 簡單輸出函數(shù)的執(zhí)行時(shí)間
- 利用python自帶的內(nèi)置分析包
cProfile分析，它主要統(tǒng)計(jì)函數(shù)調(diào)用以及每個(gè)函數(shù)所占的cpu時(shí)間 - 利用
line_profiler開源項(xiàng)目,它可以統(tǒng)計(jì)每行代碼的執(zhí)行次數(shù)和執(zhí)行時(shí)間见坑。
使用說明
我們以一個(gè)簡單的循環(huán)例子來說明一下,
def test():
for x in range(10000000):
print x
func_time
關(guān)于func_time我覺得沒什么好說的嚷掠，就是簡單輸出下函數(shù)調(diào)用時(shí)間捏检，這個(gè)在我們粗略統(tǒng)計(jì)函數(shù)執(zhí)行時(shí)間的時(shí)候可以使用
如下：
@func_time
def test():
for x in range(10000000):
print x
# 輸出
test took 6.10190296173 seconds
func_cprofile
cProfile是python內(nèi)置包，基于lsprof的用C語言實(shí)現(xiàn)的擴(kuò)展應(yīng)用不皆，運(yùn)行開銷比較合理贯城，沒有外部依賴，適合做快速的概要測試
@func_cprofile
def test():
for x in range(10000000):
print x
# 輸出
3 function calls in 6.249 seconds
Ordered by: internal time
ncalls tottime percall cumtime percall filename:lineno(function)
1 6.022 6.022 6.249 6.249 test.py:41(test)
1 0.227 0.227 0.227 0.227 {range}
1 0.000 0.000 0.000 0.000 {method 'disable' of '_lsprof.Profiler' objects}
輸出說明：
單位為秒
-
第一行告訴我們一共有3個(gè)函數(shù)被調(diào)用霹娄。
正常開發(fā)過程能犯，第一行更多是輸出類似
194 function calls (189 primiive calls) in 0.249 seconds，(189 primiive calls)表示189個(gè)是原生（primitive）調(diào)用犬耻，表明這些調(diào)用不涉及遞歸 ncalls表示函數(shù)的調(diào)用次數(shù)踩晶，如果這一列有兩個(gè)數(shù)值，表示有遞歸調(diào)用枕磁，第一個(gè)是總調(diào)用次數(shù)渡蜻，第二個(gè)是原生調(diào)用次數(shù)。
tottime是函數(shù)內(nèi)部消耗的總時(shí)間（不包括調(diào)用其他函數(shù)的時(shí)間）透典。
percall是tottime除以ncalls，表示每次調(diào)用平均消耗時(shí)間顿苇。
cumtime是之前所有子函數(shù)消耗時(shí)間的累積和峭咒。
percall是cumtime除以原生調(diào)用的數(shù)量，表示該函數(shù)調(diào)用時(shí)纪岁，每個(gè)原生調(diào)用的平均消耗時(shí)間凑队。
filename:lineno(function)為被分析函數(shù)所在文件名、行號(hào)幔翰、函數(shù)名漩氨。
func_line_time
line_profiler可以生成非常直接和詳細(xì)的報(bào)告，但它系統(tǒng)開銷很大遗增，會(huì)比實(shí)際執(zhí)行時(shí)間慢一個(gè)數(shù)量級(jí)
@func_line_time()
def test():
for x in range(10000000):
print x
# 輸出
Timer unit: 1e-06 s
Total time: 14.4183 s
File: /xx/test.py
Function: test at line 41
Line # Hits Time Per Hit % Time Line Contents
==============================================================
41 @func_line_time()
42 def test():
43 10000001 4031936.0 0.4 28.0 for x in range(10000000):
44 10000000 10386347.0 1.0 72.0 print x
輸出說明：
單位為微秒
Total Time：測試代碼的總運(yùn)行時(shí)間
Line:代碼行號(hào)
Hits：表示每行代碼運(yùn)行的次數(shù)
Time：每行代碼運(yùn)行的總時(shí)間
Per Hits：每行代碼運(yùn)行一次的時(shí)間
% Time：每行代碼運(yùn)行時(shí)間的百分比
總結(jié)
日常開發(fā)中叫惊，可以使用func_time,func_cprofile做基本檢查，定位大致問題做修，使用func_line_time進(jìn)行更細(xì)致的深入檢查霍狰。
注：
func_line_time還可以檢查函數(shù)內(nèi)部調(diào)用的函數(shù)執(zhí)行時(shí)間，通過follow參數(shù)指定對應(yīng)的內(nèi)部調(diào)用的函數(shù)聲明即可饰及，該參數(shù)是個(gè)數(shù)組蔗坯，也就是說可以檢查多個(gè)內(nèi)部調(diào)用的函數(shù)
