Python性能分析实战1

前置知识

环境上发现有接口请求的响应时间高达10s以上，严重影响功能的使用

需要分析具体的代码执行耗时，针对问题代码进行优化，优化接口性能

使用 cProfile 工具，将目标接口的代码执行情况dump到文件中


with cProfile.Profile() as pf:
  # api business code
  # ...
  pf.dump_stats('api.prof')

获得dump文件后，使用 snakeviz 渲染方便查看

1
2
3


snakeviz api.prof

执行命令后，snakeviz 会自动打开浏览器显示渲染后的结果

可以看到接口中调用的service方法耗时长达10s左右，根据图示的调用栈可以看到耗时久主要是跟一个decrypt方法有关

接下来到底下的搜索框过滤出关于decrypt相关的执行情况

可以看到，decrypt相关的方法被调用37次，每次耗时0.2s左右

0.2s算是比较耗时的操作了，这样耗时的代码逻辑居然还执行了37次，最终导致总耗时有7s之多

找到了可能有问题的代码位置，接下来就要看看对应的代码逻辑了

本文中代码涉及私密信息，仅以伪代码的方式进行讲解

decrypt实际上是一个解密的方法，解密算法需要进行大量的运算，这也解释了为什么这个操作单次就需要耗费0.2s了

为什么需要这个解密操作

这里实际上是对需要连接的中间件密码进行解密

伪代码如下：


class MongoConfig:
    @property
    def mongo_password(self):
        return decrypt(BaseConfig.cipher)

生产环境中的密码都是经过加密处理的，所以这里需要解密的操作

那么就是说这个操作不可避免，也没有很大优化空间了

这里就有个疑问了，既然只是一个密码解密的操作，且只是一个配置类，为什么需要调用那么多次，只需要在服务启动之时进行一次初始化的操作就可以了

根据查看代码逻辑后分析的原因，尝试将解密的操作放到初始化的流程中，并使用functools.cached_property缓存计算结果（这样就可以保证只进行一次计算，后续直接从缓存获取结果）

伪代码如下：


@functools.cached_property
def mongo_password(self):
  return decrypt(BaseConfig.cipher)

代码修改后再次dump查看优化结果

看起来优化的效果还是很明显的，但是接口仍然有2s的耗时，没有达到预期的效果

分析耗时主要是在service中一个查询instance的方法，通过id查询 Mongo

这里查询数据的操作就耗费了2s

这里按道理如果这是个单独的一次查询，2s已经属于慢查询了，但是并没有接到慢查询的告警消息

可以先猜测下原因

好吧，这里应该已经猜到了大概的原因了

过滤下mongo和cursor关键字

从表格的数据可以看到，其实单次的耗时都属于正常范围，问题出在调用次数上

调用次数过多，导致最终累计耗时过长

从cursor.py中_refresh和__send_message方法的调用次数也能看出有猫腻，单次接口（本身该接口并不返回大量数据）访问需要向Mongo请求近100次的数据，这显然不太合理

定位到问题代码

以下展示伪代码：

其实该接口获取instance这一步的操作非常简单，只需要根据id获取数据，并做一定的数据富化和转换即可


for id in ids:
    instance =  InstanceColl().find_instance_by_id(id)
    # 接下来是数据富化和转换的逻辑
    # ...

这里很明显可以看到问题了，为了方便接下来的数据转换，直接对ids进行遍历并在循环内初始化InstanceColl去查询单个id的instance数据

这就是为什么需要建立大量Mongo连接，多次请求Mongo获取数据

最终将循环单个查询instance的代码重写，直接使用in查询一次查询所有instance再进行数据封装后，接口响应时间优化到200ms