一个困扰多日的python django uwsgi内存泄露排查

原始贴:

https://www.v2ex.com/t/543252

背景:

参考原始贴。简单就是一个随着业务量增长内存溢出逐渐明显的程序问题。技术栈: uwsgi + mysql + redis + python3

心历路程:

实际上并不顺利，当你尝试使用方法却没找到时，会各种对自己思想猜疑甚至对官方文档的猜疑，最后找到问题后当然发现实际上很简单。 然后找到结果后对结果的逐步反推解决，才最终确定各种疑问。
文章省去了大量杂碎排查步骤，其实排查过程中，python许多的内存排查工具都尝试过，看了很多文章，例如: tracemalloc,objgraph, gc，guppy等
pylane, pyraite 原理利用反向cmd，但是在py3不是太友好，有空当然可以阅读下源码改造成py3可以使用的.

正文:

准备前置条件:

1. 升级到py3, 使用强大工具tracemalloc排查

相关代码:

"""
放在uwsgi其中一个views.py就行，可以在运行中查看
"""
last_snapshot=None
start_snapshot=None

import gc
import tracemalloc 

@login_required
def begin_show(request):

    """
    刚启动程序时执行，记录下创世内存快照
    """

    tracemalloc.start()

    global last_snapshot
    global start_snapshot
    last_snapshot=None

    start_snapshot=tracemalloc.take_snapshot()
    return HttpResponse("ok", content_type="application/json")
    
@login_required
def show(request):
	"""
	用当前快照分别跟上次快照，创世快照对比，找出没释放的内存差值
	"""
    dump_string = ""
    try:
        gc.collect() # 在快照之前手动回收，确保差值
        snapshot = tracemalloc.take_snapshot()
        top_stats = snapshot.statistics('lineno')

        for stat in top_stats[:50]:
            dump_string += "%s\n" % stat

        global last_snapshot
        global start_snapshot
        if last_snapshot:

            dump_string += "\ncompare to last:\n" 
            top_stats = snapshot.compare_to(last_snapshot, 'lineno')
            for stat in top_stats[:50]:
                dump_string += "%s\n" % stat

        if start_snapshot:

            dump_string += "\ncompare to start:\n" 
            top_stats = snapshot.compare_to(start_snapshot, 'lineno')
            for stat in top_stats[:50]:
                dump_string += "%s\n" % stat

        last_snapshot=snapshot


    except Exception as e:
        dump_string += "%s\n" % str(e)


    return HttpResponse(dump_string, content_type="application/json")

调用代码:

1.启动后，调用begin_show方法记录创世内存。
2.压测
3.调用show
4.压测
5.调用show
....
多次对比，查看到固定嫌疑犯，如下截图

看懂工具提示:(重点之中的重点)
(这个图其实我很早得到了，但是正因为没真正理解，加上其他事情优先级更高，一直搁置处理.)
信息:

1. 对比上次内存快照，多出来最多的内存是业务代码行在149的内存
   

疑问:

1. 使用标准模块logging 打印字符串日志而已，为何没有释放？难道是内置模块logging泄露了? (此问题让我百思不得其解)

信息中关键结论:

1. 实际上tracemalloc指明，该处分配的内存，并没有被释放，该处分配的内存唯有参数. (一开始我错以为dump_string没有被释放(dump_string是占主要空间的日志字符串，response body)，使用sys.getrefcount等工具后发现正常释放。实际上这里没有正常释放的，是dump_string,request.method等形成的格式化字符串!! )

追查:

1. 能得到上一步，思路已经很清晰了。接下来，需要获得logger::info的实现逻辑，则需要看logging源码.(其实我当时没有这么做，我直接猜到了结果，然后再从结果反推应该的正常思路)

2. logging代码总结: 遍历loggerHandler下以及其所有parent的handler，对其关键实现函数emit调用.

3. 查看所有涉及handlers:

    wechatinfo_logger = logging.getLogger("default")
    dump_string+="%s\n" % (wechatinfo_logger.handlers)

    dump_string+="%s" % (wechatinfo_logger.parent.handlers)

4. 发现可疑handlers: debug_toolbar.panels.logging.ThreadTrackingHandler 根据此路径可知，是debug_toolbar包下面定义的handler,查看该逻辑不难发现内存泄露原因.泄漏原因是全局变量列表随着每次请求不断添加日志打印字符串而无释放。同时去对应github项目搜索memory leak,的确有提及相关问题
5. 修复:: 去掉debug_toolbar相关组件后再无内存泄露

解答贴中提问:

1. gc模块中garbage为什么当初无法定位问题:
   答: gc.garbage储存的是unreachable
   的对象，对于全局变量，还在引用，所以无法定位.通常存储循环引用对象。 然而经过尝试，假如你不调用gc.set_debug(gc.DEBUG_LEAK) ，即使有循环引用，garbage依旧为空( 一些参考资料说假如定义了__del__可能有不一样，但是这个方法一般不定义).
   所以，对于python内存泄露的排查大致只有: 1.手写c模块引入泄露 2.全局变量无释放

2. 一开始旨意找到一个通用跨语言的，系统级别的内存泄露方法，后面还是用了python特有排查方法，是为什么呢?:
   答: 的确一开始年轻，总想找到通用排查方法，例如抓包等通用法子。但是后面尝试使用系统级通用方法排查发现，即时你发现了泄露，但是却无法真正定位到代码行！！ 所以在无尽代码量面前是前功尽弃的，而放弃了这种根本上无法解决问题的办法。
   所以，任何排查泄露的办法假如不是到语言级，你就无法快速定位到代码行. 任何排查优先使用语言级