Vimer的程序世界

最近在grahite上看到响应时间变得很长，虽说之前没有特意去优化性能，但是感觉也不应该这么差才对。

我们的服务器框架用的就是我之前开源的 maple，每个命令字都对应一个入口函数，如下：

@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中也可以直接用。

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。

相应的，我也封装了一个分析工具：

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()

用起来非常简单，执行一下:

python stat.py -f login.stat -p0.1

输出结果如下:

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人：

异常的部分均使用颜色加亮了，可以看出几个端倪：

1. 随着人数变多，有些部分的请求翻了几倍
2. 读取数据库和redis的调用量太大

既然知道了是与存储通信的问题，那么接下来就来看看是哪些地方调用了 get_db_user，get_user_from_db。

cProfile 提供了一个方法:

#如果想知道有哪些函数调用了bar,可使用
p.print_callers(0.5, "bar")

所以通过这种方法拿到:

所以接下来就去看下上面的代码中这些数据库调用是否是必要就可以了。

基本就是这样了。

另外之前也出现过python内存泄漏的定位，可惜没有写下来文档，只记得是用 objgraph，不过用起来也比较简单，等下次遇到再说吧。