巧用traceback定位 Python 内存泄漏

背景

我们（指原作者）在工作中使用 DDAgent Ver. 5 作为采集工具进行被管服务器的性能指标采集与上报，并且对 DDAgent 做了一定程度的定制。在几次特性迭代后，发现线上一批运行许久的被管服务器出现内存占用过高。分析问题机器上进程树各节点占用情况，看到 DDAgent 采集进程的内存占用居高不下。

作为保障业务系统稳定作业的监控组件发生了内存泄漏，自然是非常严重的，所以开始我们的“排查之旅”。

分析

有许多工具提供了对 Python 程序内存状态的分析与导出，这里我们使用 pyrasite，它可以 attach 到一个运行中的 Python 程序，生成一份内存快照，并查看当前有哪些对象类型分别占用了多少内存，从大到小排序。

使用命令非常简单：pyrasite-memory-viewer <PID>，同时会生成一份快照文件：/tmp/pyrasite-<PID>-objects.json 。

由于无法提供真实生产中的数据，下文提及的所有数据均来自于问题版本在测试环境中运行 12 小时之后的采样。

在 pyrasite 提供的 CUI 视图中，我们可以清晰地看到字典类型的对象实例占用内存最多，达到了 3.4MB，有 6621 个实例：

    Total 60350 objects, 223 types, Total size = 10.4MiB (10857450 bytes)
     Index   Count   %      Size   % Cum     Max Kind
(X)      0    6621  10   3551928  32  32   98584 dict
( )      1   21363  35   1817633  16  49    6342 str
( )      2     291   0    902640   8  57   12624 module
( )      3     918   1    829872   7  65     904 type
( )      4    5605   9    717440   6  72     128 code
( )      5    5969   9    716280   6  78     120 function
    More...

可惜 pyrasite 的 CUI 界面没有提供进一步数据透视的能力，以查看这么多字典对象到底是哪些，有什么特征。

但我们也看到，内存快照文件是 JSON 格式的可读文本，打开后为如下结构的内容：

{"address": 139671453162096, "type": "instance", "size": 72, "refs": [139671565716816, 139671453172632]}
{"address": 139671453172632, "type": "dict", "size": 1048, "len": 4, "refs": [139671677239136, 29053312, 139671565997664, 139671451015864, 139671677145776, 29056072, 139671677239040, 139671674819024]}
{"address": 139671674819024, "type": "bool", "size": 24, "value": "True", "refs": []}
{"address": 139671677239040, "type": "str", "size": 43, "len": 6, "value": "closed", "refs": []}
{"address": 29056072, "type": "int", "size": 24, "value": 134, "refs": []}
...

很容易猜出，每一行表示当前内存中的一个 Python 对象，address 为该对象的内存地址，type 为该对象的类型名，size 是该对象自身占据的内存大小（不出意外该值和 sys.getsizeof 计算所得一致），如果对象类型为 int、str、bool 这种 Primitive Type，则通过 value 表示其值，如果对象类型为 str、tuple、list、dict 等容器类型（按 Python 定义严谨地讲是实现了 __len__ 方法的类型），那么通过 len 表示其元素数量，最后一个 refs 则表示这个对象上所引用其他对象的地址。

在对该快照文件中的字典对象做简单分析后，得到了一个很重要的情报：6621 个字典对象中有 4884 个都是空字典 ，占比 73.8%。

不论什么业务场景，在一个正常的 Python 程序实现中，不可能有如此多的空字典。

想搞清为什么，就得找出在哪里创建了这些空字典对象。

但是到目前为止 pyrasite 提供的信息都已探索完，要进一步排查，就得“另辟蹊径”。

定位

我们针对发生泄漏的场景重新缕下思路，有如下事实和猜测：

• 一个或多个地方在持续创建空字典对象，并且无法回收它们，导致内存泄漏

• 内存泄漏量随着时间变化而增长，在指标采集业务中，很可能是在每次采集过程中造成的泄漏，在间隔周期后又重复触发

• 并未看到当前依赖的 DDAgent 版本有未关闭的相关 Issue，很可能是我们定制过程中引入的 Bug

但是，哪怕一次最简单的系统基础指标采集，程序所跑过的代码行数（DDAgent 框架代码、采集 Check 插件代码）都在千级规模，想靠人力去分析定位“泄漏点”，如同大海捞针。

同时我们还面临一个挑战：由于泄漏过程较慢，很难在本地测试环境进行快速复现和分析。

如何克服上述困难？结合造成泄漏对象很重要的画像——无法回收的空字典，我们或许可以借助 Python 解释器的运行时修改与自省特性来排查。

即，我们写一段追踪代码，捕捉符合以下特征的对象：

• 特征 1：字典（dict）类型

• 特征 2：字典对象长度为 0

• 特征 3：该对象的引用计数始终大于 0

对应的解决方案是：

• 响应特征 1：构造一个字典类型，其：

