这一次的错误是java heap space
报错日志
[ERROR] 2019-05-11 00:15:22 [pool-1-thread-14] (ForgivingExceptionHandler.java:119) Consumer com.vwym.rabbitmq.QueueManager$1@2a43ded9 (amq.ctag-bl4ipZBl-EHg3AVh9te3Og) method handleDelivery for channel AMQChannel(amqp://[email protected]:5672/,1) threw an exception for channel AMQChannel(amqp://[email protected]:5672/,1)
java.lang.OutOfMemoryError: Java heap space
at yaml.parser.ParserReader.<init>(Unknown Source)
at yaml.parser.YamlParser.<init>(Unknown Source)
at org.ho.yaml.YamlDecoder.readObject(Unknown Source)
at org.ho.yaml.YamlConfig.load(Unknown Source)
at org.ho.yaml.YamlConfig.load(Unknown Source)
at org.ho.yaml.Yaml.load(Unknown Source)
at com.vwym.rabbitmq.QueueManager.reflectDelivery(QueueManager.java:368)
at com.vwym.rabbitmq.QueueManager.access$0(QueueManager.java:362)
at com.vwym.rabbitmq.QueueManager$1.handleDelivery(QueueManager.java:229)
at com.rabbitmq.client.impl.ConsumerDispatcher$5.run(ConsumerDispatcher.java:149)
at com.rabbitmq.client.impl.ConsumerWorkService$WorkPoolRunnable.run(ConsumerWorkService.java:104)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
报错原因解释
首先Runtime.getRuntime()有3个方法:freemomery、totalmemory、maxmemory。
分别是当前jvm的剩余内存,目前可用总内存,允许向操作系统获取的最大内存。
在不动jvm设置的情况下,totalmemory默认取本机内存的1/64,maxmemory取本机内存的1/4。
一旦totalmemory超出maxmemory,就会报错,也就是上述错误。
排查
工具推荐
这次用到的环境是windows,工具是jdk中的VisualVM,目录是$JAVA_HOME/bin/jvisualvm.exe,这个工具也可以进行dump分析。打开后下图
不过使用这个工具先,我个人推荐2个插件,Tracer-JVM Probes和Visual GC ,Tracer-JVM Probes插件可以查看程序的io使用情况,Visual GC可以查看程序GC情况。
菜单栏->工具->插件 打开后,可用插件->Visual GC(选中)->Tracer-JVM Probes(选中)->安装
然后双击已有程序,点击打开
监视
监视这一栏,可以看到目前程序的堆、类总数、线程、CPU4种情况,一般程序出错,也会直接反映在这4项参数上,后文分析就是在堆这里发现了问题。
visual GC
主要用于查看GC的次数,full gc、ygc是我们排查的时候重点关注的要素之一。
Tracer
用的比较少,一般是针对高读写的情况才需要关注。
排查过程
运行一段时间后,dump堆的数据出来,dump的时间是14:57:40
可以看见,全部都是ehcache中相关包,而且全部都是SelectableConcurrentHashMap的内部类Segment,50多M都是由下面组成,我们直接点击查看
附上我个人使用的ehcache的引用和配置
<!-- https://mvnrepository.com/artifact/net.sf.ehcache/ehcache -->
<dependency>
<groupId>net.sf.ehcache</groupId>
<artifactId>ehcache</artifactId>
<version>2.10.6</version>
</dependency>
<cache name="Pingcache"
maxElementsInMemory="1800000"
eternal="false"
timeToIdleSeconds="900"
timeToLiveSeconds="900"
overflowToDisk="false"
memoryStoreEvictionPolicy="FIFO"/>
下处红框显示就是54的引用,可以发现是SelectableConcurrentHashMap的内部类Segment数组。
429,720的字节中429,500都是在这2048个数组中,我们看一下数组里面的构成。
在0-16中,我们发现0 3 6 8 10 11 15都是null,而其他都有数据,我们点击1、2分别查看。
第1条数据,可以看到,这条数据的时间是13:43:58的数据,而且最下方还保留了next引用。
第2条数据,可以看到,这条数据的时间是10:23:51的数据,最下方的next引用为null。
整体翻看,普遍就是有些null有些存在的情况,而且时间分布远超我设置的15分钟过期,但是日志显示的ehcache的size依旧是稳定的数值。
应该是删除策略的问题,惰性删除策略是访问到该数据的时候返回null再删除,而不是定时删除。惰性删除策略是不适用于这种数据增减频繁的需求的。
解决方案
我放弃使用ehcache,考虑数据量也不算大的情况下,我直接写了一个定期删除数据的map去做。
当时没注意到这里,直接用了第二版的ehcache,不确定新版是否还存在这种情况。