一次优化web项目的经历记录（二）

一次优化web项目的经历记录

这段时间以来的总结与反思

前言：最近很长一段时间没有更新博客了，忙于一堆子项目的开发，严重拖慢了学习与思考的进程。
开水倒满了需要提早放下杯子，晚了就会烫手，这段时间以来，写的东西越来越不严谨，各种低级错误频出，早该停下总结并巩固一下了。
但出于一些原因一直没付诸于行，终于，烫到手了

---

第二章：消失的118秒

---

上一章说到，我需要监控我的代码运行

在python里，这很容易实现，借助装饰器，在每个方法的首尾加入计时计数就好了。为此我写了个monitor模块，里面有register装饰器和report方法，分别用于注册一个要监控的方法、导出监测结果。

具体的代码很简单，这里就不粘贴了，主要说明一下，report导出的结果形如:

{"funcName": {"count": int, "time": float}}

其中funcName为监控的方法名，count为该方法调用次数，time为该方法总耗时，注意是总耗时，不是每一次的平均耗时。

接下来，我在overview接口的函数返回前，打印 monitor.report() ，再用 @monitor.register 注册方法内调用的一些可能耗时的函数或方法，这样我就得到了一份反映方法调用次数及耗时的日志

附件：monitor模块

---

那么overview函数内到底有哪些操作可能比较耗时，需要监控呢

粘贴大段的代码凑字数是毫无意义的，我只大概描述一下overview这个接口到底做了什么：
1. 连接数据库，获取所有管理员页面可能会用到的数据（学院、团队、足迹、地理位置、天气预警、图片url等等）
2. 分析这些数据，得出什么省什么市有多少团队，得出哪些团队处于活动时间，哪些未提交足迹，哪些团队所在地点有天气预警等
3. 访问阿里云oss，构造访问足迹内图片的url
4. （如果某团队或足迹没有可读的地理位置信息）调用百度地图api，根据坐标取得团队具体的地理位置

---

初步的排查发现，问题出在了函数 def get_team_dict(team): 内部

在对主要用到的可能耗时的方法|函数监控后，根据输出的结果，这个方法平均耗时140多秒。

{"get_team_dict": {"count": 388, "time": 141.34900045394897}}

get_team_dict(team) 函数主要做的是，将从数据库取得的team对象（team表对应的orm类Team的对象），转化为一个dict。

这个方法内有两个主要的操作，一个是 team.area() ，获取这个team对象对应的地点对象（area表对应的orm类Area的对象）。这一步耗时大约6s

{"area": {"count": 388, "time": 6.287999391555786}}

这6s是访问数据库造成的。如你所见，这里是可以优化的，把team与area做成一个view，就可以省去team.area()时查询数据库的消耗。

但一方面，这个数据是在我开发用的pc上进行统计的，相当于在访问远程数据库，考虑网络延时，效率其实远远低于实际生产环境。在这种情况下，花费时间对这种细节调优并不会带来太大好处。

我的意思是说现在造成性能瓶颈的主要原因不是它，应该优先去处理更重要的地方，这种细节还是要注意的，最好是在设计之初就把team与area绑定成relationship。

另一个是 team.analyze() 方法，也是任务量最大的方法，需要统计团队的各项信息

{"analyze": {"count": 388, "time": 134.26000142097473},}

那么接下来要做的就是对这个方法进一步拆解了，类似以上步骤，经过一些列拆解分析，最终发现造成延时的最内层方法是它：Footprint.get_pics()

def get_pics(self, url_root='/', style='@!preview'):
    """获取图片url列表"""
    from main.config import get_config
    ali_conf = get_config()['ali']
    util = OssUtil(
        ali_conf['key'], ali_conf['secret'],
        ali_conf['bucket'], ali_conf['endpoint']
    )
    return [
        {
            'image': image,
            'url': url_root[0:-1] + url_for('res.get_image', image=image) + '?param=' + style
        } for image in util.iter_directory(self.pics_dir)
    ]

方法内的导入时为了解决回环导入问题，但显然这不是很好的解决办法，虽然影响也不大。后来优化掉了

咦？内层不是还有方法吗？为什么不继续向内统计了呢？

答案是，我*也想啊，但就在这里出问题了，拆不下去了！！！

---

现在范围缩小到了 Footprint.get_pics()，并且由于奇怪的原因不能再继续缩小了

到底发生了什么呢？请看这份统计：

{
    "get_pics": {
        "count": 2679,
        "time": 405.7529995441437
    },
    "temp_get_image_dict": {
        "count": 6250,
        "time": 2.257997989654541
    },
    "get_config": {
        "count": 2679,
        "time": 0.920996904373169
    },
    "temp_url_for_get_image": {
        "count": 6250,
        "time": 2.1799986362457275
    },
    "__init__": {
        "count": 2679,
        "time": 1.189002275466919
    },
    "iter_directory": {
        "count": 2679,
        "time": 0.03299999237060547
    },
    "temp_get_ali_conf": {
        "count": 2679,
        "time": 1.0289976596832275
    }
}

告诉我你看到了什么？是的， get_pics() 方法耗时405s，其实是100多s
（这么说的原因是，由于开始时monitor模块没考虑到多次统计的清空问题，导致累加了4次）
而 get_pics() 方法内部的几个方法总耗时加起来却远远低于这个值！

带有 temp_ 前缀的函数是为了方便统计而从 get_pics 中拆出来的，根据命名大概也能猜出来原来是啥吧，

比如 temp_get_image_dict() 函数对应着原先的 return [{} for each in range] 中的 {} 部分

这就是为什么到了 get_pics() 后就拆不下去了，某个方法本身耗时100多s，其内部依次调用了几个函数，而这些函数总耗时加起来居然远低于方法本身，怎么可能！
好吧，这回真是头大了，有史以来第一次对自己的编程能力产生了怀疑，这太可怕了！

我·的·代·码·不·受·我·的·控·制！！！

---

聪明的你，告诉我这是怎么回事？

上一章说，“下面的内容是重点”，但很遗憾，现在还没到重点，或许有点啰嗦了？

嘛，“下面的内容”范围很广的，下一章、下两章，区别不是很大嘛~~~

就这样，或许在我下一章之前，你就已经意识到问题发生在哪儿了？明天见