最近在项目里遇到个 Flask 内存泄漏的问题，前前后后 debug 了几天。
起因是有人报错，发现某个 Flask 服务出现了请求超过 3 分钟还没有返回结果。查服务日志有很多的 WORKER TIMEOUT，是 gunicorn 的进程超时后 kill 的机制。但是日志只能看到超时的进程 id，看不到是哪个请求超时了。正好这个服务上有一个比较耗时的 API（下称 API A），平均耗时在 1-2 分钟，因此我们初步怀疑是 API A 最近变慢了，超过了 3 分钟触发了超时。至于为什么其它服务超时，一种合理的解释是前端的重试机制使得多次请求了 API A，导致 gunicorn 的 8 个进程都在处理这个 API，没有多的进程处理其它 API，别的 API 也就一起跟着超时了。
我们这样怀疑，但是并没有证据就是 API A 导致的超时。因此简单写了一个中间件来在每个请求开始和结束的时候输出一条日志，记录每个 API 是由哪个进程处理。同时为了缓解超时的问题，把 WORKER 数量翻倍到 16，避免 API A 把服务的所有进程一下子打满。
class LoggingMiddleware:
def __init__(self, app):
self.app = app
def __call__(self, environ, start_response):
process_id = os.getpid()
http_method = environ['REQUEST_METHOD']
http_path = environ['PATH_INFO']
start = time()
logging.info(f'[LoggingMiddleware] [{process_id}] starts {http_method} {http_path}')
response = self.app(environ, start_response)
end = time()
logging.info(f'[LoggingMiddleware] [{process_id}] finishes {http_method} {http_path} in {round(end - start, 4)}s')
return response
app = Flask(APP_NAME)
app.wsgi_app = LoggingMiddleware(app.wsgi_app)
如此设置并上线后，一两天以后又出现了超时。这也合理，毕竟我们只是加了日志，改了一下配置，并没有从根本解决问题。不过至少我们有日志了。
分析日志以后发现，不少 API 都出现了超时，并且是随机出现的。比如另一个查询数据库的 API 某次耗时 150s，而我们再调用相同的 API 时，都只耗时 0.1s 左右。上面的推测解释不了这个现象。
我们考虑从新的方向来追查。之前有同事搭建了 Grafana 服务，并导入了 k8s 集群的数据，可以方便地查看每个 pod 的 CPU、内存占用等数据。我们发现此时这个服务的 pod 的 CPU 和内存都满了，占用 90% 以上。重启服务后 CPU 和内存占用均正常。因此新的推测是应用出现了内存泄漏，长时间运行后内存占用就满了，进而触发频繁的交换和 gc，导致 CPU 也跟着满了。也有一种可能是，服务确实需要 4 GB 以上的内存来作缓存和其它用途，只给 4GB 就会 OOM。
因此，我们将 pod 的内存翻倍到 8GB，同时将 WORKER 数量调回到 8（更多的 WORKER 会占用更高的内存），尝试缓解这个问题。除此以外没有做更多操作，观察服务是否能够把 8GB 吃满，如果吃满了，内存泄漏的嫌疑就很大了；反之如果内存稳定在一个数，可能是服务的确需要这么多内存。
再次上线后，过了几天，8GB 也被占满了。这下内存泄漏石锤了。
确认是内存泄漏以后，就需要定位内存泄漏的地方了。对于一般的 Python 脚本，可以使用 memory_profiler (opens new window) 来查询运行一次的内存占用，或者内存占用随时间的变化。但是这个工具对于一个 Flask 服务不太好用，一是 Flask 服务需要长期运行，二是这个服务上有很多 API，需要确定到具体哪个 API 有内存泄漏。
于是又手搓了一个中间件，用于输出 API 开始和结束时的内存占用差，看有没有什么 API 是在持续增加内存使用的。
import logging
import os
from flask import Flask
import humanfriendly
import psutil
class MemoryMonitorMiddleware:
def __init__(self, app):
self.app = app
def __call__(self, environ, start_response):
http_method = environ['REQUEST_METHOD']
http_path = environ['PATH_INFO']
process_id = os.getpid()
process = psutil.Process(os.getpid())
mem_before = process.memory_info().rss
response = self.app(environ, start_response)
mem_after = process.memory_info().rss
mem_diff = mem_after - mem_before
logging.info(f'[MemoryMonitorMiddleware] pid:{process_id}, '
f'method:{http_method}, url:{http_path}, '
f'mem_before: {humanfriendly.format_size(mem_before)} ({mem_before}), '
f'mem_after: {humanfriendly.format_size(mem_after)} ({mem_after}), '
f'mem_diff: {humanfriendly.format_size(mem_diff)} ({mem_diff})')
return response
app = Flask(APP_NAME)
app.wsgi_app = MemoryMonitorMiddleware(app.wsgi_app)
部署了一段时间以后看看日志，并按进程 ID 筛选（grep "pid:116"）。果然有一个 API，每次调用时都会占用更多内存，且后续没有因为 gc 等原因释放过这部分内存。
[INFO] [MemoryMonitorMiddleware] pid:116, method:GET, url:/api/v1/a, mem_before: 345.42 MB (345419776), mem_after: 345.16 MB (345157632), mem_diff: -262144 bytes (-262144)
[INFO] [MemoryMonitorMiddleware] pid:116, method:HEAD, url:/api/v1/b, mem_before: 345.16 MB (345157632), mem_after: 407.2 MB (407195648), mem_diff: 62.04 MB (62038016)
[INFO] [MemoryMonitorMiddleware] pid:116, method:HEAD, url:/api/v1/b, mem_before: 407.2 MB (407195648), mem_after: 443.36 MB (443359232), mem_diff: 36.16 MB (36163584)
[INFO] [MemoryMonitorMiddleware] pid:116, method:GET, url:/api/v2/c, mem_before: 443.36 MB (443359232), mem_after: 443.36 MB (443359232), mem_diff: 0 bytes (0)
于是问题再次缩小到这一个 API 里。
这个 API 里做了两个事情：一是从对象存储中拿到一个文件并反序列化，二是用反序列化的数据绘制图表。由于第一个步骤使用的 boto3 框架比较成熟，我们也在很多地方用到了这个框架，没有出现内存泄漏，因此推测是绘制图表的时候出现了内存泄漏。
为了证明这个推测，写了一个脚本，从本地读取文件并序列化，然后用相同的逻辑绘制图表。执行多次，监测每次的内存占用。
def load_data() -> dict:
# ...
def draw(data: Optional[dict]):
# ...
def get_memory_usage():
process = psutil.Process(os.getpid())
return process.memory_info().rss / 1024 ** 2
if __name__ == '__main__':
data = load_data()
app = Flask(__name__)
with app.app_context():
for i in range(1, 1000):
draw(data)
# gc.collect()
print(f'turn {i}, current memory usage: {get_memory_usage()} MB')
在没有主动 gc 的版本中，每次请求后增加 3-30 MB 内存，正好能和前面 API 调用前后增加的 30MB 内存对应上。
turn 1, current memory usage: 352.30078125 MB
turn 2, current memory usage: 394.75 MB
turn 3, current memory usage: 427.73046875 MB
.....
turn 19, current memory usage: 601.33984375 MB
turn 20, current memory usage: 621.6484375 MB
.../site-packages/seaborn/axisgrid.py:453: RuntimeWarning:
More than 20 figures have been opened. Figures created through the pyplot interface (`matplotlib.pyplot.figure`) are retained until explicitly closed and may consume too much memory. (To control this warning, see the rcParam `figure.max_open_warning`). Consider using `matplotlib.pyplot.close()`.
...
turn 35, current memory usage: 762.19140625 MB
turn 36, current memory usage: 765.18359375 MB
在主动 gc 的版本中，每次请求后增加 3-6 MB 内存占用。
turn 1, current memory usage: 325.06640625 MB
turn 2, current memory usage: 329.59765625 MB
turn 3, current memory usage: 334.8203125 MB
.....
turn 19, current memory usage: 420.140625 MB
turn 20, current memory usage: 424.09765625 MB
.../site-packages/seaborn/axisgrid.py:453: RuntimeWarning:
More than 20 figures have been opened. Figures created through the pyplot interface (`matplotlib.pyplot.figure`) are retained until explicitly closed and may consume too much memory. (To control this warning, see the rcParam `figure.max_open_warning`). Consider using `matplotlib.pyplot.close()`.
...
turn 226, current memory usage: 1507.76171875 MB
turn 227, current memory usage: 1512.53125 MB
turn 228, current memory usage: 1518.86328125 MB
可以说明，每绘制一张图，gc 前会增加 30 MB，gc 后会增加 3-6 MB 内存占用。
seaborn 也有 warning，提示在画完图后没有 close 掉，需要 matplotlib.pyplot.close()。这很可能就是内存泄漏的原因。
修改脚本代码后再进行测试，观察内存是否持续上涨：
turn 1, current memory usage: 324.60546875 MB
turn 2, current memory usage: 325.01953125 MB
turn 3, current memory usage: 329.30078125 MB
turn 4, current memory usage: 331.84765625 MB
turn 5, current memory usage: 332.09765625 MB
turn 6, current memory usage: 332.34765625 MB
turn 7, current memory usage: 333.359375 MB
turn 8, current memory usage: 333.609375 MB
turn 9, current memory usage: 333.859375 MB
...
turn 49, current memory usage: 339.859375 MB
turn 50, current memory usage: 339.859375 MB
turn 51, current memory usage: 340.5859375 MB
turn 52, current memory usage: 339.859375 MB
turn 53, current memory usage: 339.859375 MB
turn 54, current memory usage: 339.859375 MB
turn 55, current memory usage: 339.859375 MB
turn 56, current memory usage: 340.109375 MB
...
turn 658, current memory usage: 341.33984375 MB
turn 659, current memory usage: 340.60546875 MB
测试结果表明，在 56 轮后内存占用趋于稳定。将代码部署上线后，内存占用也趋于稳定，说明暂时没有其它内存泄漏问题。
如果仍存在内存泄漏问题，在将问题代码定位并抽出 Flask 框架以后，就可以借助 memory profile 工具进行分析了。
最后简单复盘一下：
- 这次能快速定位到问题，很大一个原因是我们能在生产环境下进行调整配置和试错；但也许下次就不行了。完善的日志和 pod 监控对快速定位问题都很有必要，对于关键服务、可用性要求高的服务，一定要提前做好监控，还可以评估成本和收益以后考虑是否要做容灾。
- 这次 debug 过程也很意思，表象是服务请求超时，根本原因却是内存泄漏。如果服务出现请求超时，可以考虑看一眼服务的 CPU 和内存，判断是服务的问题，还是 API 本身的问题。