深入理解java虚拟机JVM(下)

深入理解java虚拟机JVM(下)

链接:https://pan.baidu.com/s/1c6pZjLeMQqc9t-OXvUM66w
提取码:uwak
复制这段内容后打开百度网盘手机App,操作更方便哦

4. JVM的垃圾收集器

4.1 垃圾收集器类型概述

新生代可用GC策略:

  • 串行GC(Serial Copying);
  • 并行回收GC(Parallel Scavenge);
  • 并行GC(ParNew);

老年代可用GC策略:

  • 串行GC(Serial MSC);
  • 并行GC(Parallel MSC);
  • 并发GC(CMS)。

同一种垃圾的收集类型,有可能会根据触发内存代的不同有不同的效果,所以先来看各个内存回收类型的操作特点。

4.1.1 新生代----串行GC(Serial Copying)

算法:复制(Copy)

过程:

  • 扫描出新生代中存活的对象;
  • Minor GC将存活的对象复制到作为To Space的“S0/S1”区;
  • 之前作为To Space/From Space的S0/S1区对换角色;
  • 经历过几次Minor GC仍旧存活的对象,放入老年代。

4.1.2 新生代----并行回收GC(Parallel Scavenge)

  • 算法:复制(Copying)清理算法;
  • 操作步骤:在扫描和复制时均采用多线程方式处理,并行回收GC为空间较大的新生代回收提供许多优化
  • 优势:在多CPU的机器上GC耗时会比串行方式短,适合多CPU,对暂停时间要求较短的应用。

image.png-63.8kB

GC在回收的过程中要做两件事情,第一件事情扫描所有对象找出存活的对象,第二件事情将存活对象复制到存活区空间。串行的意思是扫描和复制不能同时做,一旦发生复制就会阻塞扫描,因为只有一个线程在处理;而并行的意思是扫描和复制采用多线程的方式处理,扫描和复制同时进行,互不阻塞(或者说暂停时间较短)

4.1.3 新生代----并行GC(ParNew)

算法:复制(Copying)清理算法:

操作步骤:并行GC(ParNew)必须结合老年代"CMS GC"一起使用。因为在新生代如果发生了"Minor GC"时,老年代也需要使用"CMS GC"同时处理(并行回收GC并不会做这些)。

  • CMS(Concurrent Mark-Sweep)

4.1.4 老年代----串行GC(Serial MSC)

算法:标记-清除-压缩(Mark-Sweep-Compact)

操作步骤:

  • 扫描老年代中还存活的对象,并且对这些对象进行标记;
  • 遍历整个老年代内存空间,回收所有未标记的对象内存;
  • 将所有存活对象都集中在一端,而后将所有回收对象的内存空间变为一块连续的内存空间。

优缺点:串行执行的过程中为单线程,需要暂停应用并耗时较长

4.1.5 老年代----并行GC(Parallel Mark Sweep,Parallel Compacting)

算法:标记-压缩(Mark-Compact)

操作步骤:

  • 将老年代内存空间按照线程个数划分为若干个子区域;
  • 多个线程并行对各自子区域内的存活对象进行标记;
  • 多个线程并行清除所有未标记的对象;
  • 多个线程并行将多个存活对象整理在一起,并将所有被回收的对象空间整合为一体。

优缺点:多个线程同时进行垃圾回收可以缩短应用的暂停时间,但是由于老年代的空间一般较大,所以在扫描和标记存活对象上需要花费较长时间


与串行的处理操作相比,整体的操作只是多了一个多线程的支持,但是这样的暂停时间就会减少

4.1.6 并行GC(Concurrent Mark-Sweep GC,CMS GC)

算法:标记-清除(Mark-Sweep)

操作步骤:

  • 初始标记(STW Initial Mark):虚拟机暂停正在执行的任务(STW),由根对象扫描出所有的关联对象,并做出标记。此过程只会导致短暂的JVM暂停
  • 并发标记(Concurrent Marking):恢复所有暂停的线程对象,并且对之前标记过的对象进行扫描,取得所有跟标记对象有关联的对象;
  • 并发预清理(Concurrent Precleaning):查找所有在并发标记阶段新进入老年代的对象(一些对象可能从新生代晋升到老年代,或者有一些对象被分配到老年代),通过重新扫描,减少下一阶段的工作;
  • 重新标记(STW Remark):此阶段会暂停虚拟机,对在“并发标记”阶段被改变引用或新创建的对象进行标记;
  • 并发清理(Concurrent Sweeping):恢复所有暂停的应用线程,对所有未标记的垃圾对象进行清理,并且会尽量将已回收对象的空间重新拼凑为一个整体。在此阶段收集器线程和应用程序线程并发执行。
  • 并发重置(Concurrent Reset):重置CMS收集器的数据结构,等待下一次垃圾回收。

优缺点:只有在第一次和重新标记阶段才会暂停整个应用,这样对应用程序所带来的影响非常的小。缺点是并发标记与回收线程会与应用线程争抢CPU资源,并且容易产生内存碎片。

image.png-202.3kB

4.2 垃圾回收策略配置

4.2.1 官方推荐的常用的回收策略

对于JVM而言,本身有两种运行模式:

  • 单机版客户端程序(Clinet)
  • 服务器端程序(server)

image.png-125kB

4.2.2 GC策略调整参数

image.png-359kB

image.png-143.8kB

如果要想确认使用的GC处理,首先需要知道当前的主机上可以支持的处理进程数量(也就是CPU的总处理线程数)

