cool hit counter JVM tuning log parsing analysis_Intefrankly

JVM tuning log parsing analysis


I. Tuning parameter settings

The main parameters of the JVM's GC log include the following.

-XX:+PrintGC Output GC log

-XX:+PrintGCDetails Output the detailed log of GC

-XX:+PrintGCTimeStamps Outputs the timestamp of the GC (in the form of the base time)

-XX:+PrintGCDateStamps exportsGC timestamp( In the form of a date, as if2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC prints out the heap before and after the GC is performed.

-XX:+PrintGCApplicationStoppedTime // Output the time when the GC caused the application to be paused.

-Xloggc:... /logs/gc.log Output path to log file

After analyzing gc logs, it is often necessary to adjust jvm memory-related parameters, which are commonly used as follows.

-Xms: Initial Heap Size, The default is the physical memory of the1/64(<1GB); default(MinHeapFreeRatio Parameters can be adjusted) Free heap memory is less than40% time,JVM It will increase the heap until-Xmx Maximum limit of the -Xmx: maximum heap size, default (MaxHeapFreeRatio parameter can be adjusted) when free heap memory is greater than 70%, JVM will reduce heap until -Xms minimum limit -Xmn: Memory space size of the new generation, note: The size of this place is(eden+ 2 survivor space)。 together withjmap -heap displayed in theNew gen It's different.。 Whole heap size= New generation size + Older generation size + Permanent generation size。 The size of the old generation will be reduced by increasing the size of the new generation while keeping the heap size constant. This value has a large impact on system performance, and the official Sun recommendation is 3/8 of the entire heap. -XX:SurvivorRatio: the ratio of the capacity of the Eden region to the Survivor region in the new generation, the default value is 8. The ratio of two Survivor regions to one Eden region is 2:8,and one Survivor region accounts for 1/10 of the entire young generation. -Xss: Stack size per thread。JDK5.0 The subsequent per-thread stack size is1M, Previously the per-thread stack size was256K。 The memory size required by the threads of the application should be adjusted appropriately。 With the same physical memory, Decreasing this value will generate more threads。 But the operating system still has a limit on the number of threads within a process, Cannot be generated indefinitely, The value of experience in3000~5000 left and right。 General small applications, If the stack is not very deep, It should be.128k suffice, Large applications are recommended to use256k。 This option has a greater impact on performance, Rigorous testing required。 harmonythreadstacksize The options are interpreted very similarly, The official documentation doesn't seem to explain, There is this quote in the forum:"-Xss is translated in a VM flag named ThreadStackSize” Usually setting this value is sufficient。 -XX:PermSize: set the initial value of the permanent generation (perm gen). The default value is 1/64th of the physical memory. -XX:MaxPermSize: set persistent generation maximum. 1/4 of the physical memory.

After I made the following settings

-XX:+PrintGCDetails -Xloggc:../logs/gc.log -XX:+PrintGCTimeStamps

The log will later print out as.

 

 
0.756: [Full GC (System) 0.756: [CMS: 0K->1696K(204800K), 0.0347096 secs] 11488K->1696K(252608K), [CMS Perm : 10328K->10320K(131072K)], 0.0347949 secs] [Times: user=0.06 sys=0.00, real=0.05 secs]
 
1.728: [GC 1.728: [ParNew: 38272K->2323K(47808K), 0.0092276 secs] 39968K->4019K(252608K), 0.0093169 secs] [Times: user=0.01 sys=0.00, real=0.00 secs]
 
2.642: [GC 2.643: [ParNew: 40595K->3685K(47808K), 0.0075343 secs] 42291K->5381K(252608K), 0.0075972 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
4.349: [GC 4.349: [ParNew: 41957K->5024K(47808K), 0.0106558 secs] 43653K->6720K(252608K), 0.0107390 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
5.617: [GC 5.617: [ParNew: 43296K->7006K(47808K), 0.0136826 secs] 44992K->8702K(252608K), 0.0137904 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
7.429: [GC 7.429: [ParNew: 45278K->6723K(47808K), 0.0251993 secs] 46974K->10551K(252608K), 0.0252421 secs]

Let's take the penultimate record and analyze what each field represents

5.617( timestamp): [GC(Young GC) 5.617( timestamp): [ParNew(GC region): 43296K( Size before garbage collection)->7006K( Size after garbage collection)(47808K)( Total size of the region), 0.0136826 secs( Recovery time)] 44992K( Size of heap area before garbage collection)->8702K( Size of heap area after garbage collection)(252608K)( Total heap area size), 0.0137904 secs( Recovery time)] [Times: user=0.03(GC User time consumption) sys=0.00(GC System time consumption), real=0.02 secs(GC Actual time taken)]

Let's do another brief analysis of the data

From the last articleGC In the record we can see that Young GC Recovered.45278-6723=38555K memory

Heap In total, the District has reduced through this recycling46974-10551=36423K memory。

38555-36423=2132K indicates that 2132K of memory was moved to Old Gen through that Young GC.

Let's verify it.

Before the last Young GC recovery the size of Old Gen was 8702 - 7006 = 1696

Memory usage for Old Gen after recycling is 10551-6723=3828

Old Gen at that timeYoung GC Later memory increases3828-1696=2132K In line with expectations

4.231: [GC 4.231: [DefNew: 4928K->512K(4928K), 0.0044047 secs] 6835K->3468K(15872K), 0.0045291 secs] [Times: user=0.00 sys=0.00, real=0.00 secs]
 
4.445: [Full GC (System) 4.445: [Tenured: 2956K->3043K(10944K), 0.1869806 secs] 4034K->3043K(15872K), [Perm : 3400K->3400K(12288K)], 0.1870847 secs] [Times: user=0.05 sys=0.00, real=0.19 secs]

Top number4.231 harmony4.445 Represents the number of seconds since the virtual machine was started.

[GC harmony[Full GC is the type of garbage collection stop, rather than distinguishing whether it is a new or old generation, if thereFull It means it happened.Stop-The-World . If it is a call toSystem.gc() triggered, then what will be displayed is[Full GC (System)

following[DefNew,[Tenured,[Perm Indicates the region where the GC occurred, and the name of the region is related to the GC collector used. The new generation in the Serial collector is named "Default New Generation" and is displayed as "[DefNew". For the ParNew collector, "[ParNew" is displayed, indicating "Parallel New Generation". For the Parallel Scavenge collector, the new generation is named "PSYoungGen". The same is true for the older and permanent generations, both with names determined by the collector.

shown inside the square brackets “4928K->512K(4928K)” express “GC Previously used capacity in the region -> GC Post-use capacity of the region ( Total memory capacity of the region) ”。

Further "0.0044047 secs" indicates the time in seconds used for GC in that area.

further “6835K->3468K(15872K)” express “GC formerlyJava Heap used capacity -> GC backJava Heap used capacity (Java Total heap capacity)”。

Further back "0.0045291 secs" is the total time used for Java heap GC.

The last "[Times: user=0.00 sys=0.00, real=0.00 secs]" represents the CPU time consumed by the user state, the CPU time consumed by the kernel state, and the wall clock time elapsed from the start to the end of the operation, respectively. Wall clock time includes various non-computational wait time consumptions, such as IO waits, thread blocking. CPU time does not include wait time, and when the system has multiple cores, multi-threaded operations stack these CPU times, so user or sys time will exceed real time.

The heap generation mechanism

  • The young region is the new generation, which holds the newly created objects.
  • (a) tenured is the older generation, which holds objects that have survived multiple garbage collections in the newer generation.
  • perm is the perpetual generation that holds class definition information, metadata, and other information.

When GC occurs in the new generation, it is called Minor GC, secondary collection; when GC occurs in the old generation, it is called Major GC, main collection. In general, Minor GCs occur much more frequently than Major GCs.

Resetting the output of the GC log

 
-XX:+PrintGCDetails
 
-XX:+PrintHeapAtGC
 
-XX:+PrintGCDateStamps
 
-XX:+PrintTenuringDistribution
 
-verbose:gc
 
-Xloggc:gc.log

Afterwards, you can see the heap memory information before and after the GC is performed

{
Heap before GC invocations=1 (full 0):
 
PSYoungGen total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
 
eden space 131072K, 100% used [0x00000000f5560000,0x00000000fd560000,0x00000000fd560000)
 
from space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
 
to space 21824K, 0% used [0x00000000fd560000,0x00000000fd560000,0x00000000feab0000)
 
PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
 
object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 
PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
 
object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
 
2013-05-05T23:16:10.480+0800: 5.228: [GC Desired survivor size 22347776 bytes, new threshold 7 (max 15)
 
[PSYoungGen: 131072K->8319K(152896K)] 131072K->8319K(502464K), 0.0176346 secs] [Times: user=0.03 sys=0.00, real=0.02 secs]
 
Heap after GC invocations=1 (full 0):
 
PSYoungGen total 152896K, used 8319K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)
 
eden space 131072K, 0% used [0x00000000f5560000,0x00000000f5560000,0x00000000fd560000)
 
from space 21824K, 38% used [0x00000000fd560000,0x00000000fdd7ff78,0x00000000feab0000)
 
to space 21824K, 0% used [0x00000000feab0000,0x00000000feab0000,0x0000000100000000)
 
PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)
 
object space 349568K, 0% used [0x00000000e0000000,0x00000000e0000000,0x00000000f5560000)
 
PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)
 
object space 26432K, 99% used [0x00000000d0000000,0x00000000d19c64a0,0x00000000d19d0000)
 
}

You can see that the front and back are recycled off131072K -21824K*0.38 = 122778K RAM

sample code (computing)

/**
 * VM agrs: -verbose:gc -Xms20M -Xmx20M -Xmn10M -XX:+PrintGCDetails
 * -XX:SurvivorRatio=8 -XX:+UseSerialGC
 */

public class MinorGCTest {
    private static final int _1MB = 1024 * 1024;

    public static void testAllocation() {
        byte[] allocation1, allocation2, allocation3, allocation4;
        allocation1 = new byte[2 * _1MB];
        allocation2 = new byte[2 * _1MB];
        allocation3 = new byte[2 * _1MB];
        allocation4 = new byte[4 * _1MB];
    }

    public static void main(String[] agrs) {
        testAllocation();
    }
}
  • VM Parameters Description

Option

Description

-verbose:gc

Display the contents of the GC operation

-Xms20M -Xmx20M

Set heap size to 20M

-Xmn10M

Set the memory space size of the new generation to 10M

-XX:+PrintGCDetails

Print the changes in GC

-XX:SurvivorRatio=8

Ratio of the size of the Eden region to the Survivor region in the Cenozoic

-XX:+UseSerialGC

In the new generation harmony Using serial collectors in the olden days, thanks to-verbose:gc Parameter pairParallel Scavenge Collector not working, undisplayable Display the contents of the GC operation, Therefore a serial collector is used

  • Example code description
  • The code creates a total of four array objects, and the memory space usage before allocating space to allocation4 is as follows: eden area is 8M Two Survivor for 1M each and 10M for the aged generation.
  • A MinorGC needs to be executed to allocate space to allocation4 (when the Eden area is full) and the memory space usage after successful allocation is as follows.

2. GC Log

  • [GC [DefNew ... ...]
  • The information at the beginning of the GC log is set by setting-verbose:gc parameter before it can be output.
  • "[GC" harmony"[Full GC" Indicate the type of stop for this garbage collection, or if Stop-The-World occurred for this GC, the"[Full GC" otherwise it is"[GC"
  • "[DefNew " indicates that the region where GC occurs is in the new generation of the Serial collector, DefNew is"Default New Generation" The abbreviation for. The old age and permanent generation of the Serial collector are denoted as"Tenured""Perm"
  • ** eden space 8192K, 52% used**
  • The total size of the Eden area of the new generation is 8MB, and the 4MB used up is to store the allocation4 object
  • tenured generation total 10240K, used 6144K
  • The old age size is 10MB, the used 6MB is used to store the 3 objects location1, location2 and location3

The Survivor area in the middle takes up 19% of the memory This is not very clear to the author, so if any of you know about it, drop me a line and help explain, thanks!

III. Principles of memory allocation

Objects are assigned first on the Eden zone

The virtual machine parameters are "-verbose:gc -XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8", i.e. 10M new generation, 10M old generation, 8M Eden area in 10M new generation, and 1M each of the two Survivor areas. The code is all in the same paragraph

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[4 * _1MB];
    }
}

In Client mode

[GC [DefNew: 6487K->194K(9216K), 0.0042856 secs] 6487K->6338K(19456K), 0.0043281 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
Heap
 def new generation   total 9216K, used 4454K [0x0000000005180000, 0x0000000005b80000, 0x0000000005b80000)
  eden space 8192K,  52% used [0x0000000005180000, 0x00000000055a9018, 0x0000000005980000)
  from space 1024K,  18% used [0x0000000005a80000, 0x0000000005ab0810, 0x0000000005b80000)
  to   space 1024K,   0% used [0x0000000005980000, 0x0000000005980000, 0x0000000005a80000)
 tenured generation   total 10240K, used 6144K [0x0000000005b80000, 0x0000000006580000, 0x0000000006580000)
   the space 10240K,  60% used [0x0000000005b80000, 0x0000000006180048, 0x0000000006180200, 0x0000000006580000)
 compacting perm gen  total 21248K, used 2982K [0x0000000006580000, 0x0000000007a40000, 0x000000000b980000)
   the space 21248K,  14% used [0x0000000006580000, 0x0000000006869890, 0x0000000006869a00, 0x0000000007a40000)
No shared spaces configured.

In Server mode

Heap
 PSYoungGen      total 9216K, used 6651K [0x000000000af20000, 0x000000000b920000, 0x000000000b920000)
  eden space 8192K, 81% used [0x000000000af20000,0x000000000b59ef70,0x000000000b720000)
  from space 1024K, 0% used [0x000000000b820000,0x000000000b820000,0x000000000b920000)
  to   space 1024K, 0% used [0x000000000b720000,0x000000000b720000,0x000000000b820000)
 PSOldGen        total 10240K, used 4096K [0x000000000a520000, 0x000000000af20000, 0x000000000af20000)
  object space 10240K, 40% used [0x000000000a520000,0x000000000a920018,0x000000000af20000)
 PSPermGen       total 21248K, used 2972K [0x0000000005120000, 0x00000000065e0000, 0x000000000a520000)
  object space 21248K, 13% used [0x0000000005120000,0x0000000005407388,0x00000000065e0000)

Seeing the in Client model, with the last 4M allocated in the new generation and the 6M allocated first in the old generation.

(located) at In Server mode, final distribution4M In the olden days, prior6M Among the new generation . shows that different combinations of garbage collectors have an impact on the allocation of objects.

To explain the reasons for the difference.

1. In Client mode, the new generation is allocated 6M, and the VM has 6487K before GC, which is more than 6M which is 6144K. More mainly because of the space occupied by the object TLAB and EdenAllocationTest, TLAB can be viewed in size with the virtual machine parameter "-XX:+PrintTLAB".

OK, 6M more, then comes a 4M, Eden + a Survivor a total of 9M is not enough to allocate [feel a little wrong in this place, because the case of triggering a Minor GC is Eden memory full, here should not count Survivor], this time will trigger a Minor GC. But triggering Minor GC doesn't help, because the three references of allocation1, allocation2, and allocation3 still exist, and another 1M piece of Survivor is not enough to put down the 6M, so the effect of this Minor GC is actually to transfer the 6M into the old age through the allocation guarantee mechanism. Then a 4M, at this point after Minor GC the new generation only has 194K left, enough to allocate, so the 4M goes into the new generation smoothly.

2、 In Server mode, It's all the same up front., But inGC There's a slight difference when it comes to。 (located) atGC One more judgment call will be made before, If the memory to be allocated>=Eden Half the size of the zone, Then it will put the memory to be allocated directly into the old age。 To be allocated4M,Eden distinguish8M, Exactly half., And the old days10M, Sufficient distribution, consequently4M Just go straight to the old days.。 To test the conclusion, We put3 size2M Subsequent assignments4M change into3M Take a look.。

public class EdenAllocationTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
        byte[] allocation1 = new byte[2 * _1MB];
        byte[] allocation2 = new byte[2 * _1MB];
        byte[] allocation3 = new byte[2 * _1MB];
        byte[] allocation4 = new byte[3 * _1MB];
    }
}

The results of the run are

[GC [PSYoungGen: 6487K->352K(9216K)] 6487K->6496K(19456K), 0.0035661 secs] [Times: user=0.00 sys=0.00, real=0.00 secs] 
[Full GC [PSYoungGen: 352K->0K(9216K)] [PSOldGen: 6144K->6338K(10240K)] 6496K->6338K(19456K) [PSPermGen: 2941K->2941K(21248K)], 0.0035258 secs] [Times: user=0.02 sys=0.00, real=0.00 secs] 
Heap
 PSYoungGen      total 9216K, used 3236K [0x000000000af40000, 0x000000000b940000, 0x000000000b940000)
  eden space 8192K, 39% used [0x000000000af40000,0x000000000b269018,0x000000000b740000)
  from space 1024K, 0% used [0x000000000b740000,0x000000000b740000,0x000000000b840000)
  to   space 1024K, 0% used [0x000000000b840000,0x000000000b840000,0x000000000b940000)
 PSOldGen        total 10240K, used 6338K [0x000000000a540000, 0x000000000af40000, 0x000000000af40000)
  object space 10240K, 61% used [0x000000000a540000,0x000000000ab70858,0x000000000af40000)
 PSPermGen       total 21248K, used 2982K [0x0000000005140000, 0x0000000006600000, 0x000000000a540000)
  object space 21248K, 14% used [0x0000000005140000,0x0000000005429890,0x0000000006600000)

See 3M in the new generation and 6M coming into the old age through the distribution guarantee mechanism.

Big objects go straight to the old age

The virtual machine parameter is "-XX:+PrintGCDetails -Xms20M -Xmx20M -Xmn10M -XX:SurvivorRatio=8 -XX:PretenureSizeThreshold=3145728", that last parameter means that objects larger than this setting are allocated directly in the old age, this is done to avoid a lot of memory copying between the Eden area and the two Survivor areas. The test code is

public class OldTest
{
    private static final int _1MB = 1024 * 1024;
    
    public static void main(String[] args)
    {
         byte[] allocation = new byte[4 * _1MB];
    }
}

In Client mode

Heap
 def new generation   total 9216K, used 507K [0x0000000005140000, 0x0000000005b40000, 0x0000000005b40000)
  eden space 8192K,   6% used [0x0000000005140000, 0x00000000051bef28, 0x0000000005940000)
  from space 1024K,   0% used [0x0000000005940000, 0x0000000005940000, 0x0000000005a40000)
  to   space 1024K,   0% used [0x0000000005a40000, 0x0000000005a40000, 0x0000000005b40000)
 tenured generation   total 10240K, used 4096K [0x0000000005b40000, 0x0000000006540000, 0x0000000006540000)
   the space 10240K,  40% used [0x0000000005b40000, 0x0000000005f40018, 0x0000000005f40200, 0x0000000006540000)
 compacting perm gen  total 21248K, used 2972K [0x0000000006540000, 0x0000000007a00000, 0x000000000b940000)
   the space 21248K,  13% used [0x0000000006540000, 0x00000000068272a0, 0x0000000006827400, 0x0000000007a00000)
No shared spaces configured.

In Server mode

Heap
 PSYoungGen      total 9216K, used 4603K [0x000000000afc0000, 0x000000000b9c0000, 0x000000000b9c0000)
  eden space 8192K, 56% used [0x000000000afc0000,0x000000000b43ef40,0x000000000b7c0000)
  from space 1024K, 0% used [0x000000000b8c0000,0x000000000b8c0000,0x000000000b9c0000)
  to   space 1024K, 0% used [0x000000000b7c0000,0x000000000b7c0000,0x000000000b8c0000)
 PSOldGen        total 10240K, used 0K [0x000000000a5c0000, 0x000000000afc0000, 0x000000000afc0000)
  object space 10240K, 0% used [0x000000000a5c0000,0x000000000a5c0000,0x000000000afc0000)
 PSPermGen       total 21248K, used 2972K [0x00000000051c0000, 0x0000000006680000, 0x000000000a5c0000)
  object space 21248K, 13% used [0x00000000051c0000,0x00000000054a72a0,0x0000000006680000)

see that In Client mode4M Straight into the old days, In Server mode4M Still in the new generation . The reason for this difference is The parameter "-XX:PretenureSizeThreshold" is valid for Serial+Serial Old garbage collector combinations but not for Parallel+Serial Old garbage collector combinations

A few other principles

The principles listed above are not really important, they are just demonstrations and do not need to be remembered, because in practice we may not use the above combination of garbage collectors, we may use the ParNew garbage collector, we may use the G1 garbage collector. There are many scenarios, and it is important to have a way to know what principles the garbage collector in use has for object allocation when you actually use it, because understanding those principles is the first step in tuning. Two other principles of object assignment are listed below.

1. Long-term surviving objects will enter their old age. If the object in the Eden zone is not reclaimed after a Minor GC, the object age is +1. When the object age reaches the value set by "-XX:MaxTenuringThreshold", the object will be promoted to the old age

2, Survivor space of the same age of all objects in the size of the sum is greater than half of the Survivor space, the age of objects greater than or equal to the age can directly enter the old age, without waiting until the "-XX: MaxTenuringThreshold" set the required age


Recommended>>
1、Blockchain Digital Currency Bitcoin Latest News
2、Introducing NetToPLCsim a useful little tool
3、The most popular movies on Douban with Python without leaving home
4、Accelerating the pace iterating fast IRISnets 5th generation public beta test network released
5、After missing out on Ether and EOS do we still have a chance at financial freedom

    已推荐到看一看 和朋友分享想法
    最多200字,当前共 发送

    已发送

    朋友将在看一看看到

    确定
    分享你的想法...
    取消

    分享想法到看一看

    确定
    最多200字,当前共

    发送中

    网络异常,请稍后重试

    微信扫一扫
    关注该公众号