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

This article introduces what the GC log analysis of jvm is like, the content is very detailed, interested friends can refer to, I hope it can be helpful to you.

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

-XX:+PrintGC output GC log

-XX:+PrintGCDetails outputs the detailed log of GC

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

-XX:+PrintGCDateStamps outputs the timestamp of the GC (in the form of a date, such as 2013-05-04T21:53:59.234+0800)

-XX:+PrintHeapAtGC prints out heap information before and after GC

-XX:+PrintGCApplicationStoppedTime / / the time that the output GC causes the application to be suspended

-output path of Xloggc:../logs/gc.log log file

Common JVM parameters

After analyzing gc logs, you often need to adjust jvm memory-related parameters. The common parameters are as follows

-Xms: initial heap size, defaults to 1x64 of physical memory (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.

[java] view plain copy

Print?

5.617 (timestamp): [GC (Young GC) 5.617 (timestamp): [ParNew (area of GC): 43296K (size before garbage collection)-> 7006K (size after garbage collection) (47808K) (total size of this area), 0.0136826 secs (collection time)] 44992K (size before garbage collection)-> 8702K (size after garbage collection) (252608K) (total size of stack area) 0.0137904 secs (recovery time)] [Times: user=0.03 (GC user time) sys=0.00 (GC system time), real=0.02 secs (actual GC time)]

Let's do a simple analysis of the data.

From the last GC record, we can see that Young GC reclaimed 45278-6723 million 38555K of memory.

The Heap area has reduced a total of 46974-10551mm 36423K of memory through this collection.

38555-36423 / 2132K indicates that 2132K of memory has been moved to Old Gen through this Young GC.

Let's verify it.

Before the last Young GC recycling, the size of Old Gen was 8702-7006-1696.

The memory usage of Old Gen after recycling is 10551-6723-3828.

Old Gen increased its memory by 3828-1696mm 2132K after this Young GC, which is in line with the forecast.

[java] view plain copy

Print?

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]

The first numbers 4.231 and 4.445 represent the number of seconds since the virtual machine started.

[GC and [Full GC are the types of pauses for garbage collection, rather than distinguishing between the new generation and the old generation. If there is a Full, Stop-The-World occurs. If it is triggered by a call to System.gc (), then [Full GC (System)] is displayed.

The next [DefNew, [Tenured, [Perm] indicates the region where the GC occurs, and the name of the region is related to the GC collector used.

The new generation of Serial collectors is called "Default New Generation" and the displayed name is "[DefNew". For the ParNew collector, the display is "[ParNew", which means "Parallel New Generation". For the Parallel Scavenge collector, the new generation is called "PSYoungGen". The old generation and the permanent generation are the same, and the names are determined by the collector.

The "4928K-> 512K (4928K)" displayed inside the square brackets indicates "capacity used in this area before GC-> capacity used in this area after GC (total memory capacity in this area)".

The next "0.0044047 secs" indicates the time, in seconds, taken by the GC in that area.

The following "6835K-> 3468K (15872K)" indicates "Java heap used capacity before GC-> Java heap used capacity after GC (total Java heap capacity)".

The next "0.0045291 secs" is the total time spent on the Java heap GC.

The final "[Times: user=0.00 sys=0.00, real=0.00 secs]" represents the CPU time consumed in the user state, the CPU time consumed in the kernel state, and the wall clock time elapsed by the operation from start to finish, respectively. Wall clock time includes a variety of non-operational wait time, such as IO wait, thread blocking. CPU time does not include wait time. When the system has multiple cores, multithreaded operations will stack these CPU times, so the user or sys time will exceed the real time.

Generation of reactor

The young area is the new generation, which stores newly created objects.

Tenured is an old generation, storing objects that are still alive after repeated garbage collection in the new generation.

Perm is an immortal generation, storing class definition information, metadata and other information.

When GC occurs in the Cenozoic, it is called Minor GC, secondary collection; when GC occurs in the old generation, it is called Major GC, the main collection. Generally speaking, the frequency of Minor GC is much higher than that of Major GC.

Reset the output of the GC log

[java] view plain copy

Print?

-XX:+PrintGCDetails

-XX:+PrintHeapAtGC

-XX:+PrintGCDateStamps

-XX:+PrintTenuringDistribution

-verbose:gc

-Xloggc:gc.log

You can see the heap memory information before and after GC

[java] view plain copy

Print?

{Heap before GC invocations=1 (full 0):

PSYoungGen total 152896K, used 131072K [0x00000000f5560000, 0x0000000100000000, 0x0000000100000000)

Eden space 131072K, 100% used [0x00000000f5560000memori0x00000000fd560000memo0x0000000000fd560000)

From space 21824K, 0% used [0x00000000feab0000meme 0x0000000000feab00000x0000000100000000)

To space 21824K, 0% used [0x0000000000fd560000meme0x0000000000fd560000j0x000000000000feab0000)

PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)

Object space 349568K, 0% used [0x00000000e000000.x00000000e0000000leg0x00000000f5560000)

PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)

Object space 26432K, 99% used [0x00000000d00000J0x00000000d19c64a0pr 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 [0x00000000f5560000meme0x00000000f5560000memo0x0000000000fd560000)

From space 21824K, 38% used [0x00000000fd560000memori0x00000000fdd7ff78mem0x000000000000feab0000)

To space 21824K, 0% used [0x00000000feab0000meme 0x0000000000feab00000x0000000100000000)

PSOldGen total 349568K, used 0K [0x00000000e0000000, 0x00000000f5560000, 0x00000000f5560000)

Object space 349568K, 0% used [0x00000000e000000.x00000000e0000000leg0x00000000f5560000)

PSPermGen total 26432K, used 26393K [0x00000000d0000000, 0x00000000d19d0000, 0x00000000e0000000)

Object space 26432K, 99% used [0x00000000d00000J0x00000000d19c64a0pr 0x00000000d19d0000)

}

[java] view plain copy

Print?

[0x00000000f5560000.0x00000000f5560000.0x000000000000fd560000)

This form of logging has two meanings:

When this kind of log appears in the details of generation, the three numbers are called low_boundary, high, and high_boundary in HotSpot.

Low_boundary: the lowest address boundary of reserved space; usually equal to "low", which is the lowest address boundary of commited space

High: the highest address boundary of commited space

High_boundary: the highest address boundary of the reserved space.

Within the [low_boundary, high_boundary) range is reserved space, and the size of this space is max capacity.

The [low, high] range is commited space, and the size of this space is current capacity (current capacity), or capacity for short.

It is possible for capacity to float between a pair of minimum and maximum values. The maximum is the max capacity mentioned above.

Gc Log Analysis tool

(1) GCHisto

Http://java.net/projects/gchisto

Click gchisto.jar directly to run, and click add to load gc.log

Statistics of total gc times, youngGC times, FullGC times, percentage of times, time consumed by GC, percentage, average consumption time, minimum and maximum consumption time, etc.

(2) GCLogViewer

Http://code.google.com/p/gclogviewer/

Click run.bat to run

The trend chart of the gc situation of the whole process, and also shows the gc type, throughput, average gc frequency, memory change trend, etc.

You can also compare different gc logs in Tools

About jvm GC log analysis is how to share here, I hope the above content can be of some help to you, can learn more knowledge. If you think the article is good, you can share it for more people to see.

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.