4.2.3 理解GC日志

  • 阅读GC日志是处理Java虚拟机内存问题的基础技能,它只是一些人为确定的规则,没有太多的技术含量。
  • 每一种收集器的日志形式都是由他们自身的实现所决定的,换而言之,每个收集器的日志格式都可以不一样。但虚拟机设计者为了方便用户阅读,将各个收集器的日志都维持一定得共性,例如以下两段典型的GC日志。
[GC  [DefNew: 3324K->152K(3712K),0.0025925 secs] 3324K->152K(11904K),0.0031680 secs]

[Full GC  [Tenured: 0K->210K(10240K), 0.0149142 secs] 4603K->210K(19456K), [Perm : 2999K->2999K(21248K)], 0.0150007 secs] [Times: user=0.01 sys=0.00,real=0.02 secs]

GC日志开头的[GC[Full GC说明了这次垃圾收集的停顿类型,而不是用来区分新生代GC还是老年代GC的。如果有Full,说明这次GC是发生了Stop-The-World的,例如下面这段新生代收集器ParNew的日志也会出现[Full GC(这一般是因为出现了分配担保失败之类的问题,所以才导致STW)。如果是调用System.gc()方法所触发的收集,那么在这里将显示[Full GC(System)。

[Full GC 283.736: [ParNew: 261588K->261599K(261952K), 0.0000288 secs]
  • 接下来的[DefNew,[Tenured,[Perm表示GC发生的区域,这里显示的区域名称与使用的GC收集器是密切相关的,例如上面样例所使用的Serial收集器中的新生代名为Default New Generation,所以显示的是[DefNew。如果是ParNew收集器,新生代名称就会变为[ParNew,意为Parallel New Generation。如果采用Parallel Scavenge收集器,那它配套的新生代称为PSYoungGen,老年代和永久代同理,名称也是由收集器决定的。
  • 后面方括号内部的3324K->152K(3712K)含义是“GC前该内存区域已使用容量-->GC后该内存区域已使用容量(该内存区域总容量)”。而在方括号之外的"3324K-->152K(11904K)"表示"GC前java堆已使用容量-->GC后Java堆已使用容量(Java堆总容量)"
  • 再往后,"0.0025925 secs" 表示该内存区域GC所占用的时间,单位是秒。有的收集器会给出更具体的时间数据,如[Times:user=0.01 sys=0.00,real=0.02 secs],这里面的user,sys和real与Linux的time命令所输出的时间含义一致,分别代表用户态消耗的CPU时间,内核态消耗的CPU事件和操作从开始到结束所经过的墙钟时间(Wall Clock Time)。CPU时间与墙钟时间的区别是,墙钟时间包括各种非运算的等待耗时,例如等待磁盘I/O,等待线程阻塞,而CPU时间不包括这些耗时,但当系统有多CPU或者多核的话,多线程操作会叠加这些CPU时间,所以同学们看到的user或sys时间超过real时间是完全正常的。

4.2.4 GC处理策略调优实操

#不进行任何GC回收策略优化
[root@Tomcat-Jvm bin]# pwd
/usr/tomcat/bin
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh
JAVA_OPTS="-Djava.awt.headless=true -Dfile.encoding=UTF-8 -server -Xms1024m -Xmx1024m -Xmn500m -Xss256k"

[root@Tomcat-Jvm bin]# vim catalina.sh 
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh
JAVA_OPTS="-server -Xms10m -Xmx10m -Xss256k -XX:+PrintGCDetails"
#重启tomcat
[root@Tomcat-Jvm bin]# pgrep java
7647
[root@Tomcat-Jvm bin]# kill -9 7647
[root@Tomcat-Jvm bin]# pgrep java
[root@Tomcat-Jvm bin]#
[root@Tomcat-Jvm bin]# sh startup.sh 
[root@Tomcat-Jvm bin]# pgrep java
7711
#查看日志
[root@Tomcat-Jvm logs]# pwd
/usr/tomcat/logs

[root@Tomcat-Jvm logs]# tailf catalina.out 
[GC (Allocation Failure) [DefNew: 2752K->320K(3072K), 0.0015806 secs] 2752K->1096K(9920K), 0.0016151 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6810K(6848K), 0.0096249 secs] 9915K->9375K(9920K), [Metaspace: 14263K->14263K(1062912K)], 0.0096493 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

日志解析:
DefNew:表示新生代使用Serial串行GC垃圾收集器,defNew提供新生代空间信息;
Tenured:老年代也是串行GC
  • 从上边的测试我们发现Tomcat默认使用的是串行GC(Serial Copying);
  • 这是因为,tomcat默认启动的是JVM的clent端模式,所以我们在对JVM进行调优的时候,才必须加-server参数,也就是强制tomcat用server模式运行,性能比client高很多。但是它的GC回收策略并未发生改变,因此我们需要进行调优
#进行GC回收策略优化,使用-XX:+UseParNewGC
[root@Tomcat-Jvm bin]# pwd
/usr/tomcat/bin
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh 
JAVA_OPTS="-server -Xms10m -Xmx10m -Xss256k -XX:+PrintGCDetails"

[root@Tomcat-Jvm bin]# vim catalina.sh 
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh 
JAVA_OPTS="-server -Xms10m -Xmx10m -Xss256k -XX:+UseParNewGC -XX:+PrintGCDetails"
#重启tomcat
[root@Tomcat-Jvm bin]# pgrep java
7711
[root@Tomcat-Jvm bin]# kill -9 7711
[root@Tomcat-Jvm bin]# pgrep java
[root@Tomcat-Jvm bin]#
[root@Tomcat-Jvm bin]# sh startup.sh 
[root@Tomcat-Jvm bin]# pgrep java
7755
#查看日志
[root@Tomcat-Jvm logs]# pwd
/usr/tomcat/logs
[root@Tomcat-Jvm logs]# tailf catalina.out
Java HotSpot(TM) 64-Bit Server VM warning: Using the ParNew young collector with the Serial old collector is deprecated and will likely be removed in a future release
#警告:使用PalNew年轻收集器与串行旧收集器被弃用,并可能在未来的版本中被删除。也就是说以后不能用了。-_-!

[GC (Allocation Failure) [ParNew: 2752K->320K(3072K), 0.0037309 secs] 2752K->1105K(9920K), 0.0037752 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089162 secs] 9919K->9490K(9920K), [Metaspace: 14299K->14299K(1062912K)], 0.0089379 secs] [Times: user=0.01 sys=0.00, real=0.01 secs]

参数说明:
-XX:+UseParNewGC:对年轻带采用多线程并行回收GC,速度快
ParNew:年轻代并行GC
Tenured:老年代串行GC

-XX:+UseParNewGC这个回收策略在以后的版本中将被弃用

#进行CMS GC回收策略优化
[root@Tomcat-Jvm bin]# pwd
/usr/tomcat/bin
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh
JAVA_OPTS="-server -Xms10m -Xmx10m -Xss256k -XX:+UseParNewGC -XX:+PrintGCDetails"

[root@Tomcat-Jvm bin]# vim catalina.sh 
[root@Tomcat-Jvm bin]# sed -n '121p' catalina.sh
JAVA_OPTS="-server -Xms10m -Xmx10m -Xss256k -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails"
#重启tomcat
[root@Tomcat-Jvm bin]# pgrep java
7755
[root@Tomcat-Jvm bin]# kill -9 7755
[root@Tomcat-Jvm bin]# pgrep java
[root@Tomcat-Jvm bin]#
[root@Tomcat-Jvm bin]# sh startup.sh 
[root@Tomcat-Jvm bin]# pgrep java
16609
#查看日志
[root@Tomcat-Jvm logs]# pwd
/usr/tomcat/logs
[root@Tomcat-Jvm logs]# tailf catalina.out     


#年轻代并行GC
[GC (Allocation Failure) [ParNew: 3072K->3072K(3072K), 0.0000088 secs][CMS: 6836K->6833K(6848K), 0.0115990 secs] 9908K->9286K(9920K), [Metaspace: 14302K->14302K(1062912K)], 0.0116329 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

#老年代CMS
#初始化标记(CMS Initial Mark)
[GC (CMS Initial Mark) [1 CMS-initial-mark: 3930K(6848K)] 5227K(9920K), 0.0007426 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

#并发标记(concurrent-marking):CMS标记开始
[CMS-concurrent-mark-start]
[CMS-concurrent-mark: 0.002/0.002 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

#并发预清理(concurrent-preclean):预清理开始
[CMS-concurrent-preclean-start]
[CMS-concurrent-preclean: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

#重新标记(CMS Remark)
[GC (CMS Final Remark) [YG occupancy: 1296 K (3072 K)][Rescan (parallel) , 0.0005321 secs][weak refs processing, 0.0000757 secs][class unloading, 0.0007242 secs][scrub symbol table, 0.0004812 secs][scrub string table, 0.0000998 secs][1 CMS-remark: 3930K(6848K)] 5227K(9920K), 0.0020324 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 

#并发清理(Concurrent Sweeping):开始进行无用对象清理
[CMS-concurrent-sweep-start]
[CMS-concurrent-sweep: 0.001/0.001 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

#并发重置(Concurrent Reset)
[CMS-concurrent-reset-start]
[CMS-concurrent-reset: 0.000/0.000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 

CMS的处理适当性能会好一些。但是这所有的GC策略都是现在正在常用的策略,不过似乎他们都有缺陷。

4.3 G1收集器

很多的GC收集策略虽然提供了,但是依然会发现这些策略总会有那么一点点的不合理,造成所有不合理的本质就是内存一大,什么都不行了。而且现在大内存主机,多CPU主机越来越多了。所以Java从十多年多前就已经偷偷摸摸的提出了一个新的垃圾收集器(目前还没有大用起来),这个收集器就是G1收集器。

4.3.1 G1收集器简介

G1收集器(Garbage First)是从JDK1.7 u4版本之后正式引入到Java中的垃圾收集器,此类垃圾收集器主要应用在多CPU以及大内存的服务器环境下,这样可以极大的减少垃圾收集的停顿时间,以提升服务器的操作性能。引入此收集器的主要目的是为了在将来的某一个时间内可以替换掉CMS(Concurrent Mark Sweep)收集器。

  • 虽然G1收集器是十多年前提出的一个概念,但是真正的出现是在JDK 1.7的时候出来的(Oracle发布的)
  • 对于java服务器而言,我们如何去选择一个合适的配置呢?默认情况下,java会为每一个线程分配1M的内存空间;我们现在的服务器有32G内存,最大可以分配30G,那么理论上可以处理?(30*1024=30720个用户请求/每秒)
  • 如果实际中真的要处理这么多用户请求,那么就算服务器不崩也快死了(瓶颈很多,I/O读写,带宽等)。
  • 因此,真正一台服务器处理个5000-10000个请求/每秒基本上也就够了。

G1区域划分:

  • G1垃圾收集器采用的是区域化,分布式的垃圾收集器。其核心思想为将整个堆内存区域划分成大小相同的之区域(Region);
  • 在JVM启动时会自动设置这些子区域的大小(区域大小范围“1M-32M”,最多可以设置2048个区域,即支持的最大内存为:“32MB*2048=65536M”,64G内存),这样Eden,Survivor,Tenured就变成了一系列不连续的内存区域,也就避免了全内存区的GC操作。

image.png-116.2kB

此时,按照G1的实现方案相当于现在将所有的子内存区域合并在一起,也不再进行任何的区分,这样就相当于所有的内存的区域都可以按照一个统一的方式规划处理。而G1的最大特点就是避免了全内存扫描,这就带来了一个性能的提升。

4.3.2 G1收集策略

新生代G1回收策略

image.png-159.5kB

image.png-154.3kB

老年代G1回收策略

image.png-134.6kB

image.png-145.8kB

image.png-152.9kB

image.png-128.8kB

image.png-162.2kB

image.png-136.6kB

G1回收策略总结:在整个的G1进行标记和清理的时候是按照区域完成的,这样不影响其它的区域的执行,除此之外,使用的形式和之前的CMS都是非常类似的操作方式

4.3.3 G1相关处理参数

如果要使用G1收集器,则必须由用户自己来进行参数的指定,有如下的可用参数

image.png-375.9kB

5. JVM的内存分配与回收策略总结

Java技术体系中所提倡的自动内存管理最终可以归结为自动化地解决了两个问题

  • 给对象分配内存
  • 回收分配给对象的内存

关于回收内存这一点,已经介绍了虚拟机中的垃圾收集器体系以及运作原理,现在就让我们一起来看一下给对象分配内存的事情

5.1 对象优先在Eden分配

  • 大多数情况下,对现在新生代Eden区中分配。当Eden区没有足够空间进行分配时,虚拟机将发起一次Minor GC
  • 虚拟机提供了-XX:+PrintGCDetails这个收集器日志参数,告诉虚拟机在发生垃圾收集行为时打印内存回收日志,并且在进程退出的时候输出当前的内存各区域分配情况。在实际应用中,内存回收日志一般是打印到文件后通过日志工具进行分析。
#堆内存溢出OutOfMemoryError: Java heap space 之GC回收日志分析
[root@Tomcat-Jvm logs]# pwd
/usr/tomcat/logs
[root@Tomcat-Jvm logs]# head -50 catalina.out      #对象内存优先分配在新生代的Eden区,Eden区满触发Minor GC进行对象回收,活跃对象晋升到老年代
16-Jan-2019 16:05:34.150 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.0.27
16-Jan-2019 16:05:34.151 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Sep 28 2015 08:17:25 UTC
16-Jan-2019 16:05:34.151 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.0.27.0
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-957.1.3.el7.x86_64
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/jdk1.8.0_60/jre
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_60-b27
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/apache-tomcat-8.0.27
16-Jan-2019 16:05:34.152 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/apache-tomcat-8.0.27
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.endorsed.dirs=/usr/tomcat/endorsed
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.base=/usr/tomcat
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Dcatalina.home=/usr/tomcat
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.io.tmpdir=/usr/tomcat/temp
16-Jan-2019 16:05:34.153 INFO [main] org.apache.catalina.core.AprLifecycleListener.lifecycleEvent The APR based Apache Tomcat Native library which allows optimal performance in production environments was not found on the java.library.path: /usr/java/packages/lib/amd64:/usr/lib64:/lib64:/lib:/usr/lib
16-Jan-2019 16:05:34.539 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["http-nio-8080"]
16-Jan-2019 16:05:34.556 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
16-Jan-2019 16:05:34.570 INFO [main] org.apache.coyote.AbstractProtocol.init Initializing ProtocolHandler ["ajp-nio-8009"]
16-Jan-2019 16:05:34.571 INFO [main] org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared selector for servlet write/read
16-Jan-2019 16:05:34.585 INFO [main] org.apache.catalina.startup.Catalina.load Initialization processed in 1296 ms
16-Jan-2019 16:05:34.637 INFO [main] org.apache.catalina.core.StandardService.startInternal Starting service Catalina
16-Jan-2019 16:05:34.638 INFO [main] org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine: Apache Tomcat/8.0.27
16-Jan-2019 16:05:34.665 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/apache-tomcat-8.0.27/webapps/ROOT
16-Jan-2019 16:05:35.282 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/apache-tomcat-8.0.27/webapps/ROOT has finished in 617 ms
16-Jan-2019 16:05:35.283 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/apache-tomcat-8.0.27/webapps/docs
16-Jan-2019 16:05:35.334 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/apache-tomcat-8.0.27/webapps/docs has finished in 51 ms
16-Jan-2019 16:05:35.335 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/apache-tomcat-8.0.27/webapps/examples
16-Jan-2019 16:05:35.926 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/apache-tomcat-8.0.27/webapps/examples has finished in 591 ms
16-Jan-2019 16:05:35.926 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/apache-tomcat-8.0.27/webapps/host-manager
16-Jan-2019 16:05:35.979 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/apache-tomcat-8.0.27/webapps/host-manager has finished in 53 ms
16-Jan-2019 16:05:35.979 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deploying web application directory /usr/apache-tomcat-8.0.27/webapps/manager
16-Jan-2019 16:05:36.029 INFO [localhost-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectory Deployment of web application directory /usr/apache-tomcat-8.0.27/webapps/manager has finished in 50 ms
16-Jan-2019 16:05:36.044 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["http-nio-8080"]
16-Jan-2019 16:05:36.074 INFO [main] org.apache.coyote.AbstractProtocol.start Starting ProtocolHandler ["ajp-nio-8009"]
16-Jan-2019 16:05:36.081 INFO [main] org.apache.catalina.startup.Catalina.start Server startup in 1495 ms
16-Jan-2019 16:09:35.462 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server version:        Apache Tomcat/8.0.27
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server built:          Sep 28 2015 08:17:25 UTC
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Server number:         8.0.27.0
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Name:               Linux
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log OS Version:            3.10.0-957.1.3.el7.x86_64
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Architecture:          amd64
16-Jan-2019 16:09:35.464 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Java Home:             /usr/jdk1.8.0_60/jre
16-Jan-2019 16:09:35.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Version:           1.8.0_60-b27
16-Jan-2019 16:09:35.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log JVM Vendor:            Oracle Corporation
16-Jan-2019 16:09:35.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_BASE:         /usr/apache-tomcat-8.0.27
16-Jan-2019 16:09:35.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log CATALINA_HOME:         /usr/apache-tomcat-8.0.27
16-Jan-2019 16:09:35.465 INFO [main] org.apache.catalina.startup.VersionLoggerListener.log Command line argument: -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties
#老年代内存空间不足,Minor GC回收失败(活跃对象晋升老年代失败,老年代promotion failed担保失败)
[GC (Allocation Failure) [DefNew (promotion failed) : 3033K->3033K(3072K), 0.0022267 secs][Tenured: 6847K->6823K(6848K), 0.0089414 secs] 8854K->8104K(9920K), [Metaspace: 13838K->13838K(1062912K)], 0.0112050 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
#老年代内存空间已满,出发Full GC
[Full GC (Allocation Failure) [Tenured: 6848K->6847K(6848K), 0.0105321 secs] 9920K->9030K(9920K), [Metaspace: 14074K->14074K(1062912K)], 0.0105677 secs] [Times: user=0.00 sys=0.01, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0092309 secs] 9919K->9124K(9920K), [Metaspace: 14096K->14096K(1062912K)], 0.0092658 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0094443 secs] 9919K->9214K(9920K), [Metaspace: 14096K->14096K(1062912K)], 0.0094778 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0098410 secs] 9919K->9305K(9920K), [Metaspace: 14143K->14143K(1062912K)], 0.0098705 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6827K(6848K), 0.0108657 secs] 9920K->9015K(9920K), [Metaspace: 14162K->14162K(1062912K)], 0.0109054 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6845K->6845K(6848K), 0.0094831 secs] 9917K->9136K(9920K), [Metaspace: 14185K->14185K(1062912K)], 0.0095132 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0093504 secs] 9919K->9287K(9920K), [Metaspace: 14250K->14250K(1062912K)], 0.0093811 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0093710 secs] 9919K->9348K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0093985 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6824K(6848K), 0.0105587 secs] 9919K->9397K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0105852 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0091629 secs] 9919K->9349K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0091880 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0102117 secs] 9919K->9376K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0102377 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0096527 secs] 9919K->9415K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0096855 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6815K(6848K), 0.0103718 secs] 9914K->9374K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0103969 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6846K->6846K(6848K), 0.0091342 secs] 9918K->9428K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0091585 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0092422 secs] 9919K->9441K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0092673 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0093740 secs] 9919K->9500K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0093996 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6847K(6848K), 0.0110440 secs] 9915K->9411K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0110694 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0094166 secs] 9919K->9425K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0094449 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0095276 secs] 9919K->9461K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0095516 secs] [Times: user=0.01 sys=0.01, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0097904 secs] 9920K->9524K(9920K), [Metaspace: 14292K->14292K(1062912K)], 0.0098302 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0115462 secs] 9920K->9509K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0115767 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0098396 secs] 9919K->9531K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0098704 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0095657 secs] 9919K->9551K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0095918 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0112828 secs] 9919K->9550K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0113690 secs] [Times: user=0.02 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0104715 secs] 9919K->9569K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0104974 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0089778 secs] 9919K->9596K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090025 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0088864 secs] 9919K->9609K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089103 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0089248 secs] 9919K->9666K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089504 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0088753 secs] 9919K->9658K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0088974 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0090281 secs] 9919K->9681K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090538 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0092309 secs] 9915K->9682K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0092570 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6848K(6848K), 0.0089302 secs] 9919K->9724K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089550 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6848K->6847K(6848K), 0.0092677 secs] 9919K->9726K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0092926 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090837 secs] 9919K->9741K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0091064 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087997 secs] 9919K->9743K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0088221 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089311 secs] 9919K->9770K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089533 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0094449 secs] 9919K->9772K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0094677 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090892 secs] 9919K->9794K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0091135 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089807 secs] 9918K->9817K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090048 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089491 secs] 9912K->9823K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089730 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089082 secs] 9916K->9849K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089326 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087994 secs] 9919K->9904K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0088207 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090742 secs] 9915K->9873K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090962 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089348 secs] 9919K->9875K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089557 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089776 secs] 9919K->9898K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090067 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087318 secs] 9916K->9887K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0087530 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087339 secs] 9919K->9893K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0087559 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087723 secs] 9919K->9905K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0087960 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0088952 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089180 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090587 secs] 9919K->9911K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090813 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0088002 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0088226 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0087327 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0087536 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0086511 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0086727 secs] [Times: user=0.00 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0086630 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0086838 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090225 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090464 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089949 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090176 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0095371 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0095591 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090215 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090442 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0089622 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0089845 secs] [Times: user=0.01 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0088665 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0088884 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0109133 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0109390 secs] [Times: user=0.01 sys=0.00, real=0.02 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0126509 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0126777 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0111797 secs] 9919K->9912K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0112023 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0091912 secs] 9915K->9914K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0092391 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0090595 secs] 9914K->9914K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0090776 secs] [Times: user=0.01 sys=0.01, real=0.01 secs] 
[Full GC (Allocation Failure) [Tenured: 6847K->6847K(6848K), 0.0092440 secs] 9919K->9490K(9920K), [Metaspace: 14300K->14300K(1062912K)], 0.0092663 secs] [Times: user=0.01 sys=0.00, real=0.01 secs] 
#由于老年代空间已满,eden的活跃对象无法正常晋升老年代,导致eden空间也满了,触发OOM堆内存溢出
09-Nov-2018 18:24:24.460 严重 [Catalina-startStop-1] org.apache.catalina.startup.HostConfig.deployDirectories Error waiting for multi-thread deployment of directories to complete
 java.util.concurrent.ExecutionException: java.lang.OutOfMemoryError: Java heap space
    at java.util.concurrent.FutureTask.report(FutureTask.java:122)
    at java.util.concurrent.FutureTask.get(FutureTask.java:192)
    at org.apache.catalina.startup.HostConfig.deployDirectories(HostConfig.java:1058)
    at org.apache.catalina.startup.HostConfig.deployApps(HostConfig.java:443)
    at org.apache.catalina.startup.HostConfig.start(HostConfig.java:1584)
    at org.apache.catalina.startup.HostConfig.lifecycleEvent(HostConfig.java:318)
    at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:94)
    at org.apache.catalina.util.LifecycleBase.setStateInternal(LifecycleBase.java:395)
    at org.apache.catalina.util.LifecycleBase.setState(LifecycleBase.java:339)
    at org.apache.catalina.core.ContainerBase.startInternal(ContainerBase.java:958)
    at org.apache.catalina.core.StandardHost.startInternal(StandardHost.java:872)
    at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
    at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1421)
	at org.apache.catalina.core.ContainerBase$StartChild.call(ContainerBase.java:1411)
    at java.util.concurrent.FutureTask.run(FutureTask.java:266)
    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)
