[apache/dubbo]超大cache文件DubboSaveRegistryCache-thread-1线程多次加载致使内存溢出

2024-07-31 577 views
9

在dubbo的服务注册缓存文件cache目录下的文件已经达到了900M System.getProperty ("user.home") + "/.dubbo/dubbo-registry-" + url.getHost () + ".cache" 对比其他正常服务器,正常文件大小只有1-2M,打开这个900M的文件其中很多内容为 \u0000, 由于dubbo默认每隔10分钟会读取这个文件,由于文件太大,导致每次读取造成频繁的GC最终致使JVM在这个时间段内CPU负载非常高而无法处理业务请求。 通过DUMP内存,发现内存泄露都是线程 java.lang.Thread @ 0x779569808 DubboSaveRegistryCache-thread-1 其中同样类似的线程还有2个,每个线程占用200-300M 另外还有大对象 com.alibaba.dubbo.registry.zookeeper.ZookeeperRegistry 3个无法回收,200M左右一个 总计1.5G大小内存无法释放!

为何会有如此大的缓存文件?为何同样的文件会被不同的线程多次加载?

回答

3

这样的问题出现的概率非常低,但是一旦出现比较致命

7

你们集群和服务数量的规模是多少,你上面的cache文件远高于你们实际的服务规模吗?你的注册中心文件样本能提供一部分吗?dump的堆栈也提供一下。谢谢

4

泄露堆栈为

