一次优化web项目的经历记录（二）
一次优化web项目的经历记录
这段时间以来的总结与反思
前言：最近很长一段时间没有更新博客了，忙于一堆子项目的开发，严重拖慢了学习与思考的进程。
开水倒满了需要提早放下杯子，晚了就会烫手，这段时间以来，写的东西越来越不严谨，各种低级错误频出，早该停下总结并巩固一下了。
但出于一些原因一直没付诸于行，终于，烫到手了
第二章：消失的118秒
上一章说到，我需要监控我的代码运行
在python里，这很容易实现，借助装饰器，在每个方法的首尾加入计时计数就好了。为此我写了个monitor模块，里面有register装饰器和report方法，分别用于注册一个要监控的方法、导出监测结果。
具体的代码很简单，这里就不粘贴了，主要说明一下，report导出的结果形如:
{"funcName": {"count": int, "time": float}}其中funcName为监控的方法名，count为该方法调用次数，time为该方法总耗时，注意是总耗时，不是每一次的平均耗时。
接下来，我在overview接口的函数返回前，打印 monitor.report() ，再用 @monitor.register 注册方法内调用的一些可能耗时的函数或方法，这样我就得到了一份反映方法调用次数及耗时的日志
那么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，其内部依次调用了几个函数，而这些函数总耗时加起来居然远低于方法本身，怎么可能！
好吧，这回真是头大了，有史以来第一次对自己的编程能力产生了怀疑，这太可怕了！
我·的·代·码·不·受·我·的·控·制！！！
聪明的你，告诉我这是怎么回事？
上一章说，“下面的内容是重点”，但很遗憾，现在还没到重点，或许有点啰嗦了？
嘛，“下面的内容”范围很广的，下一章、下两章，区别不是很大嘛~~~
就这样，或许在我下一章之前，你就已经意识到问题发生在哪儿了？明天见