• • 我们使用的解释器版本为 CPython 2.7.13，所以是 __builtin__ 而不是 3.x 的 builtins

  • 该方案存在一些问题，但在我们这个场景中恰好够用了，后面复盘时再提

  • 在初始化函数 __init__ 中记录自己被实例化时的堆栈信息，通过 traceback 模块完成，这是实现追踪的关键

  • 并通过 __builtin__ 模块进行运行时替换，将内置的 dict 换成该自定义类型，实现全局追踪

• 响应特征 2：这个最简单，需要时 len(dict_obj) == 0 搞定

• 响应特征 3：使用 weakref.WeakSet 实现追踪表收集字典对象，通过“弱引用”特性避免追踪代码影响正常对象的回收

接着，只要定时将追踪表中符合特征的内容进行输出，就可以达到定位创建未回收空字典对象位置的目标：

# coding: utf-8
import __builtin__
import time
import json
import weakref
import traceback
import threading

# “弱引用”特性的追踪表确保不干扰正常对象的回收
trace_table = weakref.WeakSet()


# 定时输出符合特征的内容
def exporter():
    while True:
        time.sleep(30)
        print('writing trace infos...')
        # 将追踪表中的空字典收集输出
        empty_dicts = [d.trace_info for d in trace_table if len(d) == 0]
        with open('traceinfo', 'w') as f:
            f.write(json.dumps(empty_dicts))


threading.Thread(target=exporter).start()


class TraceableDict(dict):
    idx = 0

    def __init__(self, *args, **kwargs):
        super(TraceableDict, self).__init__(*args, **kwargs)
        # !!!获取堆栈信息!!!
        self.trace_info = traceback.extract_stack()
        self.trace_hash = TraceableDict.idx
        TraceableDict.idx += 1
        # 将自己加入到追踪表
        trace_table.add(self)

    def __hash__(self):
        # 如果不实现 __hash__ 方法，则无法被插入到 WeakSet 中
        return self.trace_hash


# !!!这只是为了定位问题!!!
# !!!平时千万不要这么用!!!
__builtin__.dict = TraceableDict

print('start tracing...')

这里需要额外提及一下，由于 dict 字典对象没有实现 __hash__ 方法，因此它无法作为 Key 被插入到 dict、set、WeakSet 对象中，一句话测试下便知：

> python -c "{}[{}]=0"
Traceback (most recent call last):
  File "<string>", line 1, in <module>
TypeError: unhashable type: 'dict'

为了使其能被顺利插入到 WeakSet 中，这里使用自增 Id 方案做最简单的 Hash 实现。

接着我们在 DDAgent 的采集模块 collect.py 入口处启用这段追踪代码：

# coding: utf-8
# file: collect.py
import tracer  # 导入即启用
import signal
# ...

将采集进程运行一段时间后，我们得到了 traceinfo 文件：

