点击上方“Python编程时光”,选择“加为星标”
第一时间关注Python技术干货!
0. 背景
我们在工作中使用 DDAgent Ver. 5 作为采集工具进行被管服务器的性能指标采集与上报,并且对 DDAgent 做了一定程度的定制。在几次特性迭代后,发现线上一批运行许久的被管服务器出现内存占用过高。分析问题机器上进程树各节点占用情况,看到 DDAgent 采集进程的内存占用居高不下。
作为保障业务系统稳定作业的监控组件发生了内存泄漏,自然是非常严重的,所以开始我们的“排查之旅”。
1. 分析
有许多工具提供了对 Python 程序内存状态的分析与导出,这里我们使用 pyrasite,它可以 attach 到一个运行中的 Python 程序,生成一份内存快照,并查看当前有哪些对象类型分别占用了多少内存,从大到小排序。
使用命令非常简单:pyrasite-memory-viewer
,同时会生成一份快照文件:/tmp/pyrasite--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 提供的信息都已探索完,要进一步排查,就得“另辟蹊径”。
2. 定位
我们针对发生泄漏的场景重新缕下思路,有如下事实和猜测:
一个或多个地方在持续创建空字典对象,并且无法回收它们,导致内存泄漏
内存泄漏量随着时间变化而增长,在指标采集业务中,很可能是在每次采集过程中造成的泄漏,在间隔周期后又重复触发
并未看到当前依赖的 DDAgent 版本有未关闭的相关 Issue,很可能是我们定制过程中引入的 Bug
但是,哪怕一次最简单的系统基础指标采集,程序所跑过的代码行数(DDAgent 框架代码、采集 Check 插件代码)都在千级规模,想靠人力去分析定位“泄漏点”,如同大海捞针。
同时我们还面临一个挑战:由于泄漏过程较慢,很难在本地测试环境进行快速复现和分析。
如何克服上述困难?结合造成泄漏对象很重要的画像——无法回收的空字典,我们或许可以借助 Python 解释器的运行时修改与自省特性来排查。
即,我们写一段追踪代码,捕捉符合以下特征的对象:
特征 1:字典(dict)类型
特征 2:字典对象长度为 0
特征 3:该对象的引用计数始终大于 0
对应的解决方案是:
响应特征 1:构造一个字典类型,其:
在初始化函数
__init__
中记录自己被实例化时的堆栈信息,通过traceback
模块完成,这是实现追踪的关键并通过
__builtin__
模块进行运行时替换,将内置的dict
换成该自定义类型,实现全局追踪我们使用的解释器版本为 CPython 2.7.13,所以是 __builtin__ 而不是 3.x 的 `builtins`
该方案存在一些问题,但在我们这个场景中恰好够用了,后面复盘时再提
响应特征 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():
whileTrue:
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 "", 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
的调用!
移除消费代码,但生产代码继续在工作,这就是导致内存泄漏的原因!
3. 复盘
这里就不提诸如“做好设计评审与 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 模块,虽然还未实践过,但从其官方介绍来看也适用我们这次的场景
该模块能提供一个对象被创建时的堆栈信息
Traceback where an object was allocated
逐文件、逐行统计已分配的内存块信息:总大小、数量、平均大小
Statistics on allocated memory blocks per filename and per line number: total size, number and average size of allocated memory blocks
可以计算两次内存快照间的差异,甄别内存泄漏
Compute the differences between two snapshots to detect memory leaks
推荐阅读
太强了!Python中完美的日志解决方案
如何使用 Python 操作 Git 代码?
情人节来了,教你个用 Python 表白的技巧
11 个最佳的 Python 编译器和解释器
用它5分钟以后,我放弃用了四年的 Flask
整理了 34 个被吹爆了的Python开源框架