一次对pool的误用导致的.net频繁gc的诊断分析

(最近有读者朋友表示,希望能加一些示意图来描述分析过程中用到的原理知识。好的,之后我会注意,谢谢这位读者)

有位朋友找我,希望我能帮看一下他的一个service。从他的描述看,并没有资源方面的泄漏,程序目前也能正常工作。他是在用dotnet-counters moniter时发现gc2、也就是full gc触发的比较频繁,频率超过了他自己的预期,于是他心里不踏实,所以想找我看一下。.

一次对pool的误用导致的.net频繁gc的诊断分析

能在没发生资源或性能异常前自觉monitor .net metrics的人,我跟佩服,这是讲究人儿啊。那后面我就管这位朋友叫"精致大哥"了哈

其实对于这次没有明确内存泄漏迹象的问题,我没啥把握能给出明确问题点,甚至可能就是没问题。但,试试吧,拿出windbg准备。

既然是频繁full gc, 而且还都把内存降下来了,那么最先想到的是会不会在申请大量的大对象。

因为如果有很多小对象在申请内存,一般都会在gc0和gc1阶段搞定,而无需总劳烦gc2;或者申请很多小对象,而且还一直引用着,这样也能造成gc2,但那样的话内存应该也会泄漏才对。

带着这个猜想,先看一下大对象堆LOH的大小:

一次对pool的误用导致的.net频繁gc的诊断分析

可以看到很多gc heap的LOH都被申请了4194384 byte大小。

然后去看看heap4里的LOH存的都是些什么。根据heap4的LOH segment的起始位置和allocation end 位置,用!dumpheap:

一次对pool的误用导致的.net频繁gc的诊断分析

可以看出这里面只有一个byte array, 而且大小也是约4M。

尝试用!gcroot看一下这个大对象的引用关系:

一次对pool的误用导致的.net频繁gc的诊断分析

这回gcroot无法给出想要的答案。这是因为引用它的引用链的head没有了引用根,画个示意图:

一次对pool的误用导致的.net频繁gc的诊断分析

(这样一来,下次同代gc触发时,这个大对象的内存也就真的被释放了)

引用链找不到,线索断了。别急,既然sos不能帮助我们了,可以试试耐下心手动找引用链。我们知道一个对象的地址的值通常会存在某个对象所占用内存的"身上",如图所示:

一次对pool的误用导致的.net频繁gc的诊断分析

那么就可以先从当前gc heap的起始位置找一下这个大对象的地址值所在的内存位置。考虑到当前进程是小端模式,所以用如下命令:

0:000> s -b 0000021000000000 L?2000000000 38 10 95 32 1e 0200000218`f29c9b38  38 10 95 32 1e 02 00 00-00 00 00 00 00 00 00 00

在内存位置218`f29c9b38找到了对象的地址值,接着找一下“包含”这个位置的对象:

Before:  00000218f29c9b28         4024 (0xfb8)  System.Byte[][]After:   00000218f29caae0           72 (0x48)  System.Threading.Tasks.Task+DelayPromise

看来我们已经到了一个System.Byte[][]对象的位置了。按上面的思路继续搜寻218f29c9b28这个值:

0:000> s -b 0000021000000000 L?2000000000 28 9b 9c f2 18 0200000218`f29c9ae8  28 9b 9c f2 18 02 00 00-00 00 40 00 db 52 a1 03  (.........@..R..

再找“包含”这个位置的对象:

Before:  00000218f29c9ae0           48 (0x30)  System.Buffers.ConfigurableArrayPool`1+Bucket[[System.Byte, System.Private.CoreLib]]After:   00000218f29c9b10           24 (0x18)  Free

以此类推,又经过一系列搜寻,最后找到了这个对象,它的地址值在这个进程空间中无法被找到了:

Before:  00000218f29b7af0           24 (0x18)  System.Buffers.ConfigurableArrayPool`1[[System.Byte, System.Private.CoreLib]]

于是认为已经找到了整个引用链的"临时"head。说它是"临时"的,是因为没有gc root引用着它。

有了这些数据,我们便可以用常规的sos指令进行一下正向的验证,从head

218f29b7af0 开始往下验证吧:

一次对pool的误用导致的.net频繁gc的诊断分析

可以看到它确实引用着218f29b7b08 _buckets,

一次对pool的误用导致的.net频繁gc的诊断分析

可以看到_buckets这个Bucket<byte>[]有19个元素,第18个元素确实就是上面推导的Bucket instance,继续看:

一次对pool的误用导致的.net频繁gc的诊断分析

可以看到这个bucket instance(00000218f29c9ae0)确实hold着218f29c9b28 这个byte[][],而这个byte[][]里也确实包含了我们最初要找的那个大对象byte[]:

一次对pool的误用导致的.net频繁gc的诊断分析

好了,现在可以画个逆向诊断的引用复原图:

一次对pool的误用导致的.net频繁gc的诊断分析

如果大家看过ArrayPool的一些基本实现,就知道这个ConfigurableArrayPool`1其实是ArrayPool.Create(config)创建出来的,所以我们调研的那个大对象byte[]其实是ArrayPool里维护的buffer。

又看了一下,进程中当时有18个这样大小的大byte[]:

一次对pool的误用导致的.net频繁gc的诊断分析

按上面类似的推导,随机看了其他几个byte[],其引用链的head都是不同的ConfigurableArrayPool`1 instances,所以对了一下ConfigurableArrayPool`1的数量,用!dumpheap:

一次对pool的误用导致的.net频繁gc的诊断分析

也是18个。所以说,貌似每个Pool只管理了1个byte[] ?? 这样就有问题了,因为这样的话相当于每个pool都不能reuse 已有的其他pool的buffers,pool没有起到pool的作用。所以每次需要用buffer时,只能不断申请新的大byte[],导致大对象数量增长。

把这个分析结果告诉了那位“精致大哥”后,“精致大哥”找到了创建pool的代码,简化后是这样的:

        private DigestSummary CalculateDigestSummary(NotificationEvent notificationEvent)        {            var bytesPool = ArrayPool<byte>.Create(4 * 1024 * 1024, 500);            byte[] buf = bytesPool.Rent(4 * 1024 * 1024);
            try            {                return CalculateWithBuffer(buf);            }            finally            {                bytesPool.Return(buf);            }        }

看第3行,每次需要byte[]时,都先创建一个pool,下次又重新用新pool。于是效果就是没有pool啦。

应该在使用buffer的scope中尽量reuse pool instance, 或者也可以用

var bytesPool = ArrayPool<byte>.Shared;

这次gc问题的诊断分析,需要脱离sos,手动找引用关系,从而获得了“这次大对象是ArrayPool挂着”这层信息,进而找出了ArrayPool instances与大byte[] instances一对一的不正常关系。