Shulou(Shulou.com)06/02 Report--

This article mainly explains "what is the relevant knowledge of JAVA GC log". Interested friends may wish to have a look. The method introduced in this paper is simple, fast and practical. Next, let the editor take you to learn "what is the relevant knowledge of the JAVA GC log?"

GC environment simulation

First of all, we give the following code to trigger GC

Public static void main (String [] args) {/ / create 100 threads every 100ms, each thread creates a 1m object, that is, each 100ms requests 100m heap space Executors.newScheduledThreadPool (1) .scheduleAtFixedRate (()-> {for (int I = 0; I)

{try {/ / apply for 1Mbyte [] temp = new byte [1024 * 1024]; Thread.sleep (new Random (). NextInt (1000)); / / Random sleep within 1 second} catch (InterruptedException e) {e.printStackTrace ();}}). Start ();}, 1000, 100, TimeUnit.MILLISECONDS);}

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

Program logic: create 100 threads every 100 milliseconds, and each thread creates a 1m object, that is, 100m heap space per 100ms. The reason why each thread sleeps randomly for 1 second is to prevent objects from dying, to ensure that some objects can be promoted to the old age, and to better trigger Young GC and Full GC. Note that if the sleep time is large, it will lead to OOM. If it is small, it is difficult to trigger FULL GC.

Virtual machine parameter interpretation

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

-Xms200m-Xmx200m minimum / maximum heap memory 200m

-Xmn100m younger generation memory 100m

-verbose:gc enables GC log

-XX:+PrintGCDetails-Xloggc:./gc.log-XX:+PrintGCDateStamps enters GC log details into gc.log

Jmap analysis

Jcmd gets the Id:6264 of our Java process

Jmap-heap 6264 to view heap information

The first time we checked, we found that the Eden area is 98m S0 and S1 is 1m.

For the second time, the Eden area is 99m focus S0 and S1 is 0.5m.

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

It turns out that we use the default garbage collector Parallel Scavenge+Parallel Old combination, under which-XX:+UseAdaptiveSizePolicy is enabled by default, that is, the ratio of Eden area to Survivor area adaptively changes according to GC.

We add parameters to turn off the adaptation of the young generation, and the proportion of the young generation is set to 8:1:1

-XX:-UseAdaptiveSizePolicy-XX:SurvivorRatio=8

In addition, in order 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 be promoted to the old age.

Restart the virtual machine to view jmap

Young generation

Eden zone 80m has used 51m, current utilization rate 63.8% S0 area 10m has used 0.43m, utilization rate 4.37% S1 area 10m utilization rate is empty

Old age

100m has used 18.39m, with a utilization rate of 18.9%

Content Analysis of GC Log

Take a look at our output GC log gc.log and select two paragraphs

2019-06-09T02:55:30.993+0800: 330.811: [GC (Allocation Failure) [PSYoungGen: 82004K-> 384K (92160K)] 184303K-> 102715K (194560K), 0.0035647 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-06-09T02:55:30.997+0800: 330.815: [Full GC (Ergonomics) [PSYoungGen: 384K-> 0K (92160K)] [ParOldGen: 102331K-> 5368K (102400K)] 102715K-> 5368K (194560K), [Metaspace: 16941K-> 16914K (1064960K)] 0.0213953 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

Young GC

2019-06-09T02:55:30.993+0800: 330.811: [GC (Allocation Failure) [PSYoungGen: 82004K-> 384K (92160K)] 184303K-> 102715K (194560K), 0.0035647 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 2019-06-09T02:55:30.997+0800: 330.815: [Full GC (Ergonomics) [PSYoungGen: 384K-> 0K (92160K)] [ParOldGen: 102331K-> 5368K (102400K)] 102715K-> 5368K (194560K), [Metaspace: 16941K-> 16914K (1064960K)] 0.0213953 secs] [Times: user=0.02 sys=0.00, real=0.02 secs]

Explanation:

Young generation GC: [GC before last year light generation 80.08M-> GC rear 0.37m (young generation total size 90m)] GC front stack 179.98M-> GC rear reactor 100.3m (total heap size 190m), time] in which the young generation total size is 90m instead of 100m. Here I understand that the current maximum application for 90m 100M*80%=80M is the Eden area size 80m 80% = 64m Eden area occupies more than 80% by default, that is, YoungGC will trigger YoungGC.

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=0.02 sys=0.00, real=0.02 secs]

Explanation:

[GC 0.375M-> GC younger generation 0m (total size 90m)] [GC 99.93M > post-GC 5.24m (total size 100m)] GC front stack 100.3m-> GC rear stack 5.24m (total stack size 190m), [metadata area: GC pre-16.5 post-GC 16.5 (total metadata area 1040m)] It can be inferred that the reason for this FullGC is the lack of space for the promotion of the younger generation in the old era.

Using visual tools to analyze

Here we use gceasy.io/ to analyze it.

(1) Statistics the maximum available space and peak value of the younger generation, the old age and the metadata area. Here, the size of the metadata area is not configured in our virtual machine parameters, so the default value is selected.

(2) Statistics of throughput, GC average delay, maximum delay and delay interval

(3) according to the real-time analysis of the size of the heap, the red position is that the FullGC makes the total amount of the heap drop in a straight line.

We will find that the virtual machine triggers a large number of FULL GC in the early stage of startup. My understanding is that all the objects we apply for sleep within a second at random, and most of them have thread references at startup, and the GCRoot is reachable. Triggering FULL GC at startup does not completely clean up old space and keeps triggering FULL GC due to lack of space.

(4) Statistics of total space and time of GC

(5) all kinds of GC time, GC times, total GC and other indicators.

At this point, I believe you have a deeper understanding of "what is the relevant knowledge of the JAVA GC log?" you might as well do it in practice. Here is the website, more related content can enter the relevant channels to inquire, follow us, continue to learn!

Welcome to subscribe "Shulou Technology Information " to get latest news, interesting things and hot topics in the IT industry, and controls the hottest and latest Internet news, technology news and IT industry trends.