Caused by: java.lang.OutOfMemoryError: Java heap space
	at java.io.BufferedInputStream.<init>(BufferedInputStream.java:203)
	at org.apache.tomcat.util.bcel.classfile.ClassParser.<init>(ClassParser.java:60)
	at org.apache.catalina.startup.ContextConfig.populateJavaClassCache(ContextConfig.java:2205)
	at org.apache.catalina.startup.ContextConfig.populateJavaClassCache(ContextConfig.java:2190)
	at org.apache.catalina.startup.ContextConfig.checkHandlesTypes(ContextConfig.java:2094)
	at org.apache.catalina.startup.ContextConfig.processAnnotationsStream(ContextConfig.java:2044)
	at org.apache.catalina.startup.ContextConfig.processAnnotationsJar(ContextConfig.java:1990)
	at org.apache.catalina.startup.ContextConfig.processAnnotationsUrl(ContextConfig.java:1960)
	at org.apache.catalina.startup.ContextConfig.processAnnotations(ContextConfig.java:1913)
	at org.apache.catalina.startup.ContextConfig.webConfig(ContextConfig.java:1153)
	at org.apache.catalina.startup.ContextConfig.configureStart(ContextConfig.java:765)
	at org.apache.catalina.startup.ContextConfig.lifecycleEvent(ContextConfig.java:299)
	at org.apache.catalina.util.LifecycleBase.fireLifecycleEvent(LifecycleBase.java:94)
	at org.apache.catalina.core.StandardContext.startInternal(StandardContext.java:5154)
	at org.apache.catalina.util.LifecycleBase.start(LifecycleBase.java:150)
	at org.apache.catalina.core.ContainerBase.addChildInternal(ContainerBase.java:754)
	at org.apache.catalina.core.ContainerBase.addChild(ContainerBase.java:730)
	at org.apache.catalina.core.StandardHost.addChild(StandardHost.java:734)
	at org.apache.catalina.startup.HostConfig.deployDirectory(HostConfig.java:1140)
	at org.apache.catalina.startup.HostConfig$DeployDirectory.run(HostConfig.java:1875)
    at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
    ... 4 more

