Python 内存泄漏问题排查

一. 问题现象

最近我在做一个推荐系统中的离线计算时，遇到了离线定时任务总是挂掉的问题，日志中记录的错误异常如下:

python exited with code 137

在stackoverflow上查询了一下这个错误的原因, 高赞回答的解释如下:

Exit code 137 means that your process was killed by (signal 9) SIGKILL . In the case you manually stopped it - there’s your answer.
If you didn’t manually stop the script and still got this error code, then the script was killed by your OS. In most of the cases, it is caused by excessive memory usage.

这看起来是Python内存溢出导致的问题，于是我从定时任务实例对应的系统监控图查看了一下内存占用的情况，如下:

图中果然可以看到有内存打满的情况，因此这的确是一个典型的OOM问题。于是我对这个问题往解决OOM的方向进一步分析。
以之前Java OOM的排查经验，解决这种问题一般需要dump内存快照，分析内存分配，对象引用链和GC状态等等。因此我猜测Python的OOM排查应该也是类似的。

二. 摸索分析

1. 了解内存分析

工欲善其事，必先利其器。我先对Python的内存回收机制以及常用的Python内存分析工具进行了调研，调研的结果如下:

(1) Python 内存回收的原理: 采用得是引用计数机制为主, 标记-清楚和分代收集两种机制为辅的策略

(2) 常用的内存分析工具:

• objgraph: 可以打印类型对象的数目, 绘制有关objs的引用图 link
• tracemalloc: Python3内置库，非常轻量和强大，可以用于追踪内存的使用情况，查看对象和调研栈（Python2如果安装的话需要编译) link
• pympler: 可以统计内存里边各种类型的使用, 获取对象的大小 link
• pyrasite: 内存注入工具的第三方库, 可以渗透进入正在运行的python进程动态修改里边的数据和代码 link
• guppy: 可以对堆里边的对象进行统计 link

2. 确认循环引用

首先检查了代码中是否存在以下2个问题:

• 是否有大对象由于长期被引用而导致未必及时释放
• 是否有class重写了__del__()方法而导致循环引用的垃圾回收没有生效

很可惜这两类问题并没有在代码中出现。为此我还特意使用了objgraph打印数量最多的几个对象，并查看这几个对象的引用链情况，并未发现有循环应用的情况。

3. 确认是否是GC问题

先在debug离线任务代码时，通过gc.isenabled() 查看GC是否在工作，返回True说明正常。
由于我们离线计算需要拉取和计算大量数据，现有实例的内存预估不够一次计算的使用量，因此我们的离线计算中有分批的逻辑。通过debug发现了内存的堆积会随着计算的批次不断增加，而已完成的批次中用到的内存似乎并没有及时释放。由于Python的内存回收，不会因为对象的引用计算器变0立刻回收对象，而是会找一个对应用进程影响较小的时机进行内存释放（这点与Java较像)。于是我在每个批次计算完这些大的对象时，手动执行del 对象来主动释放对象。尝试之后收效甚微，没有从根本解决问题。

4. 分析内存快照

我打算使用Python 3自带的tracemalloc来分析内存快照的分布情况(参考了之前Java的经验), 发现这个工具十分好用!

(1) 测试代码

首先我在离线环境里给原有代码加上了按计算逻辑分步骤打印分析内存快照的代码，大致如下:

...
tracemalloc.start()
    for xxx in xxx:
        first_size, first_peak = tracemalloc.get_traced_memory()
  
        snapshot = tracemalloc.take_snapshot()
        top_lineno = snapshot.statistics('lineno')
        print("snapshot [ Top 10 ]")
        for stat in top_lineno[:10]:
            print(stat)
        top_traceback = snapshot.statistics('traceback')
        stat = top_traceback[0]
        print("%s memory blocks: %.1f KiB" % (stat.count, stat.size / 1024))
        for line in stat.traceback.format():
            print(line)
		...

(2) 分析快照中的内存分配

先上一个内存整体分配的状况图

我们可以看到在每个批次计算完所有内容的第5个步骤时出现了内存的峰值(fifth_size)，在第6个步骤调用了del 删除对象之后内存有所回收(sixth_size)，说明了每个批次本身的内存回收还是在正常工作的。那么我就需要分别重点分析每个批次内的内存占用峰值情况，和每个计算批次间内存堆积的原因了。

三. 定位原因

1. 分析批次间内存堆积 (主要)

下面的截图是每个批次计算完并使用del释放了当前批次占用的临时变量内存时的内存分布状况

我们可以发现大部分的内存占用除了和Azure Function Core相关的核心组件占用的内存，主要就是Python进程里的thread了。我们这个项目中正好用到了线程池的多线程来并发同步数据。于是我检查了一下线程池的写法，确认是否可能是线程泄漏导致的问题。
原来的线程池用法:

def dump_table():
	...
	from concurrent.futures import ThreadPoolExecutor
	pool = ThreadPoolExecutor(batch_config['update_cosmos_max_threads'])
	for item in results:
    	pool.submit(cosmos_client.insert, item)
    ...

这么写如果没有分批调用dump_table()的逻辑是没有什么大问题的。但是我们的程序中为了保证插入数据的速度，会用for循环在外层调用dump_table(), 因此可能会导致原有的线程来不及释放，又new出了新的ThreadPoolExecutor来启动其他的新线程而出现的线程堆积。为了验证这个想法，查看了当时的对象数量分配情况，可以看到有大量的ThreadPoolExecutor出现，因此可以确定这是一个线程池线程没有及时释放的问题。

Python官方文档里推荐使用with语句来自动立即释放结束task的线程 sample link

We can use a with statement to ensure threads are cleaned up promptly

于是我立即把线程池的使用代码改成了以下方式

with futures.ThreadPoolExecutor(max_workers=xxx, thread_name_prefix=xxx) as executor:
	for item in results:
	executor.submit(cosmos_client.insert, item)

将该优化上线后发现果然解决了批次间内存堆积的问题

2. 分析批次内内存峰值 (次要)

以下是批次内的内存快照分析图:

如图可见在计算一个批次时，内存消耗最多的地方在json decode上。而在我们的离线计算逻辑中只有使用KQL进行类ORM查询来获取对象时才有json decode的逻辑。这个是在业务中使用KQL逻辑不够合理,parse_json()有大量的重复调用。把相应的逻辑进行优化后，会发现每个批次之内的内存峰值下降了一些

四. 解决效果

首先看内存使用情况，如图可见按批次计算数据时内存占用率的波峰波谷已经保持规律并且平稳进行了

其次由于是线程没有及时释放导致的计算批次间的线程内存堆积，我们也需要看看CPU的变化情况以及是否存在风险。
优化之前的CPU占用率不平稳，尖峰会超过70%

解决线程池线程泄漏问题后，CPU的使用率也稳定在70%左右浮动

由此可见这个OOM的问题终于被彻底定位并且完美解决了！😃