DZone
Thanks for visiting DZone today,
Edit Profile
  • Manage Email Subscriptions
  • How to Post to DZone
  • Article Submission Guidelines
Sign Out View Profile
  • Post an Article
  • Manage My Drafts
Over 2 million developers have joined DZone.
Log In / Join
Refcards Trend Reports Events Over 2 million developers have joined DZone. Join Today! Thanks for visiting DZone today,
Edit Profile Manage Email Subscriptions Moderation Admin Console How to Post to DZone Article Submission Guidelines
View Profile
Sign Out
Refcards
Trend Reports
Events
Zones
Culture and Methodologies Agile Career Development Methodologies Team Management
Data Engineering AI/ML Big Data Data Databases IoT
Software Design and Architecture Cloud Architecture Containers Integration Microservices Performance Security
Coding Frameworks Java JavaScript Languages Tools
Testing, Deployment, and Maintenance Deployment DevOps and CI/CD Maintenance Monitoring and Observability Testing, Tools, and Frameworks
Partner Zones AWS Cloud
by AWS Developer Relations
Culture and Methodologies
Agile Career Development Methodologies Team Management
Data Engineering
AI/ML Big Data Data Databases IoT
Software Design and Architecture
Cloud Architecture Containers Integration Microservices Performance Security
Coding
Frameworks Java JavaScript Languages Tools
Testing, Deployment, and Maintenance
Deployment DevOps and CI/CD Maintenance Monitoring and Observability Testing, Tools, and Frameworks
Partner Zones
AWS Cloud
by AWS Developer Relations
The Latest "Software Integration: The Intersection of APIs, Microservices, and Cloud-Based Systems" Trend Report
Get the report
  1. DZone
  2. Coding
  3. Languages
  4. Understanding the Java Garbage Collection Log

Understanding the Java Garbage Collection Log

To diagnose any memory problems, the Garbage Collection log file is the best place to start. Take a look at the anatomy of a GC log file in this helpful article.

Ram Lakshmanan user avatar by
Ram Lakshmanan
CORE ·
May. 05, 16 · Tutorial
Like (39)
Save
Tweet
Share
187.03K Views

Join the DZone community and get the full member experience.

Join For Free

To diagnose any memory problems, the Garbage Collection log file is the best place to start. It provides several interesting statistics:

  • When the scavenge (or Young generation) GC ran?
  • When the full GC ran?
  • How many scavenge GCs and Full GCs ran? Did they run repeatedly? In what interval?
  • After the GC process ran, how much memory was reclaimed in Young, Old, and Permanent/Metaspace generations?
  • How long did the GC run?
  • How long did JVM pause when Full GC run?
  • What was the total allocated memory in each generation?
  • How many objects were promoted to old generation?

How to Generate GC Log File?

In order to understand the GC log, you first need to generate one. Passing the following system properties to your JVM would generate GC logs.

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:<file-path>

where file-path: Garbage Collection log file path.


Example:

-XX:+PrintGCDetails -XX:+PrintGCDateStamps -Xloggc:/opt/app/gc.log


-XX:+PrintGCDateStamps would print the absolute time stamp in the log statement (i.e. “2014-11-18T16:39:25.303-0800”).

-XX:+PrintGCDetails property would print the details of how much memory is reclaimed in each generation.

Passing the above system properties would generate a Garbage Collection log file that would look like:

2014-11-18T16:39:25.512-0800: 76.592: [Full GC [PSYoungGen: 26560K->0K(233024K)] [PSOldGen: 632024K->658428K(699072K)] 658584K->658428K(932096K) [PSPermGen: 2379K->2379K(21248K)], 3.0978612 secs] [Times: user=3.09 sys=0.00, real=3.10 secs] 

2014-11-18T16:39:31.536-0800: 82.616: [Full GC [PSYoungGen: 116544K->0K(233024K)] [PSOldGen: 658428K->684832K(699072K)] 774972K->684832K(932096K) [PSPermGen: 2379K->2379K(21248K)], 3.2582136 secs] [Times: user=3.23 sys=0.03, real=3.26 secs] 