5.2 大对象直接进入老年代

  • 所谓大对象是指,需要大量连续内存空间的Java对象,最典型的大对象就是那种很长的字符串以及数组(笔者列出的例子中的byte[]数组就是典型的大对象)。大对象对虚拟机的内存分配来说就是一个坏消息,经常出现大对象容易导致内存还有不少空间时就提前触发垃圾收集以获取足够的连续空间来放置他们。
  • 虚拟机提供了一个-XX:PretenureSizeThreshold参数,让大于这个设置值的对象直接在老年区分配。这样做的目的是避免在Eden区及两个survivor区之间发生大量的内存复制(新生代采用复制算法收集内存)。

5.3 长期存活的对象将进入老年代

既然虚拟机采用了分代收集的思想来管理内存,那么内存回收时就必须能识别哪些对象应放在新生代,哪些对象应放在老年代中。为了做到这点,虚拟机给每个对象定义了一个对象年龄计数器。如果对象在Eden出生并经过第一次Minor GC后仍然存活,并且能被Survivor容纳的话,将被移动到Survirvor空间中,并且对象年龄设为1.对象在Survivor区中每"熬过"一次Minor GC,年龄就增加1岁,当它的年龄增加到一定程度(默认为15岁),就将会被晋升到老年代中。对象晋升老年代的年龄阈值,可以通过参数-XX:MaxTenuringThreshold设置。

