JVM参数_desired survivor size new threshold 6 (max 6)-CSDN博客

本文链接：https://blog.csdn.net/xiaocszn/article/details/81709032

1. -XX:+PrintGCTimeStamps

几乎所有的资料上说到打印JVM GC log的时候都会推荐一个参数： -XX:+PrintGCTimeStamps，可该选项打印的是JVM以启动时间为基准的相对时间，对于troubleshooting来说非常困难。早在07年的时候就有人提出来并且早已fix，用法是使用 PrintGCDateStamps 代替PrintGCTimeStamps，打印出来的就是真实的日期了[1]

2. -XX:+PrintTenuringDistribution

打印survivor中的对象年龄分布，for example:

Desired survivor size 26836992 bytes, new threshold 6 (max 6)
- age 1: 318760 bytes, 318760 total
- age 2: 154768 bytes, 473528 total
- age 3: 1080752 bytes, 1554280 total
- age 4: 216144 bytes, 1770424 total

Desired survivor size 26836992 bytes表示一个survivor的空间大小

岁数为1的对象有318760字节，岁数为2的对象有154768字节，后面的total是前面的累加，max 6表示-XX:MaxTenuringThreshold的值，new threshold 6表示JVM实际使用的值，由于可能存在Survivor空间过小导致对象提前晋升到老年代的情况，所以JVM通过一系列估算后采用的实际的值可能会比设定的值小[2]

3. -XX:+PrintHeapAtGC

加入这个属性后，可以看到如下的类似GC log：

{Heap before GC invocations=49 (full 1):
 par new generation   total 471872K, used 400221K [0x0000000770000000, 0x0000000790000000, 0x0000000790000000)
  eden space 419456K,  94% used [0x0000000770000000, 0x00000007884b3240, 0x00000007899a0000)
  from space 52416K,   4% used [0x000000078ccd0000, 0x000000078cef42d0, 0x0000000790000000)
  to   space 52416K,   0% used [0x00000007899a0000, 0x00000007899a0000, 0x000000078ccd0000)
 concurrent mark-sweep generation total 1572864K, used 857684K [0x0000000790000000, 0x00000007f0000000, 0x00000007f0000000)
 concurrent-mark-sweep perm gen total 152576K, used 152531K [0x00000007f0000000, 0x00000007f9500000, 0x0000000800000000)
2017-06-15T16:00:17.601+0800: 236.046: [GC 236.046: [ParNew
Desired survivor size 26836992 bytes, new threshold 6 (max 6)
- age   1:     318760 bytes,     318760 total
- age   2:     154768 bytes,     473528 total
- age   3:    1080752 bytes,    1554280 total
- age   4:     216144 bytes,    1770424 total
: 400221K->2591K(471872K), 0.7579370 secs] 1257905K->1252628K(2044736K), 0.7583240 secs] [Times: user=2.39 sys=0.57, real=0.76 secs] 
Heap after GC invocations=50 (full 1):
 par new generation   total 471872K, used 2591K [0x0000000770000000, 0x0000000790000000, 0x0000000790000000)
  eden space 419456K,   0% used [0x0000000770000000, 0x0000000770000000, 0x00000007899a0000)
  from space 52416K,   4% used [0x00000007899a0000, 0x0000000789c27ed8, 0x000000078ccd0000)
  to   space 52416K,   0% used [0x000000078ccd0000, 0x000000078ccd0000, 0x0000000790000000)
 concurrent mark-sweep generation total 1572864K, used 1250036K [0x0000000790000000, 0x00000007f0000000, 0x00000007f0000000)
 concurrent-mark-sweep perm gen total 152576K, used 152531K [0x00000007f0000000, 0x00000007f9500000, 0x0000000800000000)
}

Heap before GC invocations=49 (full 1)

49是gc总数，1是full gc总数

par new generation total 471872K, used 400221K [0x0000000770000000, 0x0000000790000000, 0x0000000790000000)

par new generation是垃圾回收器的名称，total总容量，used已使用空间，后面的三个数字指的是[申请的虚拟空间下限,已分配的虚拟空间上限,申请的虚拟空间上限)，也就是虚拟内存的地址，画出来可以发现几个年代的内存区域基本是连续的[3]

4. -XX:+PrintGCDetails

只要设置-XX:+PrintGCDetails 就会自动带上-verbose:gc和-XX:+PrintGC

2014-02-28T11:59:00.638+0800: 766.537:[GC2014-02-28T11:59:00.638+0800: 766.537: [ParNew: 1770882K->212916K(1835008K), 0.0834220 secs] 5240418K->3814487K(24903680K), 0.0837310 secs] [Times: user=1.12 sys=0.02, real=0.08 secs]

2014-02-28T11:59:00 ...（时间戳）:[GC（Young GC）（时间戳）:[ParNew（使用ParNew作为年轻代的垃圾回收期）:

1770882K（年轻代垃圾回收前的大小）->212916K（年轻代垃圾回收以后的大小）(1835008K)（年轻代的capacity）, 0.0834220 secs（回收时间）]
5240418K（整个heap垃圾回收前的大小）->3814487K（整个heap垃圾回收后的大小）(24903680K)（heap的capacity）, 0.0837310secs（回收时间）]
[Times: user=1.12（Young GC用户耗时） sys=0.02（Young GC系统耗时）, real=0.08 secs（Young GC实际耗时）]