2014-11-18T16:39:37.728-0800: 88.808: [Full GC [PSYoungGen: 116544K->12164K(233024K)] [PSOldGen: 684832K->699071K(699072K)] 801376K->711236K(932096K) [PSPermGen: 2379K->2379K(21248K)], 3.4230220 secs] [Times: user=3.40 sys=0.02, real=3.42 secs] 
:
:
Heap
 PSYoungGen total 233024K, used 116544K [0x00000000eaab0000, 0x0000000100000000, 0x0000000100000000)
 eden space 116544K, 100% used [0x00000000eaab0000,0x00000000f1c80000,0x00000000f1c80000)
 from space 116480K, 0% used [0x00000000f1c80000,0x00000000f1c80000,0x00000000f8e40000)
 to space 116480K, 0% used [0x00000000f8e40000,0x00000000f8e40000,0x0000000100000000)
 PSOldGen total 699072K, used 699071K [0x00000000c0000000, 0x00000000eaab0000, 0x00000000eaab0000)
 object space 699072K, 99% used [0x00000000c0000000,0x00000000eaaafff0,0x00000000eaab0000)
 PSPermGen total 21248K, used 2409K [0x00000000bae00000, 0x00000000bc2c0000, 0x00000000c0000000)
 object space 21248K, 11% used [0x00000000bae00000,0x00000000bb05a740,0x00000000bc2c0000)

Anatomy of GC Log Statement

2014-11-18T16:39:37.728-0800: 88.808: [Full GC [PSYoungGen: 116544K->12164K(233024K)] [PSOldGen: 684832K->699071K(699072K)] 801376K->711236K(932096K) [PSPermGen: 2379K->2379K(21248K)], 3.4230220 secs] [Times: user=3.40 sys=0.02, real=3.42 secs]

Let’s pick apart this log statement and examine each field in it:

2014-11-18T16:39:37.728-0800 – Time stamp at which GC ran.

Full GC – Type of GC. It could be either ‘Full GC’ or ‘GC’.

[PSYoungGen: 116544K->12164K(233024K)] – After the GC ran the young generation, space came down from 116544k (i.e. 113mb) to 12164k (i.e. 12mb). Total allocated young generation space is 233024k (i.e.227mb).

[PSOldGen: 684832K->699071K(699072K)] – After the GC ran the old generation space increased from 684832k (i.e. 669mb) to 699071k (i.e. 682mb) and total allocated old generation space is 669072k (i.e. 682mb). In this case after the GC event, old generation's space increased and didn't decrease, which isn't the case always. Here size has increased because all objects in Old generation are actively referenced + objects from young generation are promoted to old generation. Thus you are seeing the increase in the old generation size.

801376K->711236K(932096K) – After the GC ran, overall memory came down from 801376k to 711236k. Total allocated memory space is 932096k (i.e. 910mb).

[PSPermGen: 2379K->2379K(21248K)] – After the GC ran, there was no drop in perm generation space.

3.4230220 secs – the GC took 3.42 seconds to complete.

[Times: user=3.40 sys=0.02, real=3.42 secs] – Real is wall clock time (time from start to finish of the call). This is all elapsed time including time slices used by other processes and time the process spends blocked (for example if it is waiting for I/O to complete).

User is the amount of CPU time spent in user-mode code (outside the kernel) within the process. This is only actual CPU time used in executing the process. Other processes, and the time the process spends blocked, do not count towards this figure.

Sys is the amount of CPU time spent in the kernel within the process. This means executing CPU time spent in system calls within the kernel, as opposed to library code, which is still running in user-space. Like user, this is only CPU time used by the process.

In your case, if the CPU time (3.4 sec) is considerably higher than the real time passed (3.42 Sec), we can conclude that the GC was run using multiple threads. To learn more about the difference between each of these Times, please check out this article.

Image title

Fig: Anatomy of a Garbage Collection Log Statement

Tools to Analyze GC Logs

Depending on the JVM version and the GC algorithm that you use, the GC log format will differ. I have seen 30+ different version of GC logs. It’s tedious to analyze GC logs in a text editor. I highly recommend using http://gceasy.io/ - a universal online Garbage collection analysis tool. It's a free tool that analyzes the Garbage collection logs and provides telemetrics, potential Garbage Collection problems, and Memory problems, and it provides solutions to these problems, as well.

garbage collection Garbage (computer science) Java (programming language) CPU time

Opinions expressed by DZone contributors are their own.

Popular on DZone

  • Implementing PEG in Java
  • Chaos Engineering Tutorial: Comprehensive Guide With Best Practices
  • Demystifying the Infrastructure as Code Landscape
  • A First Look at Neon

Comments

Partner Resources

X

ABOUT US

  • About DZone
  • Send feedback
  • Careers
  • Sitemap

ADVERTISE

  • Advertise with DZone

CONTRIBUTE ON DZONE

  • Article Submission Guidelines
  • Become a Contributor
  • Visit the Writers' Zone

LEGAL

  • Terms of Service
  • Privacy Policy

CONTACT US

  • 600 Park Offices Drive
  • Suite 300
  • Durham, NC 27709
  • support@dzone.com
  • +1 (919) 678-0300

Let's be friends: