Java8 is used as an example

GC environment simulation

First we present the following code to trigger the GC

Public static void main(String[] args) {// Create 100 threads every 100 milliseconds, each thread creates a 1M object, Per 100 ms for 100 m heap space Executors newScheduledThreadPool (1) the scheduleAtFixedRate (() - > {for(int i = 0; i < 100; I++) {new Thread(() -> {try {// apply 1M byte[] temp = new byte[1024 * 1024]; Thread.sleep(new Random().nextInt(1000)); Catch (InterruptedException e) {e.printStackTrace(); } }).start(); } }, 1000, 100, TimeUnit.MILLISECONDS); }Copy the code

The scenario we want to simulate is that the Young generation is constantly Young GC, and some objects are promoted to the old generation, triggering the Full GC when the old generation runs out of space.

Program logic: Create 100 threads every 100 milliseconds, each thread creates a 1M object, that is, apply 100M heap space every 100ms. The reason why each thread sleeps randomly for 1s is to avoid the object being born and dying, and to ensure that some objects can be promoted to the old age, so as to trigger the Young GC and Full GC better. Note that if the sleep time is too large, it will cause OOM, and if it is too small, it will be difficult to trigger the Full GC.

Description VM parameters

Start the Java process: java -Xms200m -Xmx200m -Xmn100m -verbose:gc -XX:+PrintGCDetails -Xloggc:./gc.log -XX:+PrintGCDateStamps -jar Demo – 0.0.1 – the SNAPSHOT. The jar

-xms200m -XMx200m Minimum/maximum heap memory 200M

-Xmn100m The memory of the young generation is 100M

-verbose:gc Enables GC logs

-xx :+PrintGCDetails -xloggc :./gc.log -xx :+PrintGCDateStamps Enters the GC log details into gc.log

Jmap analysis

JCMD gets the Id of our Java process: 6264

Jmap-heap 6264 Displays heap information

On the first check, we found that the Eden area was 98M, and S0 and S1 were 1M

On the second check, the Eden area is 99M, and S0 and S1 are 0.5M

The ratio of Eden zone to Survivor zone changes dynamically and is not the default 8:1:1.

The collector is the Parallel Insane +Parallel Old collector. The -xx :+UseAdaptiveSizePolicy is on by default. The ratio of Eden to Survivor is adjusted according to the GC.

We add the parameter to turn off the young generation adaptive and set the young generation ratio to 8:1:1

-XX:-UseAdaptiveSizePolicy -XX:SurvivorRatio=8

In addition, to trigger FULL GC as soon as possible, we added virtual machine parameters

-XX:MaxTenuringThreshold=10

The promotion age has been changed from the default 15 to 10, making it easier for the younger generation to advance to the older generation

Restart the VM to view jMAP

The young generation

  • 51M of the 80M in Eden area has been used, and the current usage is 63.8%

  • 10M in S0 area has been used 0.43m, with a utilization rate of 4.37%

  • The 10M usage in S1 is empty

The old s

  • 18.39M of 100M has been used, and the utilization rate is 18.9%

Analyze GC log content

Take a look at our output of the GC log, gc.log, and select two of them

2019-06-09T02:55:993 + 0800:330.811: [Allocation Failure for GC] [PSYoungGen: Secs] [Times: Times: 328k -> 328k [Times: 328k] 328K -> 328k [Times: 328k] 328k -> 328k [Times: 328k] 328k -> 328k [Times: 328k] 328k -> 328k [Times: 328k] Sys =0.00, sys=0.00, real=0.00 384K->0K(92160K)] [ParOldGen: 102331K->5368K(102400K)] 102715K->5368K(194560K), [Metaspace: [Times: user= 0.03sys =0.00, real= 0.03secs] [Times: user= 0.03sys =0.00, real= 0.03secs]

Young GC

[PSYoungGen: 82004K->384K(92160K)] 184303K->102715K(194560K), 0.0035647 secs] [Times: User sys = = 0.00 0.00, real = 0.00 secs]

Explanation:

  • Young generation GC: [young generation 80.08m before GC -> 0.37m after GC (total size of young generation 90M)] Heap before GC 179.98m -> heap after GC 100.3m (total size of heap 190M), time]

  • The total size of the young generation is 90M instead of 100M. Here I understand that the maximum size of the young generation is 90M

  • 100M x 80%=80M indicates the Eden area size

  • 80M x 80% = 64M By default, if the Eden area usage exceeds 80%, YoungGC will be triggered

Full GC

[Full GC (Ergonomics) [PSYoungGen: 384K->0K(92160K)] [ParOldGen: 102331K->5368K(102400K)] 102715K->5368K(194560K), [Metaspace: 16941K->16914K(1064960K)], 0.0213953 secs] [Times: User sys = = 0.02 0.00, real = 0.02 secs]

Explanation:

  • [pre-GC: 0.375m -> post-GC: 0M [pre-GC: 99.93m -> post-GC: 5.24m] pre-GC: 100.3m -> post-GC: 5.24m [pre-GC: 0.375m -> post-GC: 5.24m] 16.5(total size of metadata area 1040M)]

  • It can be inferred that the FullGC was caused by the lack of space for the promotion of the younger generation to the older generation

Analyze using visual tools

Here we use gceasy. IO/to analyze

(1) Statistics on the maximum available space and peak value of young generation, old age, metadata area. Here, the metadata area size is not configured in our VM parameters, so the default value is 1040M

(2) Throughput, AVERAGE GC delay, maximum delay and delay interval statistics

(3) Real-time analysis of the heap size, the red position is FullGC occurred, resulting in a straight decline in the total heap

(4) Statistics of total amount and time of GC space

(5) Various GC time, GC times, GC total amount and other indicators

conclusion

GC log analysis can help us monitor GC health at a macro level. On the one hand, frequent FullGC will cause serious performance problems (STW); on the other hand, too frequent GC, that is, GC occupies too much of the normal operation of the system and the throughput is low, is a waste of performance resources to a certain extent. If the system has performance problems, according to the GC analysis of various indicators as a reference, we can also do some tuning in the program or virtual machine parameters.