5.4 动态对象年龄判定

为了能更好地适应不同程序的内存情况,虚拟机并不是永远地要求对象的年龄必须达到MaxTenuringThreshold才能晋升老年代,如果在Survivor空间中相同年龄所有对象大小的总和大于Survivor空间的一半,年龄大于或等于该年龄的对象就可以直接进入老年代,无需等到MaxTenuringThreshold中要求的年龄。

5.5 空间分配担保

在发生Minor - [ ] GC之前,虚拟机会先检查老年代最大可用的连续空间是否大于新生代所有对象总空间;

  • 如果条件成立,那么Minor GC就是安全的。
  • 如果不成立,则虚拟机会查看HandlePromotionFailure设置值是否允许担保失败。

如果允许,那么会继续检查老年代最大可用的连续空间是否大于历次晋升到老年代对象的平均大小;

  • 如果大于,将尝试进行一次Minor GC,尽管是存有风险的;
  • 如果小于,那么就进行一次Full GC

如果不允许,那么就会直接进行一次Full GC


在JDK7,8中,HandlePromotionFailure参数不会再影响到虚拟机的空间分配担保策略(Minor GC),只要满足两个条件;

  • 老年代的连续空间大于新生代对象总大小,就会进行Minor GC;
  • 老年代的连续空间大于历次晋升的平均大小就会进行Minor GC;

