Deeper understanding of the JVM – interpret GC logs

preface

This article will show you how to look at the JVM log in practice. It can be difficult to look at the JVM log, it can be easy to say, and it takes time to try and summarize.

In addition, because the actual performance of the code on different machines is not the same! This article uses the jdk1.8.0_221 version, the specific system configuration check:

Summary:

The main content is to explain how to read the log, and the results of different machines are different. The article is more about how to read the parameters:

Parameter Configuration Cases

Configuration Introduction:

  1. The new generation of 5 m
  2. The maximum new generation memory is 5M
  3. The initial heap memory size is 10 MB
  4. Maximum heap memory size is 10 MB
  5. The Cenozoic Eden region size, or survior ratio: 8 represents an 8:1:1 ratio
  6. Use the ParNew+CMS collector

Actual operation:

Do not perform any code tests:

Parameter configuration:

​ -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC

Meanings of parameters:

Here 20M memory space is allocated for the heap, 10M for the new generation, and GC information is printed at the same time. The ratio of allocation is 8:1:1 for the new generation, and finally the Serrial collector is used. Note the Serrial collector.

Code configuration

Starting with the simplest method, we run a Main method without any code

public class MinorGcTest {

    public static void main(String[] args) {}}Copy the code

Note that the following is the log content for running an empty Main method.

Heap
 def new generation   total 9216K, used 3977K [0x00000000fec00000.0x00000000ff600000.0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000.0x00000000fefe27f0.0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000.0x00000000ff400000.0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000.0x00000000ff500000.0x00000000ff600000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000.0x0000000100000000.0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000.0x00000000ff600000.0x00000000ff600200.0x0000000100000000)
 Metaspace       used 3241K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 349K.capacity 388K.committed 512K.reserved 1048576K
Copy the code

Explanation:

First look at the second line: Def new Generation total 9216K, used 3977K, clearly indicates that the Cenozoic total size is 9216K, which is the size of 9M space. Why 9M, because here we calculate 8M Eden region +1M Survior from region. The remaining region of Survior adds up to 10 meters, while only 9 meters of available space is correct according to the replication algorithm.

If you look at Eden Space 8192K, 48% used, you can see that we are using about 4 meters of space without running any code. So what is this 4 meters of space? These objects are actually generated by the JVM itself.

Metaspace stands for Metaspace, and since JDK8 does not have a permanent generation, what JVMS before JDK8 see is different here.

Heap overflow test:

In the case of a heap overflow, what is printed in the GC log? JAVA exception information is ignored because it affects our view of the log:

Parameter configuration:

​ -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails -XX:SurvivorRatio=8 -XX:+UseSerialGC

Code configuration:

byte[] allocation1, allocation2, allocation3, allocation4, allocation5;
allocation1 = new byte[_1MB * 2];
allocation1 = new byte[_1MB * 2];
allocation1 = new byte[_1MB * 1];
allocation3 = new byte[20*_1MB * 2];
Copy the code

Here are the log results:

