最近在grahite上看到響應時間變得很長，雖說之前沒有特意去優化效能，但是感覺也不應該這麼差才對。
我們的伺服器框架用的就是我之前開源的 maple，每個命令字都對應一個入口函式，如下：
|
1 2 3 4 5 6 7 8 9 10 |
@app.route(2) def login(request): logger.error("login: %s", request.gw_box) uid = request.box.get_json()["uid"] request.login_client(uid) time.sleep(1) request.write_to_client(dict( ret=0, body="login %s" % uid )) |
所以只要找到一種方法分析這個函式對應的內部呼叫情況就可以了。
很方便的，python內建了cProfile類來完成我們想要的功能，我給封裝成為一個裝飾器，用起來更方便一些，當然在django和flask中也可以直接用。
|
1 2 3 4 5 6 7 8 9 10 |
def monitor_profile(func): import cProfile import functools @functools.wraps(func) def func_wrapper(*args, **kwargs): def tmpfunc(): return func(*args, **kwargs) # 直接用run是不行的 cProfile.runctx("tmpfunc()", globals(), locals(), "%s.stat" % func.__name__) return func_wrapper |
執行到對應的函式後，就會將統計寫到函式名對應的stat檔案中，比如 login.stat。
相應的，我也封裝了一個分析工具：
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 20 21 22 23 24 25 |
import sys import argparse import pstats def build_parser(): parser = argparse.ArgumentParser() parser.add_argument('-f', '--file', help='stat filename', action='store', required=True) parser.add_argument('-s', '--sort', help='sort type: cumulative, time', action='append') parser.add_argument('-p', '--percent', help='sort type', action='store', default=0.5, type=float) parser.add_argument('-d', '--dir', help='show directory', action='store_true') return parser def main(): args = build_parser().parse_args() p = pstats.Stats(args.file) sort_keys = args.sort or ('cumulative', 'time') if not args.dir: p = p.strip_dirs() p.sort_stats(*sort_keys).print_stats(args.percent) if __name__ == '__main__': main() |
用起來非常簡單，執行一下:
|
1 |
python stat.py -f login.stat -p0.1 |
輸出結果如下:
|
1 2 3 4 5 6 7 8 9 10 11 12 13 14 15 16 17 18 19 |
Mon Apr 6 11:16:02 2015 login.stat 442 function calls (439 primitive calls) in 1.002 seconds Ordered by: cumulative time, internal time List reduced from 107 to 11 due to restriction ncalls tottime percall cumtime percall filename:lineno(function) 1 0.000 0.000 1.002 1.002 :1() 1 0.000 0.000 1.002 1.002 worker.py:40(tmpfunc) 1 0.000 0.000 1.002 1.002 worker.py:46(login) 1 1.000 1.000 1.000 1.000 {time.sleep} 1 0.000 0.000 0.001 0.001 request.py:73(write_to_client) 1 0.000 0.000 0.001 0.001 __init__.py:1176(error) 1 0.000 0.000 0.001 0.001 __init__.py:1260(_log) 3 0.000 0.000 0.000 0.000 box.py:41(__init__) 1 0.000 0.000 0.000 0.000 request.py:146(login_client) 1 0.000 0.000 0.000 0.000 __init__.py:1281(handle) 1 0.000 0.000 0.000 0.000 __init__.py:1313(callHandlers) |
可以明顯看到時間消耗在 time.sleep 上。
好了，上面只是一個簡單的示例，接下來看今天解決的問題的真實情況。
下面兩張圖分別是牌桌內有2人和7人的情況下的呼叫圖。
2人：
7人：
異常的部分均使用顏色加亮了，可以看出幾個端倪：
- 隨著人數變多，有些部分的請求翻了幾倍
- 讀取資料庫和redis的呼叫量太大
既然知道了是與儲存通訊的問題，那麼接下來就來看看是哪些地方呼叫了 get_db_user，get_user_from_db。
cProfile 提供了一個方法:
|
1 2 |
#如果想知道有哪些函式呼叫了bar,可使用 p.print_callers(0.5, "bar") |
所以通過這種方法拿到:
所以接下來就去看下上面的程式碼中這些資料庫呼叫是否是必要就可以了。
基本就是這樣了。
另外之前也出現過python記憶體洩漏的定位，可惜沒有寫下來文件，只記得是用 objgraph，不過用起來也比較簡單，等下次遇到再說吧。