6. JDK的命令行工具

  • 经过前面两章对于虚拟机内存分配与回收技术各方面的介绍,相信都已经建立了一套比较完整的理论基础。理论总是作为指导实践的工具,能把这些知识应用到实际工作中才是我们的最终目的。接下来,我们就从实践的角度去了解虚拟机内存管理的世界。
  • 给一个系统定位问题的时候,知识,经验是关键基础,数据是依据,工具是运用知识处理数据的手段。这里说的数据包括:运行日志,异常堆栈,GC日志,线程快照(threaddump/javacore文件),堆转储快照(heapdump/hprof文件)等。经常使用适当的虚拟机监控和分析的工具可以加快我们分析数据,定位解决问题的速度,但在学习工具前,也该意识到工具永远都是知识技能的一层包装,没有什么工具是“秘密武器”,不可能学会了就能包治百病。

6.1 jps:虚拟机进程状况工具

功能和ps类似:可以列出正在运行的虚拟机进程,并显示虚拟机执行主类名称以及这些进程的本地虚拟机唯一ID(LVMID),虽然功能比较单一,但它是使用频率最高的JDK命令行工具,因为其他的工具大多都需要输入查询到的LVMID(进程PID)来确定要监控的是哪一个虚拟机进程。

6.1.1 命令格式与主要选项