上面是一个新生代回收的日志示例，下面给一个老年代回收的示例：[4]

2014-02-28T23:58:42.314+0800: 25789.661: [GC [1 CMS-initial-mark: 17303356K(23068672K)] 18642315K(24903680K), 1.0400410 secs] [Times: user=1.04 sys=0.00, real=1.04 secs] 
2014-02-28T23:58:43.354+0800: 25790.701: [CMS-concurrent-mark-start] 
2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-mark: 0.315/0.363 secs] [Times: user=1.64 sys=0.02, real=0.37 secs] 
2014-02-28T23:58:43.717+0800: 25791.064: [CMS-concurrent-preclean-start] 
2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-preclean: 0.181/0.190 secs] [Times: user=0.20 sys=0.01, real=0.19 secs] 
2014-02-28T23:58:43.907+0800: 25791.254: [CMS-concurrent-abortable-preclean-start] CMS: abort preclean due to time 2014-02-28T23:58:49.082+0800: 25796.429: [CMS-concurrent-abortable-preclean: 5.165/5.174 secs] [Times: user=5.40 sys=0.04, real=5.17 secs] 
2014-02-28T23:58:49.083+0800: 25796.430: [GC[YG occupancy: 1365142 K (1835008 K)]2014-02-28T23:58:49.083+0800: 25796.430: [Rescan (parallel) , 0.9690640 secs]2014-02-28T23:58:50.052+0800: 25797.399: [weak refs processing, 0.0006190 secs]2014-02-28T23:58:50.053+0800: 25797.400: [scrub string table, 0.0006290 secs] [1 CMS-remark: 17355150K(23068672K)] 18720292K(24903680K), 0.9706650 secs] [Times: user=16.49 sys=0.06, real=0.97 secs] 
2014-02-28T23:58:50.054+0800: 25797.401: [CMS-concurrent-sweep-start] 
2014-02-28T23:58:51.940+0800: 25799.287: [CMS-concurrent-sweep: 1.875/1.887 secs] [Times: user=2.03 sys=0.03, real=1.89 secs] 
2014-02-28T23:58:51.941+0800: 25799.288: [CMS-concurrent-reset-start] 
2014-02-28T23:58:52.067+0800: 25799.414: [CMS-concurrent-reset: 0.127/0.127 secs] [Times: user=0.13 sys=0.00, real=0.13 secs] 
2014-03-01T00:00:36.293+0800: 25903.640: [GC2014-03-01T00:00:36.293+0800: 25903.640: [ParNew: 1805234K->226801K(1835008K), 0.1020510 secs] 10902912K->9434796K(24903680K), 0.1023150 secs] [Times: user=1.35 sys=0.02, real=0.10 secs] 
2014-03-01T00:07:13.559+0800: 26300.906: [GC2014-03-01T00:07:13.559+0800: 26300.906: [ParNew: 1799665K->248991K(1835008K), 0.0876870 secs] 14086673K->12612462K(24903680K), 0.0879620 secs] [Times: user=1.24 sys=0.01, real=0.09 secs]

5. -XX:+PrintGCApplicationStoppedTime

该选项字面意思有歧义，它指的并不是STW的时间，而是应用在safepoints里停留的时间，而safepoints并不是垃圾回收的时候才会进入，以下这些情况也会进入：

Deoptimization
Biased lock revocation
Thread dump
Heap inspection
Class redifinition
etc. (see the list)

所以这个选项基本没啥用[5]

6. -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1

5.141: RevokeBias [ 13 0 2 ] [ 0 0 0 0 0 ] 0 Total time for which application threads were stopped: 0.0000782 seconds, Stopping threads took: 0.0000269 seconds

关于安全点的信息是按照如下的顺序进行显示的：

JVM启动之后所经历的毫秒数（上例中是5.141）
触发这次暂停的操作名（RevokeBias）。如果你看见”no vm operation”，就说明这是一个”保证安全点”。JVM默认每秒会触发一次安全点来处理那些非紧急的排队的操作。GuaranteedSafepointInterval选项可以用来调整这一行为（设置为0的话就会禁用该功能）
停在安全点的线程的数量（13）
在安全点开始时仍在运行的线程的数量（0）
虚拟机操作开始执行前仍处于阻塞状态的线程的数量（2）
到达安全点时的各个阶段以及执行操作所花的时间（0）

因此我们可以看出，使用了偏向锁会导致大量的STW暂停，尽管它们只花了几十毫秒。在如今这个大量使用并发的年代，禁用它们也不是什么罕见的事情。

这个选项的日志输出似乎并不是gc.log里，而是控制台，使用-XX:+LogVMOutput -XX:LogFile=vm.log这两个选项可以重定向这些日志