[
  [
    [".../embedded/lib/python2.7/threading.py",774,"__bootstrap","self.__bootstrap_inner()"],
    [".../embedded/lib/python2.7/threading.py",801,"__bootstrap_inner","self.run()"],
    [".../modules/monitor/bot/schedule.py",51,"run","task.run()"],
    [".../modules/monitor/bot/task.py",50,"run","super(RepeatTask, self).run()"],
    [".../modules/monitor/bot/task.py",18,"run","self.check()"],
    [".../modules/monitor/checks/collector.py",223,"wrapper","_check.run()"],
    [".../modules/monitor/checks/__init__.py",630,"run","self._roll_up_instance_metadata()"],
    [".../modules/monitor/checks/__init__.py",498,"_roll_up_instance_metadata","dict((k, v) for (k, v) in self._instance_metadata))"],
    [".../modules/monitor/tracer.py",33,"__init__","self.trace_info = traceback.extract_stack()"]
  ],
  [
    [".../embedded/lib/python2.7/threading.py",774,"__bootstrap","self.__bootstrap_inner()"],
    [".../embedded/lib/python2.7/threading.py",801,"__bootstrap_inner","self.run()"],
    [".../modules/monitor/bot/schedule.py",51,"run","task.run()"],
    [".../modules/monitor/bot/task.py",50,"run","super(RepeatTask, self).run()"],
    [".../modules/monitor/bot/task.py",18,"run","self.check()"],
    [".../modules/monitor/checks/collector.py",223,"wrapper","_check.run()"],
    [".../modules/monitor/checks/__init__.py",630,"run","self._roll_up_instance_metadata()"],
    [".../modules/monitor/checks/__init__.py",498,"_roll_up_instance_metadata","dict((k, v) for (k, v) in self._instance_metadata))"],
    [".../modules/monitor/tracer.py",33,"__init__","self.trace_info = traceback.extract_stack()"]
  ],
  [
    [".../embedded/lib/python2.7/threading.py",774,"__bootstrap","self.__bootstrap_inner()"],
    [".../embedded/lib/python2.7/threading.py",801,"__bootstrap_inner","self.run()"],
    [".../modules/monitor/bot/schedule.py",51,"run","task.run()"],
    [".../modules/monitor/bot/task.py",50,"run","super(RepeatTask, self).run()"],
    [".../modules/monitor/bot/task.py",18,"run","self.check()"],
    [".../modules/monitor/checks/collector.py",223,"wrapper","_check.run()"],
    [".../modules/monitor/checks/__init__.py",630,"run","self._roll_up_instance_metadata()"],
    [".../modules/monitor/checks/__init__.py",498,"_roll_up_instance_metadata","dict((k, v) for (k, v) in self._instance_metadata))"],
    [".../modules/monitor/tracer.py",33,"__init__","self.trace_info = traceback.extract_stack()"]
  ],
...

不用花太多精力，就可以识别到几乎所有的空字典对象都创建自 .../modules/monitor/checks/__init__.py 文件的第 498 行，在一个名为 _roll_up_instance_metadata 的方法中：

class AgentCheck(object):
    # ...
    def _roll_up_instance_metadata(self):
        self.svc_metadata.append(
            dict((k, v) for (k, v) in self._instance_metadata))
        self._instance_metadata = []

该方法在每个采集过程中都会被调用一次，每次调用将某些元数据插入到 svc_metadata 这个对象成员列表中。

既然有生产肯定有消费，我们紧接着该方法就找到重置 svc_metadata 列表的代码：

class AgentCheck(object):
    # ...
    def _roll_up_instance_metadata(self):
        # ...
    def get_service_metadata(self):
        if self._instance_metadata:
            self._roll_up_instance_metadata()  # 注意：这里并不是唯一调用 _roll_up_instance_metadata 的位置
        service_metadata = self.svc_metadata
        self.svc_metadata = []  # 重置
        return service_metadata

如果 get_service_metadata 方法能在每次采集过程末被成功调用，那至少 svc_metadata 不会产生数据堆积。

但是在检查当前版本的整体实现后，我们并没找到任何一处触发 get_service_metadata 的地方。

随后，通过对比 DDAgent 官方实现，并审查 Git 提交历史，终于一切真相大白。

DDAgent 在 checks/collector.py 的第 416 行 调用了 get_service_metadata，对元数据进行了消费：

class Collector(object):
    # ...
    @log_exceptions(log)
    def run(self, checksd=None, start_event=True, configs_reloaded=False):
        # ...
        # Collect metadata
        current_check_metadata = check.get_service_metadata()  # L416
        # ...

然而我们在某次特性迭代中，为了让 run 方法看上去更整洁，将一些与需求实现无关的代码全部移除了，包括对 get_service_metadata 的调用！

移除消费代码，但生产代码继续在工作，这就是导致内存泄漏的原因！

复盘

这里就不提诸如“做好设计评审与 Code Review”、“加强测试阶段质量检测工作”等“套话”，当然这些也值得我们反思。

内存泄漏问题几乎不可能彻底预防与治理，像 Rust 这样的安全编程语言也 无法作出承诺保证程序不会发生内存泄漏。

许多触发内存不安全的行为：数组访问越界、访问释放后的内存等，都可以通过制定更严格的编程模型（如 Rust 提出的所有权+生命周期规则）来规避——甚至可以规避数据竞争（data-race）的问题。

然而触发内存泄漏的行为，和竞态条件（race-condition）一样，则需要开发人员自己结合开发组件和业务规则进行约束。试想一个需要手动触发 flush 的数据队列，结果我们在不停推送数据的同时却忘了调用它，这种引发的内存泄漏是无法靠任何通用检查规则来甄别的。

敬畏编码。

最后聊下我们的“排查之旅”其实非常幸运，因为触发泄漏的关键代码：

class AgentCheck(object):
    # ...
    def _roll_up_instance_metadata(self):
        self.svc_metadata.append(
            dict((k, v) for (k, v) in self._instance_metadata))
        self._instance_metadata = []

恰好使用 dict 类型构造函数实例化了一个空字典！

如果直接使用字面量方式创建，如：self.svc_metadata.append({})，则是无法被追踪到的 —— __builtin__ 模块只能替换内置类型构造函数的入口，无法控制字面量。

假想通过字面量构建空字典的内存泄漏场景，我们又该如何排查？这里提供两个思路，仅作记录：

• 修改 CPython 源码中 dict 内置类型的实现，根据前面的追踪方案给每个 dict 对象加上实例化时的堆栈信息

• 后面了解到，CPython 3.4 新增了一个 tracemalloc 模块，虽然还未实践过，但从其官方介绍来看也适用我们这次的场景

• • Compute the differences between two snapshots to detect memory leaks

  • Statistics on allocated memory blocks per filename and per line number: total size, number and average size of allocated memory blocks

  • Traceback where an object was allocated

  • 该模块能提供一个对象被创建时的堆栈信息

  • 逐文件、逐行统计已分配的内存块信息：总大小、数量、平均大小

  • 可以计算两次内存快照间的差异，甄别内存泄漏