jps [options] [hostid]

选项 作用
-q 只输出LVMID,省略主类名称
-m 输出虚拟机进程启动时传递给主类的参数
-l 输出主类的全名,如果进程执行的是Jar包,输出Jar路径
-v 输出虚拟机进程启动时JVM参数

6.1.2 操作示例

#查看JVM进程的LVMID(PID)
[root@Tomcat-Jvm ~]# jps
16609 Bootstrap
16673 Jps

[root@Tomcat-Jvm ~]# jps -q
16609
16685

[root@Tomcat-Jvm ~]# jps -m
16609 Bootstrap start
16697 Jps -m

[root@Tomcat-Jvm ~]# jps -l
16609 org.apache.catalina.startup.Bootstrap
16709 sun.tools.jps.Jps
#查看JVM启动时的优化参数
[root@Tomcat-Jvm ~]# jps -v
16609 Bootstrap -Djava.util.logging.config.file=/usr/tomcat/conf/logging.properties -Djava.util.logging.manager=org.apache.juli.ClassLoaderLogManager -Xms10m -Xmx10m -Xss256k -XX:+UseConcMarkSweepGC -XX:+PrintGCDetails -Djava.endorsed.dirs=/usr/tomcat/endorsed -Dcatalina.base=/usr/tomcat -Dcatalina.home=/usr/tomcat -Djava.io.tmpdir=/usr/tomcat/temp
16721 Jps -Denv.class.path=.:/usr/jdk/lib:/usr/jdk/lib/tools.jar -Dapplication.home=/usr/jdk1.8.0_60 -Xms8m

6.2 jstat:虚拟机统计信息监视工具

用于监视虚拟机各种运行状态信息的命令行工具。它可以显示本地或者远程虚拟机进程中的类装载,内存,垃圾收集,JIT即时编译等运行数据,在没有GUI图形界面,只有文本控制台环境的服务器上,它是定位虚拟机性能问题的首选工具

6.2.1 命令格式与主要选项

jstat [ option LVMID [interval[s|ms] [count]] ]

  • interval:查询间隔
  • count:查询次数,如果省略,则只查询一次

例如:假设需要每250毫秒查询一次进程2764垃圾收集状况,一共查询20次,那么命令如下:jstat -gc 2764 250 20

选项 作用
-class 监视类装载,卸载数量,总空间以及类装载耗费时间
-gc 监视java堆状况,包含eden,s0,s1,老年代,元空间等使用情况
-gccapacity 与-gc基本相同,但输出主要关注区域的最大最小空间
-gcutil 与-gc基本相同,但输出主要关注已使用空间占总空间的百分比
-gccause 与-gcutil基本相同,但会额外输出导致上一次GC产生原因
-gcnew 监视新生代GC
-gcnewcapacity 监视内容与-gcnew基本相同,输出主要关注使用到的最大,最小空间
-gcold 监视老年代GC状况
-gcoldcapacity 监视内容与-gcold基本相同,输出主要关注使用的最大,最小空间
-gcmetacapacity 输出元空间使用的最大,最小空间
-compiler 输出JIT编译器编译过的方法,耗时等信息
-printcompilation 输出已经被JIT编译的方法

6.2.2 操作示例

[root@Tomcat-Jvm ~]# jps
16609 Bootstrap
16733 Jps

#查看jvm的类装载情况
[root@Tomcat-Jvm ~]# jstat -class 16609
Loaded  Bytes  Unloaded  Bytes     Time   
  2452  4902.3        0     0.0       2.16

Loaded:加载class的数量
Bytes:所占用空间大小
Unloaded:未加载数量
Bytes:未加载占用空间
Time:时间
#查看JVM的堆状况及垃圾回收统计
[root@Tomcat-Jvm ~]# jstat -gc 16609
 S0C    S1C    S0U    S1U      EC       EU        OC         OU       MC     MU    CCSC   CCSU   YGC     YGCT    FGC    FGCT     GCT   
