preface
The article I compiled today is from my daily notes.
In the early days of the JVM, GC logs were treated with an “escape” attitude, and when applications deployed online did not perform as efficiently or as expected, memory was often blamed for the problem.
Is there not enough memory?
Why so many GC logs? How many gigabytes of disk usage?
Do not want to see how much printing, even violent program logs will be shielded.
I’ve done this before, and I’ve written programs that have run out of memory and even crashed hosts.
Yes, garbage collection in Java does save us a lot of work. Unlike C/C++ programmers,
Malloc memory allocation and free memory need to be considered, but I’m sure every Java developer does
GC problems can be encountered, whether in program performance optimization or fault analysis.
We should learn from mistakes over and over again, not run away from them or try to fix them. Review the same knowledge point twice, will produce 1 + 1 > 2 effect.
So in this article we’re going to talk about GC logging for the JVM.
What is a GC log
Let’s start with the concept of GC, which stands for Garbage Collection.
What is garbage?
Objects that have no reference to them are treated as garbage by the JVM.
Of course, the corresponding decision algorithms are: reference counting algorithm, reachability analysis algorithm. Corresponding recycling algorithms include: mark clearing, copy, mark sorting, generation collection algorithm.
What is the GC log?
GC logs are descriptive text logs produced by the Java Virtual machine. Just like we need to output logs to develop Java programs. JAVA virtual machines use GC logs to describe garbage collection.
The Minor and Major GC
All Minor GCS trigger stop-the-world, stopping the application thread, but this process is very short.
Major GC: refers to GC that occurs in an older era, also known as Full GC.
What are GC logs for
Through the GC log, we can visually see the basic working process of memory cleaning.
Learn about some of the actions of garbage collection, when in the Young generation and when in the Old generation, and show how many resources garbage collection uses.
Although there are many visual monitoring tools available for Java programs today , but GC logs are one of the most intuitive pieces of information for developers to quickly locate potential memory failures and performance bottlenecks.
What information can we get from GC logs
ES’s GC Allocation Failure
The log of an online GC problem is also valuable for analysis. The graph of GC Allocation Failure here is taken from the ES node GC log of a group member.
GC Allocation Failure is a common type of GC log that we encounter.
An allocation failure means that there is no more space in the Eden area of the JVM to allocate objects, which is a normal log for the Minor GC.
Let’s take a look at what a GC Allocation Failure log looks like.
Is that confusing? 【 Head Pick dialog 】
That’s okay. Let’s take it one by one.
If we split the log by time, we can see that there are two lines of log in the screenshot. Let’s look at log 1 first:
The 2020-03-17 T19:03:19. 701 + 0800:6664.686: Total timefor whichApplication Threads were stopped: 0.0313360 seconds, Stopping Threads took: 0.0000925 secondsCopy the codeOf course, the first thing that pops up is log time with time zones.
Total time for which Application Threads were stopped indicates that all application threads were stopped for 0.0313360 seconds.
0.0000925 seconds was spent waiting for all application threads to reach the safe point.
This pause time is actually spent on GC. Real =0.03 secs in the following second line corresponds here.
Just to mention the safety point, we know that threads in Java have several different states. We also know what problems can occur if threads are “interrupted.” So for designers, it’s important to let the thread “run” to a safe point and then pause. When at a safe point, the thread’s state is determined, allowing the JVM to safely perform operations such as garbage collection.
Locations of safety points include:
If a thread never makes it to the safe point, this can cause the JVM to pause longer during GC.
Let’s look at log 2:
1) 2020-03-17T19:03:20.118+ 0800:6665.102:2) [GC (Allocation Failure) 2020-03-17T19:03:20.118+ 0800:6665.102: 3) [ParNew Desired survivor size 8716288 bytes, new threshold 6 (Max 6) 4) -age 1: 6826872 bytes, 6826872 total 5) - age 2: 1060216 bytes, 7887088 total 6) : 149828K-> 1495k (153344K), 0.0363166secs] 8) [Times: 149828K-> 1495k (153344K), 0.0363166secs] 8) [Times: User sys = = 0.07 0.00, real = 0.03 secs]Copy the codeThe first line is the log output time.
The second line, indicating that a GC collection took place, notes that since there is no Full keyword, it indicates a Minor GC and indicates the time of the GC. An Allocation Failure indicates that the cause of GC is that there is not enough space in the young generation to store data.
The third line, ParNew, also indicates that the GC is in the young generation and that the ParNew garbage collector is used. The collector reclaims memory using a copy algorithm, stopping other worker threads in The process, i.e. stopping The World.
The third, fourth, and fifth lines indicate that the age distribution of objects in survivor region is printed after each young generation GC, and threshold indicates that the age threshold for promotion to the old age is set to 6.
The sixth line respectively represents the capacity used by the young generation before GC, the capacity used by the region after GC, and the total capacity of the region in parentheses. Finally, the GC time for the memory region is in seconds.
The seventh row represents the size between garbage collection in the heap, the size after garbage collection in the heap, and the total size of the heap.
You can see that after GC, the percentage of reclaimed objects is very small.
The eighth line shows three time consuming, namely, user-mode time, kernel-mode time, and total time.
From the above information, we can draw the following conclusions:
New generation of GC decreased: 149828-8895 = 140933K.
Total heap memory area decreased: 6272826-6139400 = 133426K.
Subtract the two equal signs: 140933-133426 = 7507K
This time, 7507K (7.3m) of memory has been moved from the young generation to the old generation. It can be seen that the amount of memory is not very large, indicating that they are objects with short life cycles, but there are many such objects.
What we need is to avoid Full GC as much as possible and make the object as young as possible, so we can increase the size of the young generation a little bit, so that the 7.3m data is also stored in the young generation.
ES of Old GC
The GC logs of the younger generation were introduced above, and the GC logs of the older generation are analyzed in the same way as the GC logs of the younger generation.
Let’s start with the log:
[gc][238384] overhead, spent [2.2s] collecting inThe last 2.3 [s] [the 2020-03-18 T01:01:29, 020] [INFO] [O.E.M.J.J vmGcMonitorService] [eS] [gc] [the old] [238385] [160772] duration (5 s), the collections of [1] / [s] 5.1, total [5 s] / [d] 4.4, the memory [945.4 MB] - > [958.5 MB] / [1007.3 MB], All_pools {[young] [87.8 MB] - > [100.9 MB] / [133.1 MB]} {[survivor] b [0] - > [0 b] / [16.6 MB]} {[the old] [857.6 MB] - > [857.6 MB] / [857.6 MB]}Copy the codeLet’s get straight to it. The first line indicates that this is the 238,384 GC that has spent 2.2 seconds for garbage collection in the last 2.3 seconds.
The second line should not be complicated for GC who has read the younger generation.
Duration duration duration duration duration duration duration duration duration duration duration duration duration duration duration duration duration
Collections [1 TOTAL GC since last check]/[5.1 seconds since last check],
Total [Total GC time checked this time is 5 seconds]/[Total GC time since JVM startup is 4.4 days],
Memory [pre-GC Heap memory space]->[post-GC Heap memory space]/[total Heap memory space],
All_pools (details of generation section)
{[young Memory] [pre-gc Memory] ->[post-GC Memory]/[young Memory total size]}
{[survivor][pre-gc Memory] ->[post-GC Memory]/[survivor Memory size]}{[old Memory size][pre-GC Memory] ->[post-GC Memory size] }
GC configuration for ES
-xx :+PrintGCDetails Prints GC details logs
-xx :+PrintGCDateStamps indicates the date and time to print GC
– XX: + PrintGCApplicationStoppedTime print recycling program suspended during the period of time
Log scrolling, output to specified log files, and so on.
GC log icon
If that doesn’t make sense, here are two images of the GC log that you can use as a tool when you need to read the GC log.
Young generation:
Old age:
To sum up (my view)
GC involves a lot of knowledge, this article is probably just the tip of the iceberg, from the GC log analysis, let the reader understand, each number change in the GC log, what it means. More, there was introduced and some screening ways of online OOM and MAT performance analysis tools used in the actual cases, at the same time, hope everybody can combined with the actual case to analysis, completes the knowledge reserve, as well as some problems of online out of the GC can do a plan, adjust the optimal JVM configuration, improving the efficiency of the online application, Try to avoid some performance glitches. Finally, make a summary on the content
- This article explains why I compiled this note
- This section describes the basic concepts of GC logging
- Basic concepts for minor and Major GC
- Illustrates the purpose of GC logging
- ES failed to read the log for GC allocation
- ES Old GC log interpretation.
- Graphical representation of the JAVA GC
Recommended to join the Java Troubleshooter group, recommended reading
【 combat 】 ElasticSearch write speed increase case share
Make a profitable wechat group chat robot with Java (PC protocol)
Mysql millions of data into Redis efficiently
The visual interface generates JVM parameters online
Java online fault analysis + Performance tuning
ELK practice Walkthrough