[GC (Allocation Failure) [DefNew: 7909K->1023K(9216K), 0.0025258 secs] 7909K->3242K(19456K), 0.0025739 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[GC (Allocation Failure) [DefNew: 2131K->0K(9216K), 0.0015020 secs][Tenured: 4266K->2217K(10240K), 0.0030024 secs] 4350K->2217K(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0045414 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC (Allocation Failure) [Tenured: 2217K->2198K(10240K), 0.0017918 secs] 2217 - > 2198 kK(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0018074 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 404K [0x00000000fec00000.0x00000000ff600000.0x00000000ff600000)
  eden space 8192K,   4% used [0x00000000fec00000.0x00000000fec65330.0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000.0x00000000ff400000.0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000.0x00000000ff500000.0x00000000ff600000)
 tenured generation   total 10240K, used 2198K [0x00000000ff600000.0x0000000100000000.0x0000000100000000)
   the space 10240K,  21% used [0x00000000ff600000.0x00000000ff8259d8.0x00000000ff825a00.0x0000000100000000)
 Metaspace       used 3360K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 362K.capacity 388K.committed 512K.reserved 1048576K
Copy the code
[GC (Allocation Failure) [DefNew: 7909K->1023K(9216K), 0.0025258 secs] 7909K->3242K(19456K), 0.0025739 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Copy the code

Let’s look at the first line, where the Serrial collector is used, so you can see that the new generation prints 7909K->1023K(9216K), which means that the total available space is 9216KB, while the garbage occupies 7909K, leaving 1023K after recycling. Part 2:7909K->3242K(19456K), which indicates the reclaimof the entire heap, 19456K indicates the available space of the entire heap, and also from the heap size you can see the reclaimfrom 7909K to the remaining 3242K living objects. [Times: User =0.00 sys=0.00, real=0.00 secs]; user=0.00 sys=0.00, real=0.00 secs]; user=0.00 sys=0.00, real=0.00 secs;

If you look at the log of full GC, you can see that there is almost no space left for the new generation and the old generation, and there is still no room for 20M large objects.

[Full GC (Allocation Failure) [Tenured: 2217K->2198K(10240K), 0.0017918 secs] 2217 - > 2198 kK(19456K), [Metaspace: 3254K->3254K(1056768K)], 0.0018074 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
Copy the code

ParNew + CMS test:

No tests are performed

Parameter configuration:

Notice the combination of parnew+ CMS used at the end

-verbose:gc
-Xms20M
-Xmx20M
-Xmn10M
-XX:+PrintGCDetails
-XX:SurvivorRatio=8
-XX:+UseParNewGC
-XX:+UseConcMarkSweepGC
Copy the code

Code configuration:

Again, no code is executed, and the result is similar to other collectors

Heap
 par new generation   total 9216K, used 3977K [0x00000000fec00000.0x00000000ff600000.0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000.0x00000000fefe27f0.0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000.0x00000000ff400000.0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000.0x00000000ff500000.0x00000000ff600000)
 concurrent mark-sweep generation total 10240K, used 0K [0x00000000ff600000.0x0000000100000000.0x0000000100000000)
 Metaspace       used 3255K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 353K.capacity 388K.committed 512K.reserved 1048576K
Copy the code

What if I get rid of CMS?

If we remove the above argument -xx :+UseConcMarkSweepGC, the following appears:

Heap
 par new generation   total 9216K, used 3977K [0x00000000fec00000.0x00000000ff600000.0x00000000ff600000)
  eden space 8192K,  48% used [0x00000000fec00000.0x00000000fefe27f0.0x00000000ff400000)
  from space 1024K,   0% used [0x00000000ff400000.0x00000000ff400000.0x00000000ff500000)
  to   space 1024K,   0% used [0x00000000ff500000.0x00000000ff500000.0x00000000ff600000)
 tenured generation   total 10240K, used 0K [0x00000000ff600000.0x0000000100000000.0x0000000100000000)
   the space 10240K,   0% used [0x00000000ff600000.0x00000000ff600000.0x00000000ff600200.0x0000000100000000)
 Metaspace       used 3238K, capacity 4496K, committed 4864K, reserved 1056768K
  class space    used 349K.capacity 388K.committed 512K.reserved 1048576K
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
Copy the code

Note the last sentence here:

The parNew+serrial combination is not recommended and will be deprecated in future releases. In fact, the parNew+serrial combination is completely banned in JDK9

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
Copy the code

Conclusion:

According to the above test cases, it is relatively easy to read the GC log, but the actual operation results will be different from the expected results due to the interference of various factors. There is no need to worry too much here, because as long as the basic theory is mastered, In accordance with the practice simulation of constant familiarity will find that the JVM garbage collection law is basically in line with our theoretical basis introduced.

If you are interested in object allocation policies, you can read the previous personal article: An In-depth Understanding of JVM Virtual Machine-JVM Object allocation Policies

Write in the last

The suggestion of reading the log is more practical operation and practice, and the memory can be deepened after several attempts. Since the personal machine itself will generate 4M objects without running any code, we can only simply introduce the method of reading the log…..