320.0  320.0  245.7   0.0    2752.0   2752.0    6848.0     6841.1   15616.0 15114.2 1792.0 1658.8    171    0.049 3280    41.204   41.253


S0C:第一个幸存区的总大小
S1C:第二个幸存区的总大小
S0U:第一个幸存区的使用大小
S1U:第二个幸存区的使用大小
EC:伊甸园区的总大小
EU:伊甸园区的使用大小
OC:老年代的总大小
OU:老年代的使用大小
MC:元空间的总大小(方法区占用大小)
MU:元空间的使用大小
CCSC:压缩类空间的总大小
CCSU:压缩类空间的使用大小
YGC:年轻代垃圾回收次数
YGCT:年轻代垃圾回收消耗时间
FGC:老年代垃圾回收次数
FGCT:老年代垃圾回收消耗时间
GCT:垃圾回收消耗总时间
#查看JVM堆内存空间占用比例
[root@Tomcat-Jvm ~]# jstat -gcutil 16609
  S0     S1     E      O      M     CCS    YGC     YGCT    FGC    FGCT     GCT   
 87.27   0.00 100.00  99.90  96.79  92.57    172    0.049  3305   41.512   41.561

S0:第一幸存区占当前空间总容量百分比
S1:第二幸存区占当前空间总容量百分比
E:伊甸园空间利用率占空间当前容量的百分比
O:老年代空间利用率占空间当前容量的百分比
M:元空间利用率占空间当前容量的百分比
CCS:压缩的类空间利用率百分比
YGC:minor GC事件的数量
YGCT:minor GC垃圾收集时间
FGC:FULL GC事件的数量
FGCT:FULL GC垃圾收集时间
GCT:GC垃圾收集总时间
#查看JVM编译统计
[root@Tomcat-Jvm ~]# jstat -compiler 16609
Compiled Failed Invalid   Time   FailedType FailedMethod
    1681      1       0     7.36          1 org/apache/tomcat/util/IntrospectionUtils setProperty

Compiled:编译数量
Failed:失败数量
Invalid:不可用数量
Time:时间
FailedType:失败类型
FailedMethod:失败的方法
#查看JVM编译方法统计
[root@Tomcat-Jvm ~]# jstat -printcompilation 16609
Compiled  Size  Type Method
    1681     27    1 java/nio/charset/CharsetEncoder onUnmappableCharacter

Compiled:最近编译方法的数量
Size:最近编译方法的字节码数量
Type:最近编译方法的编译类型
Method:方法名标识

6.3 jmap:java内存映像工具

用于生成堆转储快照(一般称为heapdump或dump文件)。

6.3.1 命令格式与主要选项

jmap [ option ] LVMID

选项 作用
-dump 生成java堆转储快照
-heap 相似java堆详细信息
-histo 显示堆对象统计信息
-F 当虚拟机进程对-dump无响应,可用此项强制生成dump快照

6.3.2 操作示例

#生成tomcat的JVM堆转储快照
[root@Tomcat-Jvm ~]# jps
16609 Bootstrap
16897 Jps

[root@Tomcat-Jvm ~]# jmap -dump:format=b,file=tomcat.bin 16609
Dumping heap to /root/tomcat.bin ...
Heap dump file created

[root@Tomcat-Jvm ~]# ll tomcat.bin 
-rw------- 1 root root 15118054 1月  18 15:27 tomcat.bin
#查看JVM的堆详细信息
[root@Tomcat-Jvm ~]# jmap -heap 16609
Attaching to process ID 16609, please wait...
Debugger attached successfully.
Server compiler detected.
JVM version is 25.60-b23

using parallel threads in the new generation.
using thread-local object allocation.
Concurrent Mark-Sweep GC

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 10485760 (10.0MB)
   NewSize                  = 3473408 (3.3125MB)
   MaxNewSize               = 3473408 (3.3125MB)
   OldSize                  = 7012352 (6.6875MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 3145728 (3.0MB)
   used     = 3121512 (2.9769058227539062MB)
   free     = 24216 (0.02309417724609375MB)
   99.23019409179688% used
Eden Space:
   capacity = 2818048 (2.6875MB)
   used     = 2818048 (2.6875MB)
   free     = 0 (0.0MB)
   100.0% used
From Space:
   capacity = 327680 (0.3125MB)
   used     = 303464 (0.28940582275390625MB)
   free     = 24216 (0.02309417724609375MB)
   92.60986328125% used
To Space:
   capacity = 327680 (0.3125MB)
   used     = 0 (0.0MB)
   free     = 327680 (0.3125MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 7012352 (6.6875MB)
   used     = 7005264 (6.6807403564453125MB)
   free     = 7088 (0.0067596435546875MB)
   99.89892121787383% used

9569 interned Strings occupying 830088 bytes.

6.4 jhat:虚拟机堆转储快照分析工具

jhat需要搭配jmap来使用,来分析jmap生成的堆转储快照。jhat内置了一个微型的HTTP/HTML服务器,生成dump文件的分析结果后,可以在浏览器中查看。

6.4.1 操作示例

[root@Tomcat-Jvm ~]# jhat tomcat.bin 
Reading from tomcat.bin...
Dump file created Fri Jan 18 15:27:56 CST 2019
Snapshot read, resolving...
Resolving 137258 objects...
Chasing references, expect 27 dots...........................
Eliminating duplicate references...........................
Snapshot resolved.
Started HTTP server on port 7000
Server is ready.

在浏览器中输入:http://192.168.200.19:7000

image.png-131.2kB