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

In this article Xiaobian for you to introduce in detail "JVM GC logging case analysis", detailed content, clear steps, details handled properly, I hope that this "JVM GC logging example analysis" article can help you solve doubts, following the editor's ideas slowly in-depth, together to learn new knowledge.

GC Evaluation of Java applications

It is possible that after developing a requirement, most programmers throw it into the online environment and pay little attention to the subsequent changes. But have you ever considered the impact these newly introduced code will have on the original system? Below, we will give readers a better understanding of this process through a period of actual combat.

Simulated scene

One application (temporarily called the moment service) is going to launch a social dynamic push function on Mini Program, which means that every time a user refreshes the page, he or she will push out 20 pieces of dynamic user data according to certain rules. Due to the large number of c-end users of the product, the corresponding pressure test was carried out before the product was launched to judge the bearing capacity of the function.

At the beginning of the stress test, the interface response speed is OK, but gradually began to pressurize, found that the program appeared OOM. After troubleshooting, troubleshoot the problem in the database layer. So I began to wonder if there was an exception inside the Java application.

Startup parameters of the application:

Java-Xmx1512m-Xms1512m-Xmn1024m-XX:+UseConcMarkSweepGC-XX:+UseParNewGC-XX:+HeapDumpOnOutOfMemoryError-XX:+PrintGCDetails-XX:+PrintGCTimeStamps-Xloggc:log/gc.log-jar qiyu-framework-demo-jvm.jar

Single node pressure test, stress test 10w requests, 1000 concurrent. Use the ab tool for stress testing:

Ab-n100000-c1000 http://localhost:8080/user/batch-query

Jstat checks the GC and prints it every 5 seconds for 20 times

Jstat-gc 5673 5000 20

After a period of pressure, after the pressure lasted for 1 minute, the frequency of YGC felt a little high. Usually a healthy system ygc should be about 20-30min once, full gc may be only once in several weeks.

Through the jstat, we can see that the younger generation of gc will be more frequent, and the pause time has seriously affected the normal business use. In order to get more accurate data, I tried to put the gc log on the GCeasy tool for visual analysis:

This is a very good gc log analysis tool.

Https://www.gceasy.io/

Visual Analysis of GC Log

First of all, the analysis of the occupation of JVM memory, it is clear that the memory of the younger generation and the memory of the old are almost full, and the meta-space has basically not changed.

Then there is the GC time analysis of the whole system:

Taken as a whole, most of the GC time is within 0-100ms, and in extreme cases the GC time may be as long as 700ms.

The next step is to look at the impact of GC recycling on heap memory as a whole. It is found that basically every time GC can recover about the memory of the modified 200mb.

After further analysis, we can find out the time spent by the CMS collector in each stage of collection: initial marking, concurrent marking, correcting marking, concurrent cleanup.

In addition to simply analyzing the time spent on GC recycling, this tool also has a great feature to help us analyze the rate at which objects are generated by the Java program during this period:

You can find that if you want to generate 445mb objects in a second, 2.5mb objects will be promoted to the old age in about a second.

No abnormal records were found in the memory escape analysis.

After analyzing the report, my first intuition told me that the younger generation was insufficient and needed to increase the memory of the younger generation. But after careful observation, the rate of producing objects is as high as 445mb/s, which feels very abnormal, and it is extremely suspected that there are large objects in the program.

So try to use jvisualVM this tool for in-depth analysis, through the monitoring of CPU samples, found some abnormal information:

It seems that this method consumes a lot of CPU, followed by a memory monitoring:

At this point, you can probably locate the location of the exception method, and then it is time to analyze the business code within the system.

Finally, the result of investigation shows that it is actually a method call within the system, which loads 5k User objects into memory for calculation, and each User object stores a byte array of size 1kb. The approximate code logic is:

So you need to optimize the method at the business level, such as reducing the number 5k, while filtering the byte array within the User object (because this field is not actually used).

After adjustment, it is found that the frequency of GC is much lower, which is relatively normal.

After reading this, the article "GC logging example Analysis of JVM" has been introduced. If you want to master the knowledge points of this article, you still need to practice and use it yourself. If you want to know more about related articles, welcome to follow the industry information channel.

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.