Use hpjtune to analyze GC logs (a practical case diagnosis process)

The last time I introduced IBM's two GC log analysis tools (GMV and pmat), I will talk aboutHpjmeter. Hpjmeter integrates the previous hpjtune function to analyze garbage collection log files generated on HP machines. You can go {
Pagetracker. _ trackpageview ('/outbound/article/www.hp.com ');
} "Href =" http://www.hp.com/go/java "> Hewlett-Packard Java website free download of the latest version 4.0, of course, will let you fill in some information.

Next, I will analyze a log file in the actual production environment. After the new function is enabled, the application access speed slows down, and each operation takes about 10 s, by comparing different GC information, we hope to optimize the current performance at the JVM level.

After using the hp jdk, the-xloggc: filename or-xverbosegc

<Gch: vmrelease = "1.4.2 1.4.2.10-060112-16:07-pa_risc2.0 pa2.0 (acc_ap)
......
<Gch: mode = n>
<Gch: ncpu = 8>
<Gch: availswap = 33554432>
<Gch: usedswap = 0>
......
<GC: 2 4 9.625554 1 0 31 48539536 0 286392320 0 35782656 2409608 715849728 20971424 20971424 20971520 0.279391 0.279391>
<GC: 2 4 10.879321 2 0 31 9797920 0 286392320 0 35782656 2409608 2742416 715849728 25165568 25165568 25165824 0.307422 0.307422>

In pmat, it can be opened in xverbosegc/HPUX file format, but the image function cannot be used here, we had to turn to HP's own tool, hpjmeter.

Analysis Process

After you load the log file with hpjmeter, The hpjtune window is automatically opened. First, you will see the heap Usage After GC tab, which is normal in March (ignore systemgc first, which will be left for later analysis)

 

The following shows the slow speed of March:

We can see that the old full (with perm) represents an increase in the number of yellow points. From the previous log file header, we can see thatJDK is 1.4.2 32-bit (the 64-bit version will indicate Java VM name = Java hotspot (TM) 64-bit server VM)The default collection policy is the serial collector. When garbage collection occurs in the old area, the full GC of the world is stopped. The duration of full GC is 10 seconds ~ 12 s

Switch to the "summary" tab

In April, GC took 3.036% Of the total JVM running time, and full GC took 0.993% Of the total JVM running time. It should be said that the situation is good.

By June, the situation had changed a lot. The time was 10.791% and 8.417%, respectively, because the warning line of more than 5% was red, and 79% of GC time was spent on full GC.

This is still a week, including weekend and evening free time. Let's take a look at the running status during the peak hours.

Dear user, 61% of the time is spent on GC, and the speed is not slow. View the current heap Usage After GC

In addition to the rapid scavenge that occurred in the first few young generations, most of them were slow full GC, and we can see that the heap space used after each recycle is not reduced, but it is getting bigger and bigger, there are symptoms of Memory leakage. However, the heap space does not grow until outofmemory, but repeats like this.

In the morning and afternoon, the busy periods of the two businesses are full GC, with poor performance. The normal situation in April should be like this.

When the Eden area is full, some objects in the scavenge action are transferred to the old area, so the occupied space in the heap increases until the old area cannot be allocated. Full GC occurs, memory returns to a lower position again, which is normal. Now, full GC cannot be recycled since July, but outofmemory does not exist. We can judge that the original parameters cannot meet the requirements after the new content is put into production.

For example, parallel recovery is not used, 8 CPUs are not used, and the CMS recovery mode with low response time is not used.

At the same time, the number of objects generated by the new system is also greatly increased, from 500000 to 900000 on January 1, (January 1, on the left ).

As a result, the number of objects transferred from the new generation to the old area also increases after each collection. In fact, they are not permanent objects, but they cannot be accommodated by the new generation.

In addition, full GC will cause all objects in the same vor area to be transferred to the old area, which leads to a vicious circle. (After the yellow full GC, the objects in the same vor are zero)

Optimization operations

Adjust target: Try to discard objects that have survived for a short period of time in the young generation, instead of transferring them to the old generation. Use parallel collection to increase efficiency and avoid unnecessary full GC; or use the garbage collection method with a short response time.

Adjustment Method: Increase the size of the young generation, reduce the volume vorratio, and increase the volume vor area (from or to). Set the parallel recovery parameters; set the initial heap and the maximum heap to the same value, and set the initial permsize to a reasonable value to avoid growth during operation. Set the recycle policy to CMS.

Parameter settings 1:-Xms1500m-xmx1500m-xmn800m-XX: Export vorratio = 4-XX: permsize = 160 m-XX: + useparallelgc (-XX: parallelgcthreads = 8 I don't think any explicit statement is required, you can analyze the new GC log after setting the above parameters. Check the number of parallelgcthreads on the system details page and determine the number. It is also a pity that JDK 1.4.2 cannot perform parallel collection in the old area)

Parameter Setting 2:-Xms1500m-xmx1500m-xmn800m-XX: permsize = 160 m-XX: + useconcmarksweepgc-XX: + useparnewgc-XX: cmsfullgcsbeforecompaction = 5 (or set the last parameter to-XX: + usecmscompactatfullcollection)

For the significance of the above parameters, see Java Performance Optimization-sun hotspot jdk jvm parameter settings

Subsequent progress

There is another observation process after parameter settings. If the effect is not good, then from the perspective of system integration, one is to change the 64-bit JDK, in this way, you can set up a larger heap space (however, replacing the JDK with WebSphere is not as simple as weblogic. If you have not bought a 64-bit websphere, you have to stop it). Second, you can enable the WebSphere cluster, however, this requires the was of the Nd version.

From the application perspective, you can perform a heapdump at half past nine a.m. And a heapdump at a.m. to analyze the reason why full GC memory cannot be recycled and determine that it is not caused by program errors. You can also enable the-agentlib: hprof parameter and use hpjmeter to trace the performance of the application, and use hpjmeter to directly monitor the running status of the application. However, these two methods have a great impact on the performance and should be carried out in the testing environment.

Other broken ideas

Now let's talk about the many systemgc logs. I was surprised at first, but after enlarging the image, I found that all these self-called full GC jobs were completed after work, it should be triggered by another application, which has little impact on daytime performance.

However, here we still need to declare another sentence: Self-calling system. GC () function will damage JVM performance, because it is a collection of stop the world, which consumes a long time, but the effect is not optimal. You may think that you are familiar with the program and can execute system in idle time. GC does not affect customer access, but as mentioned earlier, after full GC, all content in the same VOR is transferred to the old area for long-term storage, so in a future, JVM has to perform unnecessary full GC again for this reason.

In ibm jdk, the parameter"-Xdisableexplicitgc", The parameter in Sun JDK is"-XX: + disableexplicitgc", Pay attention to the difference.

 

 

Note:

This article Reprinted from: http://www.hashei.me/2009/07/use-hpjtune-to-analysis-gc-log.html