HotSpot JVM 有许多可用的参数选项,也许太多了,有时候我们会将一些正在寻找的或者“魔法式”的选项添加在我们的应用上,导致非常可怕的后果。我认为这种情况不应该存在,应该有一些选项能帮助我们监控应用或者调整应用的某些部分。
为了获得完整的JVM参数列表,我们不仅可以参考OpenJDK源码里的 globals.hpp 文件,也可以从这个 网站 上找到这些列表。
在这里我总结了一些实用的JVM参数,接下来我们一起学习一下。
虽然我们已经完全理解-Xms -Xms选项(有时也被缩写成-ms、-mx),但是Java堆和非堆中的其它一些部分也应该被设置:
-XX:NewSize=n 定义了年轻代(Young generation)的初始大小,包括Eden(伊甸园区)和Survivors(幸存者区)
-XX:MaxNewSize=n 定义了年轻代的最大大小,包括Eden(伊甸园区)和Survivors(幸存者区)
-XX:SurvivorRatio=n 定义了Eden(伊甸园区)和2个幸存者区(2 survivors)之间的大小比例。
n没有设置单位的话,默认用字节来表示。我们也可以使用k,K, m, M, g & G来表示千字节(kilobytes,即k、K)、兆字节(megabytes,即m、M)和千兆字节(gigabytes,即g、G)。
如果NewSize < MaxNewSize,年轻代(Young generation)会在应用运行期间自动地调节大小。然而年轻代的这个动态调整可能会引发Full GC,因此为了避免这个问题的发生,我们通常将这两个参数的值设置成一样的。
-XX:PermSize=n 表示持久代的初始大小
-XX:MaxPermSize=n 表示持久代的最大大小。
n没有设置单位的话,默认用字节来表示。我们也可以使用k,K, m, M, g & G来表示千字节(kilobytes,即k、K)、兆字节(megabytes,即m、M)和千兆字节(gigabytes,即g、G)。
如果PermSize < MaxPermSize,年轻代(Young generation)会在应用运行过程中自动地调节大小。然而持久代的这个动态调整可能会引发Full GC,因此为了避免这个问题的发生,我们通常将这两个参数的值设置成一样的。
-XX:InitialCodeCacheSize=n 定义了代码缓存区的初始大小
-XX:ReservedCodeCacheSize=n 定义了代码缓存区的最大大小。
n没有设置单位的话,默认用字节来表示。我们也可以使用k,K, m, M, g & G来表示千字节(kilobytes,即k、K)、兆字节(megabytes,即m、M)和千兆字节(gigabytes,即g、G)。
代码缓存区存储着经过JIT编译过的代码,这是一个堆外空间,因此GC不能回收利用它。如果达到了代码缓存区的ReservedCodeCacheSize大小限制,由于没有额外的空间存储它们,JIT编译器(JIT Compiler)将停止编译更多的方法。因此如果我们有很多类和方法需要被编译的话,注意这个选项的设置。
当达到最大限制时,JVM会输出如下警告:
Java HotSpot(TM) Server VM warning: CodeCache is full. Compiler has been disabled
用-XX:+PrintCompilation参数我们可以看到:
7383 COMPILE SKIPPED: code cache is full
配置GC,有大量的选项,比如对于CMS来说,最后几个非常有用。在这里我不会来微调CMS。
-XX:+UseSerialGC 表示激活单线程方式来进行年轻代GC(young GC)
-XX:+UseParallelGC 表示激活多线程方式来进行年轻代GC(young GC)
-XX:+UseParallelGC 表示激活另一种多线程方式来进行年轻代GC(young GC),但是需要和CMS垃圾收集器一起使用
-XX:+UseParalelOldGC 表示激活多线程方式来进行老年代GC(Old GC)
-XX:+UseConcMarkSweepGC 表示激活并行GC(Concurrent GC)
-XX:+UseG1GC 表示激活G1 GC(Garbage First GC)
-XX:ParallelGCThreads=n 设置进行并行GC(Parallel*GC)的线程数量,避免相同机器上多个JVM的GC线程互相干扰。
通过-XX:ParallelGCThreads=
当JVM独占地使用系统和处理器时使用默认设置更有意义。 但是,如果有多个JVM(或其他耗CPU的系统)在同一台机器上运行,我们应该使用-XX:ParallelGCThreads来减少垃圾收集线程数到一个适当的值。 例如,如果4个以服务器方式运行的JVM同时跑在一个具有16核处理器的机器上,设置-XX:ParallelGCThreads=4是明智的,它能使不同JVM的垃圾收集器不会相互干扰。(引自 JVM实用参数-6 吞吐量收集器 关于该参数的解释部分)
-XX:CMSInitiatingOccupancyFraction=n 设置CMS垃圾收集器开始GC时,老年代所占JVM大小的比例,当分配率不可预测时,这个选项是有用的
-XX:+UseCMSInitiatingOccupancyOnly 设置JVM不基于运行时收集的数据来启动CMS垃圾收集周期。而是,当该标志被开启时,JVM通过CMSInitiatingOccupancyFraction的值进行每一次CMS收集,而不仅仅是第一次。然而,请记住大多数情况下,JVM比我们自己能作出更好的垃圾收集决策。因此,只有当我们充足的理由(比如测试)并且对应用程序产生的对象的生命周期有深刻的认知时,才应该使用该标志。(引自 JVM实用参数(七)CMS收集器 关于该参数解释部分)
-XX:+CMSClassUnloadingEnabled 相对于并行收集器,CMS收集器默认不会对永久代进行垃圾回收。如果希望对永久代进行垃圾回收,可用设置标志-XX:+CMSClassUnloadingEnabled。在早期JVM版本中,要求设置额外的标志-XX:+CMSPermGenSweepingEnabled。注意,即使没有设置这个标志,一旦永久代耗尽空间也会尝试进行垃圾回收,但是收集不会是并行的,而再一次进行Full GC(引自 JVM实用参数(七)CMS收集器 关于该参数解释部分)
对于应用程序来说,为了诊断内存管理的任何异常行为,绝对需要用一个单独的日志文件来记录GC活动。并且,激活这些信息对您的应用程序几乎没有影响,所以没有理由不激活这些选项。
通过这个选项,我们可以获得以下日志:
8.567: [GC 16448K->168K(62848K), 0.0014256 secs] 16.979: [GC 16616K->152K(62848K), 0.0007727 secs] 25.157: [GC 16600K->152K(62848K), 0.0007124 secs] 33.881: [GC 16600K->136K(62848K), 0.0003721 secs] 43.032: [GC 16584K->152K(59968K), 0.0004123 secs] 50.795: [GC 16216K->152K(59584K), 0.0009683 secs] 58.584: [GC 15832K->148K(59136K), 0.0008669 secs] 66.430: [GC 15508K->148K(58816K), 0.0003436 secs] 73.766: [GC 15188K->148K(58688K), 0.0002917 secs] 81.082: [GC 14868K->148K(58176K), 0.0003157 secs] 88.851: [GC 14548K->148K(58048K), 0.0003148 secs] 96.379: [GC 14228K->148K(57536K), 0.0003129 secs] 101.618: [GC 13908K->704K(57472K), 0.0032532 secs] 102.684: [GC 3206K->744K(57280K), 0.0034611 secs] 102.687: [Full GC 744K->723K(57280K), 0.0525762 secs] 109.313: [GC 14227K->755K(57344K), 0.0005165 secs] 115.905: [GC 14003K->779K(56768K), 0.0006688 secs]
通过这个选项,我们可以获得以下日志:
9.053: [GC [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0014471 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 16.991: [GC [PSYoungGen: 16616K->152K(19136K)] 16616K->152K(62848K), 0.0008244 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 24.965: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0006850 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 32.915: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0007040 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 40.857: [GC [PSYoungGen: 16600K->152K(16256K)] 16600K->152K(59968K), 0.0007618 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 48.653: [GC [PSYoungGen: 16216K->152K(15872K)] 16216K->152K(59584K), 0.0007632 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 53.896: [GC [PSYoungGen: 15832K->192K(15552K)] 15832K->620K(59264K), 0.0131835 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 55.252: [GC [PSYoungGen: 3888K->64K(15424K)] 4317K->716K(59136K), 0.0025925 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 55.255: [Full GC (System) [PSYoungGen: 64K->0K(15424K)] [PSOldGen: 652K->715K(43712K)] 716K->715K(59136K) [PSPermGen: 5319K->5319K(16384K)], 0.0269456 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 62.544: [GC [PSYoungGen: 15360K->32K(15488K)] 16075K->747K(59200K), 0.0006252 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 69.502: [GC [PSYoungGen: 15072K->32K(14784K)] 15787K->747K(58496K), 0.0003713 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
从上面的日志中,我们可以看到更多和有价值的信息。我们能知道年轻代和老年代(Young & Old)被配置的GC类型(PSYoungGen & PSOlgGen = ParallelScavenge, ParallelGC),由于显式调用了System.GC()而触发了full gc,还有年轻代和老年代内存使用的详细信息,从而可以判断出是否需要调整两者的大小。对于CMS垃圾收集器,可以记录CMS整个阶段的初始标记暂停时间和重新标记暂停时间(Initial Mark pause time & Remark pause time)。
通过这个选项,我们可以获得以下日志:
2012-11-08T22:31:12.310+0100: 8.250: [GC [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0007445 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:20.526+0100: 16.466: [GC [PSYoungGen: 16616K->136K(19136K)] 16616K->136K(62848K), 0.0008255 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:28.503+0100: 24.444: [GC [PSYoungGen: 16584K->152K(19136K)] 16584K->152K(62848K), 0.0007196 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 2012-11-08T22:31:36.497+0100: 32.439: [GC [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0007185 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:44.565+0100: 40.507: [GC [PSYoungGen: 16600K->152K(16256K)] 16600K->152K(59968K), 0.0007928 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:52.694+0100: 48.637: [GC [PSYoungGen: 16216K->152K(15872K)] 16216K->152K(59584K), 0.0007599 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:31:58.204+0100: 54.147: [GC [PSYoungGen: 15832K->192K(15552K)] 15832K->620K(59264K), 0.0072012 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 2012-11-08T22:31:59.999+0100: 55.942: [GC [PSYoungGen: 4932K->64K(15424K)] 5360K->716K(59136K), 0.0015449 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:32:00.000+0100: 55.944: [Full GC (System) [PSYoungGen: 64K->0K(15424K)] [PSOldGen: 652K->716K(43712K)] 716K->716K(59136K) [PSPermGen: 5311K->5311K(16384K)], 0.0273445 secs] [Times: user=0.03 sys=0.00, real=0.03 secs] 2012-11-08T22:32:07.453+0100: 63.397: [GC [PSYoungGen: 15360K->32K(15488K)] 16076K->748K(59200K), 0.0003439 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2012-11-08T22:32:14.695+0100: 70.640: [GC [PSYoungGen: 15072K->32K(14784K)] 15788K->748K(58496K), 0.0007333 secs]
如果要去掉JVM运行时间(elapsed time)的话,我们可以使用-XX:-PrintGCTimeStamps选项,该选项默认被-Xloggc选项激活
通过这个选项,我们可以获得以下日志:
8.494: [GC8.496: [SoftReference, 0 refs, 0.0000084 secs]8.496: [WeakReference, 3 refs, 0.0000061 secs]8.496: [FinalReference, 6 refs, 0.0000117 secs]8.496: [PhantomReference, 0 refs, 0.0000042 secs]8.496: [JNI Weak Reference, 0.0000034 secs] [PSYoungGen: 16448K->168K(19136K)] 16448K->168K(62848K), 0.0017036 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 16.874: [GC16.874: [SoftReference, 0 refs, 0.0000050 secs]16.874: [WeakReference, 1 refs, 0.0000034 secs]16.874: [FinalReference, 4 refs, 0.0000036 secs]16.874: [PhantomReference, 0 refs, 0.0000028 secs]16.874: [JNI Weak Reference, 0.0000028 secs] [PSYoungGen: 16616K->152K(19136K)] 16616K->152K(62848K), 0.0005199 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 24.889: [GC24.890: [SoftReference, 0 refs, 0.0000078 secs]24.890: [WeakReference, 1 refs, 0.0000053 secs]24.890: [FinalReference, 4 refs, 0.0000056 secs]24.890: [PhantomReference, 0 refs, 0.0000039 secs]24.890: [JNI Weak Reference, 0.0000036 secs] [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0008915 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 32.829: [GC32.830: [SoftReference, 0 refs, 0.0000084 secs]32.830: [WeakReference, 1 refs, 0.0000050 secs]32.830: [FinalReference, 4 refs, 0.0000056 secs]32.830: [PhantomReference, 0 refs, 0.0000045 secs]32.830: [JNI Weak Reference, 0.0000045 secs] [PSYoungGen: 16600K->152K(19136K)] 16600K->152K(62848K), 0.0009845 secs]
通过以上日志,可以帮助我们排查指定引用(special references)比如Weak, Soft, Phantom & JNI所引起的问题。
通过这个选项,我们可以获得以下日志:
8.654: [GC 8.655: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 187568 bytes, 187568 total : 17472K->190K(19648K), 0.0022117 secs] 17472K->190K(63360K), 0.0023006 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] 17.087: [GC 17.087: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 80752 bytes, 80752 total - age 2: 166752 bytes, 247504 total : 17662K->286K(19648K), 0.0036440 secs] 17662K->286K(63360K), 0.0037619 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 25.491: [GC 25.491: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 104008 bytes, 104008 total - age 2: 34256 bytes, 138264 total - age 3: 166752 bytes, 305016 total : 17758K->321K(19648K), 0.0035331 secs] 17758K->321K(63360K), 0.0036424 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 34.745: [GC 34.746: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 34400 bytes, 34400 total - age 2: 104008 bytes, 138408 total - age 3: 34256 bytes, 172664 total - age 4: 166752 bytes, 339416 total : 17793K->444K(19648K), 0.0040891 secs] 17793K->444K(63360K), 0.0042000 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 43.215: [GC 43.215: [ParNew Desired survivor size 1114112 bytes, new threshold 15 (max 15) - age 1: 138808 bytes, 138808 total - age 2: 34400 bytes, 173208 total - age 3: 34264 bytes, 207472 total - age 4: 34256 bytes, 241728 total - age 5: 166752 bytes, 408480 total : 17916K->586K(19648K), 0.0048752 secs] 17916K->586K(63360K), 0.0049889 secs]
上面日志输出了JVM在每次新生代GC(minor GC,包括Survivor spaces)后,幸存区中对象的年龄分布。
通过这个选项,我们可以获得以下日志:
{Heap before GC invocations=1 (full 0): PSYoungGen total 19136K, used 16448K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 100% used [0x33f20000,0x34f30000,0x34f30000) from space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) to space 2688K, 0% used [0x34f30000,0x34f30000,0x351d0000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1715K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561ccc8,0x06470000) 8.304: [GC [PSYoungGen: 16448K->228K(19136K)] 16448K->228K(62848K), 0.0028543 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap after GC invocations=1 (full 0): PSYoungGen total 19136K, used 228K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 0% used [0x33f20000,0x33f20000,0x34f30000) from space 2688K, 8% used [0x34f30000,0x34f69100,0x351d0000) to space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1715K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561ccc8,0x06470000) } {Heap before GC invocations=2 (full 0): PSYoungGen total 19136K, used 16676K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 100% used [0x33f20000,0x34f30000,0x34f30000) from space 2688K, 8% used [0x34f30000,0x34f69100,0x351d0000) to space 2688K, 0% used [0x351d0000,0x351d0000,0x35470000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1721K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561e620,0x06470000) 16.577: [GC [PSYoungGen: 16676K->261K(19136K)] 16676K->261K(62848K), 0.0021589 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Heap after GC invocations=2 (full 0): PSYoungGen total 19136K, used 261K [0x33f20000, 0x35470000, 0x49470000) eden space 16448K, 0% used [0x33f20000,0x33f20000,0x34f30000) from space 2688K, 9% used [0x351d0000,0x352115f0,0x35470000) to space 2688K, 0% used [0x34f30000,0x34f30000,0x351d0000) PSOldGen total 43712K, used 0K [0x09470000, 0x0bf20000, 0x33f20000) object space 43712K, 0% used [0x09470000,0x09470000,0x0bf20000) PSPermGen total 16384K, used 1721K [0x05470000, 0x06470000, 0x09470000) object space 16384K, 10% used [0x05470000,0x0561e620,0x06470000)
我们可以看到每次minor 或者 Full GC前后,各个空间(eden, from & to survivors, old & perm)的使用情况。
通过这个选项,当应用终止时,我们可以看到如下标准输出:
vmop [threads: total initially_running wait_to_block] [time: spin block sync cleanup vmop] page_trap_count 4.162: EnableBiasedLocking [ 8 0 0] [0 0 0 0 0] 0 8.466: ParallelGCFailedAllocation [ 8 0 0] [0 0 0 0 2] 0 23.927: ParallelGCFailedAllocation [ 8 0 0] [0 0 0 0 2] 0 31.039: RevokeBias [ 9 0 1] [0 0 0 0 0] 0 31.377: RevokeBias [ 10 0 1] [0 0 0 0 0] 0 31.388: RevokeBias [ 11 1 1] [2 0 2 0 0] 0 31.390: ParallelGCFailedAllocation [ 11 0 0] [0 0 0 0 4] 0 31.452: RevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.487: BulkRevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.515: RevokeBias [ 12 0 1] [0 0 0 0 0] 0 31.550: BulkRevokeBias [ 12 0 0] [0 0 0 0 0] 0 32.572: ThreadDump [ 12 0 1] [0 0 0 0 0] 0 38.572: ThreadDump [ 13 0 2] [0 0 0 0 0] 0 39.042: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 6] 0 39.575: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 39.775: ParallelGCSystemGC [ 13 0 0] [0 0 0 0 35] 0 40.574: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 45.519: HeapDumper [ 13 0 0] [0 0 0 0 93] 0 45.626: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.575: no vm operation [ 13 0 0] [0 0 0 0 0] 0 50.576: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.875: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 50.881: GC_HeapInspection [ 13 0 1] [0 0 0 0 9] 0 51.577: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 82.281: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 4] 0 82.578: ThreadDump [ 13 0 1] [0 0 0 0 0] 0 88.578: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 88.999: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 4] 0 94.580: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 95.439: ParallelGCFailedAllocation [ 13 0 0] [0 0 0 0 2] 0 95.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 101.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 102.276: ParallelGCFailedAllocation[ 13 0 0] [0 0 0 0 5] 0 102.579: ThreadDump [ 13 0 0] [0 0 0 0 0] 0 133.776: no vm operation [ 12 0 1] [0 0 0 0 332] 0 Polling page always armed ThreadDump 103 HeapDumper 1 GC_HeapInspection 1 ParallelGCFailedAllocation 16 ParallelGCSystemGC 1 EnableBiasedLocking 1 RevokeBias 57 BulkRevokeBias 2 0 VM operations coalesced during safepoint Maximum sync time 2 ms Maximum vm operation time (except for Exit VM operation) 93 ms
这些统计输出表示执行VM操作(vm operation)所花费的时间,也就意味着在VM操作期间所有的线程是停止的(比如STW GC)。
通过这个选项,我们可以获得以下日志:
Total time for which application threads were stopped: 0.0000257 seconds 6.253: [GC [PSYoungGen: 16448K->565K(19136K)] 16448K->565K(62848K), 0.0042058 secs] [Times: user=0.03 sys=0.00, real=0.00 secs] Total time for which application threads were stopped: 0.0045092 seconds Total time for which application threads were stopped: 0.0000916 seconds Total time for which application threads were stopped: 0.0047405 seconds Total time for which application threads were stopped: 0.0000869 seconds Total time for which application threads were stopped: 0.0000285 seconds Total time for which application threads were stopped: 0.0002229 seconds Total time for which application threads were stopped: 0.0002159 seconds 13.310: [GC [PSYoungGen: 17013K->798K(19136K)] 17013K->798K(62848K), 0.0058890 secs] [Times: user=0.00 sys=0.00, real=0.01 secs] Total time for which application threads were stopped: 0.0064142 seconds 26.148: [GC [PSYoungGen: 11951K->908K(19136K)] 11951K->908K(62848K), 0.0060538 secs] [Times: user=0.03 sys=0.00, real=0.01 secs] 26.154: [Full GC (System) [PSYoungGen: 908K->0K(19136K)] [PSOldGen: 0K->876K(43712K)] 908K->876K(62848K) [PSPermGen: 5363K->5363K(16384K)], 0.0385560 secs] [Times: user=0.03 sys=0.00, real=0.04 secs] Total time for which application threads were stopped: 0.0450568 seconds 39.332: [GC [PSYoungGen: 16448K->150K(16256K)] 17349K->1051K(33664K), 0.0017511 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] Total time for which application threads were stopped: 0.0020282 seconds
这个日志告诉我们在VM操作(比如GC, thread dump, heap dump, revoke bias, deoptimization等)期间所有线程停止的实际时间。
正如你所看到的在GC过程中GC可能停止线程多一点,一个线程到达安全点(safepoint)所需的时间可能会增加开销。
-XX:+HeapDumpBeforeFullGC 指定在Full GC之后生成一个堆快照,这可以帮助我们排查在一个时间段Full GC发生的原因
-XX:+PrintClassHistogramBeforeFullGC 指定在GC日志中输出类的直方图(number of instances per class with bytes allocated),这是一个轻量级的堆快照
-XX:+HeapDumpOnOutOfMemoryError 指定在内存溢出时(OutOfMemory)生成堆快照,这可以帮助我们判断哪一个类或者对象导致了内存溢出
-XX:HeapDumpPath=path 指定堆快照输出的路径(java_pid
##监控(Monitoring)
有些有用的选项可以帮助我们监视和GC无关的JVM行为。
通过这个选项,我们可以获得以下标准输出:
1 java.lang.Object::<init> (1 bytes) --- n java.lang.System::currentTimeMillis (static) 2 java.util.ArrayList::add (29 bytes) 3 java.util.ArrayList::ensureCapacity (58 bytes) --- n java.lang.Thread::sleep (static) 1% com.bempel.sandbox.TestJIT::allocate @ 7 (84 bytes) 4 com.bempel.sandbox.TestJIT::call (10 bytes) 5 java.util.ArrayList::contains (14 bytes) 6 java.util.ArrayList::indexOf (67 bytes) 4 made not entrant (2) com.bempel.sandbox.TestJIT::call (10 bytes) 7 com.bempel.sandbox.TestJIT::call (10 bytes) 8 java.util.concurrent.CopyOnWriteArrayList::contains (22 bytes) 9 java.util.concurrent.CopyOnWriteArrayList::indexOf (63 bytes) 2% com.bempel.sandbox.TestJIT::main @ 60 (83 bytes)
<task_queued compile_id='4' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <task_queued compile_id='5' method='java/util/ArrayList contains (Ljava/lang/Object;)Z' bytes='14' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <task_queued compile_id='6' method='java/util/ArrayList indexOf (Ljava/lang/Object;)I' bytes='67' count='5000' backedge_count='1' iicount='10000' stamp='20.696' comment='count' hot_count='10000'/> <writer thread='2508'/> <nmethod compile_id='5' compiler='C2' level='2' entry='0x024c8a00' size='788' address='0x024c8908' relocation_offset='208' code_offset='248' stub_offset='472' consts_offset='487' scopes_data_offset='496' scopes_pcs_offset='636' dependencies_offset='748' handler_table_offset='752' nul_chk_table_offset='776' oops_offset='488' method='java/util/ArrayList contains (Ljava/lang/Object;)Z' bytes='14' count='7000' backedge_count='1' iicount='12000' stamp='20.702'/> <writer thread='1392'/> <nmethod compile_id='4' compiler='C2' level='2' entry='0x024c7a40' size='776' address='0x024c7948' relocation_offset='208' code_offset='248' stub_offset='568' consts_offset='583' scopes_data_offset='604' scopes_pcs_offset='668' dependencies_offset='748' nul_chk_table_offset='756' oops_offset='584' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='7000' backedge_count='1' iicount='12000' stamp='20.703'/> <writer thread='2508'/> <nmethod compile_id='6' compiler='C2' level='2' entry='0x024c9700' size='728' address='0x024c9608' relocation_offset='208' code_offset='248' stub_offset='472' consts_offset='487' scopes_data_offset='492' scopes_pcs_offset='576' dependencies_offset='688' handler_table_offset='692' nul_chk_table_offset='716' oops_offset='488' method='java/util/ArrayList indexOf (Ljava/lang/Object;)I' bytes='67' count='7000' backedge_count='1' iicount='12000' stamp='20.707'/> <writer thread='3508'/> <uncommon_trap thread='3508' reason='class_check' action='maybe_recompile' compile_id='4' compiler='C2' level='2' stamp='21.700'> <jvms bci='3' method='com/bempel/sandbox/TestJIT call (Ljava/util/List;)V' bytes='10' count='7000' backedge_count='1' iicount='12000'/> </uncommon_trap>
这可以帮助我们理解为什么有一些方法没有被优化(deoptimized)。
-XX:+LogVMOutput 记录所有的VM操作输出到当前目录的hotspot.log文件里,需要和-XX:+UnlockDiagnosticVMOptions选项搭配使用
-XX:LogFile=file 指定hotpot.log文件的路径和名称,需要和-XX:+UnlockDiagnosticVMOptions选项搭配使用
-XX:+PrintAssembly 输出被JIT编译器编译后方法的分解形式,可以看我的另一篇 文章 ,需要和-XX:+UnlockDiagnosticVMOptions选项搭配使用
-XX:ErrorFile=file 指定JVM发生崩溃时(JVM crash),hs_err_
-Dcom.sun.management.jmxremote -Dcom.sun.management.jmxremote.port=1234 -Dcom.sun.management.jmxremote.ssl=false -Dcom.sun.management.jmxremote.authenticate=false 激活JMX远程连接,使我们可以使用VisualVM等工具远程连接JVM
以下选项控制JIT编译器的行为:
-XX:CICompilerCount=n 指定JIT编译器用来编译方法的线程数量
-XX:CompileThreshold=n 指定一个方法的调用次数,以使HotSpot和JIT 编译器能编译它
-Xcomp 指定JVM在第一次使用时把所有的字节码编译成本地代码. (即CompileThreshold=1)
-Xbatch 在前台编译方法,直到编译完成方法才能执行
-Xint 仅仅使用解释模式,不激活JIT编译器 (即CompileThreshold=0)
以下选项能启用或者禁用特定类型的JIT优化(JIT optimizations):
-XX:+UseCompressedStrings 指定用byte数组(byte array)来处理String对象而不是用char数组(char array),这虽然在一定程度上能减少堆内存的消耗,但是也要注意副作用(Beware of side effects),默认情况下禁用
-XX:+UseBiasedLocking 指定启用偏向锁(Biased Locking),JDK1.6开始默认打开的偏向锁,会尝试把锁赋给第一个访问它的线程,取消同步块上的synchronized原语。如果始终只有一条线程在访问它,就成功略过同步操作以获得性能提升。
但一旦有第二条线程访问这把锁,JVM就要撤销偏向锁恢复到未锁定线程的状态,详见 JVM的Stop The World,安全点,黑暗的地底世界, 可以看到不少RevokeBiasd的纪录,像GC一样,会Stop The World的干活,虽然只是很短很短的停顿,但对于多线程并发的应用,取消掉它反而有性能的提升和延时的极微的缩短,所以Cassandra就取消了它。(引自: 唯品会资深架构师给你的 JVM 调优建议 偏向锁部分)
-XX:+TraceBiasedLocking 提供关于BiasedLocking优化的额外的信息。默认情况下禁用
-XX:+PrintBiasedLockingStatistics 提供关于BiasedLocking优化的额外的信息。默认情况下禁用
-XX:+Inline 启用内联方法调用,默认情况下启用
-XX:+AggressiveOpts 使一些新的优化不默认启用。如果优化是好的,他们将在下一版本的JDK中启用
编译自: The useful JVM options 。