DubboSaveRegistryCache-thread-1 at java.util.Properties.loadConvert([CII[C)Ljava/lang/String; (Properties.java:573) at java.util.Properties.load0(Ljava/util/Properties$LineReader;)V (Properties.java:390) at java.util.Properties.load(Ljava/io/InputStream;)V (Properties.java:341) at com.alibaba.dubbo.registry.support.AbstractRegistry.doSaveProperties(J)V (AbstractRegistry.java:192) at com.alibaba.dubbo.registry.support.AbstractRegistry$SaveProperties.run()V (AbstractRegistry.java:170) at java.util.concurrent.Executors$RunnableAdapter.call()Ljava/lang/Object; (Executors.java:471) at java.util.concurrent.FutureTask.run()V (FutureTask.java:262) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(Ljava/util/concurrent/ScheduledThreadPoolExecutor$ScheduledFutureTask;)V (ScheduledThreadPoolExecutor.java:178) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run()V (ScheduledThreadPoolExecutor.java:292) at java.util.concurrent.ThreadPoolExecutor.runWorker(Ljava/util/concurrent/ThreadPoolExecutor$Worker;)V (ThreadPoolExecutor.java:1145) at java.util.concurrent.ThreadPoolExecutor$Worker.run()V (ThreadPoolExecutor.java:615) at java.lang.Thread.run()V (Thread.java:745)

4

泄露的具体对象为,注意着只是泄露的java.lang.Thread @ 0x779569808 DubboSaveRegistryCache-thread-1 关联的一部分对象,大概200多M 类似的泄露对象还有好几个

Name Shallow Heap Retained Heap
java.util.Hashtable$Entry @ 0x79b5bdb00 32 8,952,288
next java.util.Hashtable$Entry @ 0x79b5bdaa0 32 12,456,600
next java.util.Hashtable$Entry @ 0x79b5bda40 32 14,387,672
next java.util.Hashtable$Entry @ 0x79b5bd9e0 32 17,904,944
next java.util.Hashtable$Entry @ 0x79b5bd980 32 19,835,656
next java.util.Hashtable$Entry @ 0x799b5a2d0 32 19,841,216
next java.util.Hashtable$Entry @ 0x799b5a270 32 23,358,128
next java.util.Hashtable$Entry @ 0x799b5a210 32 26,855,192
next java.util.Hashtable$Entry @ 0x799b5a1b0 32 30,322,352
next java.util.Hashtable$Entry @ 0x799b5a150 32 33,844,200
next java.util.Hashtable$Entry @ 0x799b593b8 32 33,847,680
next java.util.Hashtable$Entry @ 0x799b57ee8 32 33,853,008
next java.util.Hashtable$Entry @ 0x799b57138 32 33,856,512
next java.util.Hashtable$Entry @ 0x799b570d8 32 37,354,912
next java.util.Hashtable$Entry @ 0x799b57078 32 39,983,992
next java.util.Hashtable$Entry @ 0x799b560f8 32 39,987,960
next java.util.Hashtable$Entry @ 0x799b56098 32 43,538,496
next java.util.Hashtable$Entry @ 0x799b56038 32 47,073,912
next java.util.Hashtable$Entry @ 0x7a76b1cf8 32 50,599,704
next java.util.Hashtable$Entry @ 0x7a6586840 32 54,120,360
next java.util.Hashtable$Entry @ 0x7a65867e0 32 57,654,168
next java.util.Hashtable$Entry @ 0x7a6586780 32 57,659,456
next java.util.Hashtable$Entry @ 0x7a65863a0 32 57,660,448
next java.util.Hashtable$Entry @ 0x7a46d51a0 32 57,664,120
next java.util.Hashtable$Entry @ 0x7a46d5140 32 61,161,792
next java.util.Hashtable$Entry @ 0x7a46d42d8 32 61,165,480
next java.util.Hashtable$Entry @ 0x7a46d4278 32 64,715,576
next java.util.Hashtable$Entry @ 0x7a9efc818 32 65,147,408
next java.util.Hashtable$Entry @ 0x7a9efb810 32 65,151,512
next java.util.Hashtable$Entry @ 0x7a9efb7b0 32 68,650,408
next java.util.Hashtable$Entry @ 0x7a7a0ff78 32 68,653,376
next java.util.Hashtable$Entry @ 0x7a7a0ff18 32 72,150,072
next java.util.Hashtable$Entry @ 0x7a7a0feb8 32 75,691,288
next java.util.Hashtable$Entry @ 0x7a7a0fe58 32 79,216,680
next java.util.Hashtable$Entry @ 0x7a7a0fdf8 32 79,221,120
next java.util.Hashtable$Entry @ 0x7aa68a2d8 32 82,747,776
next java.util.Hashtable$Entry @ 0x7aa68a278 32 86,239,536
next java.util.Hashtable$Entry @ 0x7aa6893e8 32 86,243,264
next java.util.Hashtable$Entry @ 0x7aa689388 32 89,734,184
next java.util.Hashtable$Entry @ 0x7aa689328 32 93,243,496
next java.util.Hashtable$Entry @ 0x7aa6892c8 32 96,773,024
next java.util.Hashtable$Entry @ 0x7aa688630 32 96,776,248
next java.util.Hashtable$Entry @ 0x7ae997518 32 100,285,040
next java.util.Hashtable$Entry @ 0x7ae9974b8 32 102,911,232
next java.util.Hashtable$Entry @ 0x7ae997458 32 106,422,344
next java.util.Hashtable$Entry @ 0x7ae9961b0 32 106,427,120
next java.util.Hashtable$Entry @ 0x7ae996150 32 109,966,296
next java.util.Hashtable$Entry @ 0x7ad8dbdc8 32 109,969,416
next java.util.Hashtable$Entry @ 0x7ad8dbd68 32 109,974,720
next java.util.Hashtable$Entry @ 0x7ad8dbd08 32 113,450,400
next java.util.Hashtable$Entry @ 0x7ad8dbbe0 32 113,450,696
next java.util.Hashtable$Entry @ 0x7ad8db420 32 113,452,680
next java.util.Hashtable$Entry @ 0x7ad8da788 32 113,455,904
next java.util.Hashtable$Entry @ 0x7b08a3528 32 116,975,688
next java.util.Hashtable$Entry @ 0x7b08a34c8 32 116,981,144
next java.util.Hashtable$Entry @ 0x7b08a3468 32 120,519,968
next java.util.Hashtable$Entry @ 0x7b08a2080 32 120,525,064
next java.util.Hashtable$Entry @ 0x7b1cfb358 32 124,057,672
next java.util.Hashtable$Entry @ 0x7b1cf05c8 32 127,513,424
next java.util.Hashtable$Entry @ 0x7b1cf04a8 32 131,006,392
next java.util.Hashtable$Entry @ 0x7b1cef378 32 131,010,792
next java.util.Hashtable$Entry @ 0x7b1ceefb8 32 131,011,752
next java.util.Hashtable$Entry @ 0x7b3450df0 32 134,533,264
next java.util.Hashtable$Entry @ 0x7b3450d90 32 134,537,488
next java.util.Hashtable$Entry @ 0x7b344f7e8 32 138,061,032
next java.util.Hashtable$Entry @ 0x7b344f788 32 138,065,520
next java.util.Hashtable$Entry @ 0x7b4f44d10 32 141,582,528
next java.util.Hashtable$Entry @ 0x7b4f44cb0 32 143,515,000
next java.util.Hashtable$Entry @ 0x7b4f44c50 32 147,053,808
next java.util.Hashtable$Entry @ 0x7b4f44bf0 32 147,058,480
next java.util.Hashtable$Entry @ 0x7b6987d48 32 150,564,184
next java.util.Hashtable$Entry @ 0x7b6987ce8 32 150,569,720
next java.util.Hashtable$Entry @ 0x7b6987c88 32 154,091,496
next java.util.Hashtable$Entry @ 0x7b8156f70 32 157,607,128
next java.util.Hashtable$Entry @ 0x7b8156f10 32 161,142,400
next java.util.Hashtable$Entry @ 0x7b8156eb0 32 164,670,552
next java.util.Hashtable$Entry @ 0x7b8156e50 32 168,188,416
next java.util.Hashtable$Entry @ 0x7b8156df0 32 171,725,336
next java.util.Hashtable$Entry @ 0x7b8156290 32 171,728,248
next java.util.Hashtable$Entry @ 0x7bb4671d8 32 175,215,360
next java.util.Hashtable$Entry @ 0x7bb467178 32 178,720,264
next java.util.Hashtable$Entry @ 0x7bb467118 32 182,251,064
next java.util.Hashtable$Entry @ 0x7bb4670b8 32 185,761,736
next java.util.Hashtable$Entry @ 0x7bb467058 32 189,292,776
next java.util.Hashtable$Entry @ 0x7bb466ff8 32 192,806,160
next java.util.Hashtable$Entry @ 0x7bb466f98 32 196,269,632
next java.util.Hashtable$Entry @ 0x7bb466f38 32 199,785,912
next java.util.Hashtable$Entry @ 0x7bb466ed8 32 203,325,168
next java.util.Hashtable$Entry @ 0x7bb466e78 32 206,868,856
next java.util.Hashtable$Entry @ 0x7bb466e18 32 210,390,880
next java.util.Hashtable$Entry @ 0x7bb466db8 32 213,891,800
next java.util.Hashtable$Entry @ 0x7bb466d58 32 217,388,296
next java.util.Hashtable$Entry @ 0x7bb466cf8 32 220,897,392
next java.util.Hashtable$Entry @ 0x7bb465778 32 220,902,896
next java.util.Hashtable$Entry @ 0x7bb465718 32 224,411,968
next java.util.Hashtable$Entry @ 0x7bb4656b8 32 227,899,904
next java.util.Hashtable$Entry @ 0x7bb465658 32 231,415,336
next java.util.Hashtable$Entry @ 0x7bb4655f8 32 234,929,256
next java.util.Hashtable$Entry @ 0x7bb465598 32 238,450,376
next java.util.Hashtable$Entry @ 0x7bb465538 32 241,948,920
next java.util.Hashtable$Entry @ 0x7bb4654d8 32 245,473,336
9

我们也遇到这个问题了,分析dump出来的内存,是ZookeeperRegistry对象的properties属性过大(每个对象两百兆左右,一共14个对象达到了近3个g),key中全部或者部分包含非常多的\u0000字符,查看本地的cache文件,也是很多\u0000,与内存的情况一致,偶发性的,请问是什么原因啊?

3

@zhangzacks @maodie007 按理说,ZookeeperRegistry 只会有一个。。。你们是有多个注册中心么?

3

@qinliujie 只有一个注册中心

9

@qinliujie 另外补充一点,我们的系统是存在Jboss热部署的,实际上dubbo在Jboss的热部署的时候也存在问题,比如一些线程池或者静态引用在Jboss热部署的时候并不能正常释放,导致部署的包无法正常卸载。这个问题不一定和这个Issue有关系,但是我还是尽可能的将环境描述清楚,谢谢你们对问题的关注!

7

大致了解了 @maodie007 你那里能提供一下出错时文件的部分内容么。。我现在觉得比较奇怪,这个不应该引入 \u0000 才对啊

5

你们有通过ops向zk中写配置信息吗?有没有可能\u0000是从外部引入的

3

为什么会有那么多ZookeeperRegistry对象,会不会和热部署有关系。能不能在服务正常启动后,多次热部署后分别dump一份数据,确定下ZookeeperRegistry对象数量?

0

这种BUG出现的概率很低,而我们的热部署非常频繁,所以直接将热部署和这个任务相关可能性不大,我们之前也DUMP过在没有出现故障的时候是不会有这个BUG的

没有反写zk配置信息的行为。

8

@qinliujie zk集群只有一个,但是不同系统的服务在zk上的分组不一样,所以跨系统调用的时候配置了多个dubbo:registry

1

@maodie007

  1. 同一个工程中配置了多个dubbo:registry?具体是几个那?
  2. 既然是同一个zk集群,分组不同没必要配置多个dubbo:registry吧
  3. 出问题的cache文件,涉及的服务分组个数有多少?
7

@chickenlj 1.dubbo:registry的配置个数是和ZookeeperRegistry对象个数一致的,14个. 2.这个分组不同,是指的dubbo:registry的group属性值不同,配置一个dubbo:registry不能实现跨组调用吧. 3.我这里出问题的系统,会调用另外13个系统的服务,所以分组共有14个. 另外每个dubbo:registry没有单独指定cache文件,是共用的,不知道和这个有没有关系,我看官网上说两个注册中心不能使用同一个文件存储,我这个情况不知道算不算是多个注册中心,然后看源码里又有防止多个注册中心冲突的措施,很迷惑.主要是我们一直这么用的,以前也没出过问题.

0

dubbo:registry的group是什么意思?只有服务有group的概念,不过分group并不需要配置14个dubbo:registry,占用过多的内存

2

@chickenlj 我好像明白你的意思了,你说的服务分组是指dubbo:service的group属性是吧?好吧,是我描述不清楚,我们是通过指定dubbo:registry的group属性值来分组的,这应该是叫注册中心分组更准确吧,意思是一个系统一个zk分组,然后需要实现不同zk分组下的服务互相调用.不过这并不是问题I的根源,单就一个ZookeeperRegistry对象来看就达到了200M,显然这是有问题的.

5

使用tomcat热部署,也是同样出现这个问题

SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-2] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [New I/O server worker #1-2] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-3] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [New I/O server worker #1-3] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-4] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboSharedHandler-thread-1] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-5] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-6] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-7] but has failed to stop it. This is very likely to create a memory leak. Oct 19, 2017 1:26:35 PM org.apache.catalina.loader.WebappClassLoader clearReferencesThreads SEVERE: The web application [/zd-model-platform] appears to have started a thread named [DubboServerHandler-139.199.175.58:31250-thread-8] but has failed to stop it. This is very likely to create a memory leak.

3

@JavaxinYao 看你这个日志是今天的,我建议你将其他的一些信息可以更多的发在这里,比如现在有问题的cache文件内容 请 @chickenlj 关注下

5

我觉得可能是tomcat reload 类重新加载内存不释放 就比较容易导致内存溢出

3

@JavaxinYao 热部署是会存在问题,我在之前的回复上说到过,但是你的OOM不一定和这个ISSUE是一致的,你需要DUMP才能知晓,我前面说过dubbo本来就存在在热部署的情况下无法正常关闭一些资源,导致多次部署将会致使内存溢出的可能,这一块我们自己对dubbo也进行过调整

7

cache文件和ZookeeperRegistry对象过大的问题有头绪吗?我们这里很长时间没出现过了,这个问题隐藏的有点深.

1

这个问题我也遇到过,可能不是因为服务数量过多导致的。dubbo启动后会默认把zookeeper上的服务URL信息按ZK的IP地址为标识分多个文件缓存到本地的${user.home}目录下,如果当前服务器节点上部署有多个dubbo 应用,当ZK上有服务变更信息时会推给所有的消费者服务,如果有多个消费这个服务的应用都部署在这个一个节点上,会导致ZK缓存文件特别大。建议通过 dubbo.registry.file 配置给每个应用指定一个ZK缓存目录

1

@663534597 非常感谢你的分享,你的这个说法正好印证了可能和热部署应用未正常卸载导致同一个服务在一个服务节点上注册多次

6

@663534597 不知道我们遇到的情况是否一样,我这里是cache文件出现大量的\u0000字符,cache文件达到几百兆,对应到内存里,ZookeeperRegistry对象的properties属性的很多key里包含大量的\u0000,就这些key(String类型)每一个就有几兆,甚至十几兆大,\u0000是不可识别的字符,到底是怎么出现的,设么情况下会出现,不得而知.

6

目前我们把Registry Cache部分的逻辑简单优化了一下,注册中心+应用名做缓存文件名,减少了对文件的重复载入。 不过\u0000字符的问题、缓存文件过大的问题仍未定位到,不知你使用的模式注册中心分组模式是否有关系? 可以升级到2.5.7版本,持续观察

1

@chickenlj 你的这个修改可能针对于这个问题还没有到关键点,因为故障的场景不是重复加载了文件,而是一个文件的加载就导致了故障,因为这个文件太大了,可能的思路应该是Registry Cache的文件内容的生成做一个考虑,比如内容必须有某个格式,若出现异常写应该直接报错,这样可以把故障挡在前面,若找不到根本解决原因,但是可以做一个预防

0

@chickenlj 我们出现过有多个注册中心的情况 是因为我们的 zk 集群是 配置了 域名(dns转发), 在 AbstractRegistryFactory.getRegistry 方法中 String key = url.toServiceString(); 这个实现是获取的 域名的ip,就生成了多个 注册中心

7

?非常好的问题,涨经验啦。“使用姿势”很重要,功能好坏在于怎么使用。

同机房调用场景下,使用一个注册中心即可,建议优先使用服务分组或服务版本做隔离;跨机房调用场景下,可能需要多个注册中心。