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 Video Library
Refcards
Trend Reports

Events

View Events Video Library

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
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

Last call! Secure your stack and shape the future! Help dev teams across the globe navigate their software supply chain security challenges.

Modernize your data layer. Learn how to design cloud-native database architectures to meet the evolving demands of AI and GenAI workloads.

Releasing software shouldn't be stressful or risky. Learn how to leverage progressive delivery techniques to ensure safer deployments.

Avoid machine learning mistakes and boost model performance! Discover key ML patterns, anti-patterns, data strategies, and more.

Related

  • How Java Apps Litter Beyond the Heap
  • JVM Memory Architecture and GC Algorithm Basics
  • Java: How Object Reuse Can Reduce Latency and Improve Performance
  • All You Need To Know About Garbage Collection in Java

Trending

  • The 4 R’s of Pipeline Reliability: Designing Data Systems That Last
  • AI's Dilemma: When to Retrain and When to Unlearn?
  • Comprehensive Guide to Property-Based Testing in Go: Principles and Implementation
  • Unlocking AI Coding Assistants Part 2: Generating Code
  1. DZone
  2. Coding
  3. Languages
  4. Java Runtime Performance Monitoring: GC and Safepoints

Java Runtime Performance Monitoring: GC and Safepoints

Manoj Chandrabhanu shares his method for analyzing Java runtime performance while using Jenkins and looking at logs in JVM.

By 
Manoj Chandrabhanu user avatar
Manoj Chandrabhanu
·
Jul. 16, 16 · Tutorial
Likes (9)
Comment
Save
Tweet
Share
10.9K Views

Join the DZone community and get the full member experience.

Join For Free

JVM internally takes care of many things for us, such as Garbage Collection and JIT Compilation. So JVM also needs its own time to sort out some stuff for itself, outside of the application. Some of the stuff that JVM can do might involve a safepoint (including GC). During a safepoint, all threads running Java code are suspended for JVM to do its work. The application goes to a halt for the time the JVM goes to a safepoint. 

There might be situations where the JVM could have been paused—not because of the GC but because of a safepoint. The -XX:+PrintGCApplicationStoppedTime option tells us the total time the application threads were paused by the JVM. It includes the pause time due to GC as well.

This article explains how to know whether GC was the cause of the pause or if the application was paused for some other reason as well. We will do this by combining the -XX:+PrintGCApplicationStoppedTime option with loggc option.

Consider a simple example. We will monitor Jenkins and see what we can infer. We can start Jenkins using the command below: 

java -XX:+PrintGCApplicationStoppedTime -Xloggc:testgc.log -jar jenkins.war

Now, we look at the testgc.log file and examine the contents: 

0.684: Total time for which application threads were stopped: 0.0303546 seconds
0.741: Total time for which application threads were stopped: 0.0001263 seconds
1.739: Total time for which application threads were stopped: 0.0001794 seconds
2.739: Total time for which application threads were stopped: 0.0001932 seconds
3.065: [GC 33280K->6009K(124928K), 0.0287263 secs]
3.094: Total time for which application threads were stopped: 0.0293479 seconds
3.471: [GC 39289K->4969K(124928K), 0.0157467 secs]
3.487: Total time for which application threads were stopped: 0.0161742 seconds
3.725: [GC 38249K->4417K(124928K), 0.0113980 secs]
3.737: Total time for which application threads were stopped: 0.0117724 seconds
3.944: [GC 37697K->4417K(158208K), 0.0118140 secs]
3.956: Total time for which application threads were stopped: 0.0121504 seconds
4.178: Total time for which application threads were stopped: 0.0004003 seconds
4.551: [GC 70977K->5083K(158208K), 0.0170096 secs]
4.569: Total time for which application threads were stopped: 0.0173157 seconds
4.569: Total time for which application threads were stopped: 0.0002169 seconds
4.569: Total time for which application threads were stopped: 0.0002606 seconds
4.570: Total time for which application threads were stopped: 0.0001754 seconds
4.570: Total time for which application threads were stopped: 0.0001602 seconds
4.570: Total time for which application threads were stopped: 0.0001691 seconds
4.570: Total time for which application threads were stopped: 0.0001383 seconds
4.571: Total time for which application threads were stopped: 0.0001098 seconds
4.571: Total time for which application threads were stopped: 0.0002347 seconds
4.571: Total time for which application threads were stopped: 0.0001441 seconds
4.571: Total time for which application threads were stopped: 0.0001598 seconds
4.572: Total time for which application threads were stopped: 0.0001209 seconds
4.572: Total time for which application threads were stopped: 0.0001218 seconds
4.572: Total time for which application threads were stopped: 0.0001531 seconds
4.572: Total time for which application threads were stopped: 0.0001410 seconds
4.573: Total time for which application threads were stopped: 0.0001531 seconds
4.573: Total time for which application threads were stopped: 0.0001441 seconds
4.573: Total time for which application threads were stopped: 0.0002240 seconds
4.574: Total time for which application threads were stopped: 0.0002022 seconds
4.574: Total time for which application threads were stopped: 0.0001490 seconds
4.574: Total time for which application threads were stopped: 0.0001473 seconds
4.574: Total time for which application threads were stopped: 0.0002129 seconds
4.575: Total time for which application threads were stopped: 0.0002312 seconds
4.575: Total time for which application threads were stopped: 0.0001937 seconds
4.575: Total time for which application threads were stopped: 0.0001705 seconds
4.576: Total time for which application threads were stopped: 0.0001513 seconds
4.576: Total time for which application threads were stopped: 0.0002463 seconds
4.576: Total time for which application threads were stopped: 0.0002093 seconds
4.577: Total time for which application threads were stopped: 0.0001883 seconds
4.577: Total time for which application threads were stopped: 0.0002084 seconds
4.577: Total time for which application threads were stopped: 0.0002320 seconds
4.577: Total time for which application threads were stopped: 0.0001999 seconds
4.578: Total time for which application threads were stopped: 0.0001397 seconds
4.578: Total time for which application threads were stopped: 0.0001040 seconds
4.578: Total time for which application threads were stopped: 0.0001098 seconds
4.578: Total time for which application threads were stopped: 0.0000754 seconds
4.578: Total time for which application threads were stopped: 0.0000692 seconds
4.578: Total time for which application threads were stopped: 0.0001044 seconds
4.579: Total time for which application threads were stopped: 0.0001258 seconds
4.579: Total time for which application threads were stopped: 0.0000768 seconds
4.579: Total time for which application threads were stopped: 0.0000763 seconds
5.407: Total time for which application threads were stopped: 0.0003485 seconds
5.409: Total time for which application threads were stopped: 0.0001977 seconds
5.436: Total time for which application threads were stopped: 0.0002080 seconds
5.717: Total time for which application threads were stopped: 0.0002472 seconds
5.759: Total time for which application threads were stopped: 0.0002267 seconds
6.238: Total time for which application threads were stopped: 0.0002499 seconds
6.492: Total time for which application threads were stopped: 0.0001794 seconds
6.492: Total time for which application threads were stopped: 0.0001910 seconds
6.493: Total time for which application threads were stopped: 0.0002878 seconds
6.493: Total time for which application threads were stopped: 0.0002834 seconds
6.493: Total time for which application threads were stopped: 0.0001847 seconds
6.494: Total time for which application threads were stopped: 0.0001490 seconds
6.494: Total time for which application threads were stopped: 0.0001669 seconds
6.494: Total time for which application threads were stopped: 0.0001602 seconds
6.495: Total time for which application threads were stopped: 0.0002030 seconds
6.495: Total time for which application threads were stopped: 0.0001888 seconds
6.495: Total time for which application threads were stopped: 0.0001923 seconds
6.496: Total time for which application threads were stopped: 0.0001794 seconds
6.496: Total time for which application threads were stopped: 0.0001870 seconds
6.496: Total time for which application threads were stopped: 0.0001830 seconds
6.496: Total time for which application threads were stopped: 0.0001812 seconds
6.497: Total time for which application threads were stopped: 0.0001740 seconds
6.497: Total time for which application threads were stopped: 0.0001669 seconds
6.497: Total time for which application threads were stopped: 0.0001807 seconds
6.497: Total time for which application threads were stopped: 0.0002062 seconds
6.498: Total time for which application threads were stopped: 0.0002405 seconds
6.498: Total time for which application threads were stopped: 0.0001843 seconds
6.499: Total time for which application threads were stopped: 0.0001629 seconds
6.499: Total time for which application threads were stopped: 0.0003396 seconds
6.499: Total time for which application threads were stopped: 0.0001522 seconds
6.501: Total time for which application threads were stopped: 0.0001004 seconds
6.501: Total time for which application threads were stopped: 0.0000705 seconds
6.501: Total time for which application threads were stopped: 0.0000678 seconds
6.501: Total time for which application threads were stopped: 0.0000629 seconds
6.501: Total time for which application threads were stopped: 0.0000968 seconds
6.502: Total time for which application threads were stopped: 0.0000884 seconds
6.502: Total time for which application threads were stopped: 0.0000968 seconds
6.502: Total time for which application threads were stopped: 0.0000678 seconds
6.502: Total time for which application threads were stopped: 0.0000638 seconds
6.502: Total time for which application threads were stopped: 0.0001348 seconds
6.502: Total time for which application threads were stopped: 0.0000647 seconds
6.502: Total time for which application threads were stopped: 0.0000491 seconds
6.503: Total time for which application threads were stopped: 0.0000473 seconds
6.503: Total time for which application threads were stopped: 0.0000477 seconds
6.503: Total time for which application threads were stopped: 0.0000464 seconds
6.503: Total time for which application threads were stopped: 0.0000460 seconds
6.503: Total time for which application threads were stopped: 0.0000455 seconds
6.503: Total time for which application threads were stopped: 0.0000469 seconds
6.503: Total time for which application threads were stopped: 0.0000464 seconds
6.503: Total time for which application threads were stopped: 0.0001272 seconds
6.527: Total time for which application threads were stopped: 0.0001303 seconds
6.527: Total time for which application threads were stopped: 0.0000714 seconds
6.527: Total time for which application threads were stopped: 0.0000732 seconds
6.527: Total time for which application threads were stopped: 0.0000785 seconds
6.550: Total time for which application threads were stopped: 0.0001218 seconds
6.550: Total time for which application threads were stopped: 0.0000683 seconds
6.550: Total time for which application threads were stopped: 0.0000705 seconds
6.550: Total time for which application threads were stopped: 0.0000754 seconds
6.559: Total time for which application threads were stopped: 0.0001821 seconds
6.559: Total time for which application threads were stopped: 0.0001316 seconds
6.559: Total time for which application threads were stopped: 0.0001598 seconds
6.560: Total time for which application threads were stopped: 0.0001464 seconds
6.584: Total time for which application threads were stopped: 0.0001263 seconds
6.584: Total time for which application threads were stopped: 0.0001254 seconds
6.584: Total time for which application threads were stopped: 0.0001080 seconds
6.585: Total time for which application threads were stopped: 0.0001044 seconds
6.623: Total time for which application threads were stopped: 0.0002544 seconds
6.632: Total time for which application threads were stopped: 0.0001254 seconds
6.633: Total time for which application threads were stopped: 0.0002240 seconds
6.633: Total time for which application threads were stopped: 0.0000951 seconds
6.635: Total time for which application threads were stopped: 0.0001419 seconds
6.657: Total time for which application threads were stopped: 0.0005721 seconds
6.657: Total time for which application threads were stopped: 0.0005154 seconds
6.672: Total time for which application threads were stopped: 0.0001232 seconds
6.677: Total time for which application threads were stopped: 0.0000768 seconds
6.677: Total time for which application threads were stopped: 0.0000571 seconds
6.715: Total time for which application threads were stopped: 0.0000736 seconds
6.716: Total time for which application threads were stopped: 0.0000567 seconds
6.716: Total time for which application threads were stopped: 0.0000594 seconds
6.716: Total time for which application threads were stopped: 0.0000397 seconds
6.717: Total time for which application threads were stopped: 0.0000366 seconds
6.720: Total time for which application threads were stopped: 0.0000585 seconds
6.720: Total time for which application threads were stopped: 0.0000527 seconds
6.721: Total time for which application threads were stopped: 0.0000571 seconds
6.721: Total time for which application threads were stopped: 0.0000567 seconds
6.722: Total time for which application threads were stopped: 0.0000567 seconds
6.722: Total time for which application threads were stopped: 0.0000571 seconds
6.730: Total time for which application threads were stopped: 0.0000607 seconds
6.730: Total time for which application threads were stopped: 0.0000531 seconds
6.730: Total time for which application threads were stopped: 0.0000567 seconds
6.731: Total time for which application threads were stopped: 0.0000732 seconds
6.767: Total time for which application threads were stopped: 0.0001589 seconds
6.771: Total time for which application threads were stopped: 0.0000718 seconds
6.771: Total time for which application threads were stopped: 0.0000379 seconds
6.771: Total time for which application threads were stopped: 0.0000437 seconds
6.771: Total time for which application threads were stopped: 0.0000513 seconds
6.786: Total time for which application threads were stopped: 0.0001129 seconds
6.804: Total time for which application threads were stopped: 0.0000759 seconds
6.834: Total time for which application threads were stopped: 0.0000772 seconds
6.844: Total time for which application threads were stopped: 0.0000705 seconds
6.845: Total time for which application threads were stopped: 0.0000567 seconds
6.845: Total time for which application threads were stopped: 0.0000602 seconds
6.845: Total time for which application threads were stopped: 0.0000589 seconds
6.884: Total time for which application threads were stopped: 0.0000768 seconds
6.923: Total time for which application threads were stopped: 0.0000790 seconds
6.932: Total time for which application threads were stopped: 0.0000701 seconds
6.946: Total time for which application threads were stopped: 0.0000754 seconds
6.947: Total time for which application threads were stopped: 0.0000589 seconds
6.947: Total time for which application threads were stopped: 0.0000594 seconds
6.948: Total time for which application threads were stopped: 0.0000683 seconds
6.976: Total time for which application threads were stopped: 0.0000754 seconds
6.976: Total time for which application threads were stopped: 0.0000576 seconds
6.976: Total time for which application threads were stopped: 0.0000598 seconds
6.977: Total time for which application threads were stopped: 0.0000594 seconds
6.982: Total time for which application threads were stopped: 0.0000665 seconds
6.984: Total time for which application threads were stopped: 0.0000585 seconds
6.984: Total time for which application threads were stopped: 0.0000540 seconds
6.984: Total time for which application threads were stopped: 0.0000580 seconds
6.985: Total time for which application threads were stopped: 0.0000580 seconds
6.987: Total time for which application threads were stopped: 0.0000580 seconds
6.987: Total time for which application threads were stopped: 0.0000535 seconds
6.987: Total time for which application threads were stopped: 0.0000580 seconds
6.988: Total time for which application threads were stopped: 0.0000585 seconds
6.995: Total time for which application threads were stopped: 0.0000594 seconds
6.995: Total time for which application threads were stopped: 0.0000531 seconds
6.995: Total time for which application threads were stopped: 0.0000571 seconds
6.996: Total time for which application threads were stopped: 0.0000585 seconds
7.009: Total time for which application threads were stopped: 0.0000620 seconds
7.009: Total time for which application threads were stopped: 0.0000540 seconds
7.009: Total time for which application threads were stopped: 0.0000580 seconds
7.010: Total time for which application threads were stopped: 0.0000576 seconds
7.028: [GC 71643K->11880K(222208K), 0.0437746 secs]
7.072: Total time for which application threads were stopped: 0.0441517 seconds
7.072: Total time for which application threads were stopped: 0.0001209 seconds
7.072: Total time for which application threads were stopped: 0.0001183 seconds
7.073: Total time for which application threads were stopped: 0.0001102 seconds
7.073: Total time for which application threads were stopped: 0.0001044 seconds
7.073: Total time for which application threads were stopped: 0.0000942 seconds

Take a look at the lines below from the log:

3.065: [GC 33280K->6009K(124928K), 0.0287263 secs]
3.094: Total time for which application threads were stopped: 0.0293479 seconds
3.471: [GC 39289K->4969K(124928K), 0.0157467 secs]
3.487: Total time for which application threads were stopped: 0.0161742 seconds
3.725: [GC 38249K->4417K(124928K), 0.0113980 secs]
3.737: Total time for which application threads were stopped: 0.0117724 seconds

All of the entries that say, “Total time for which application threads were stopped,” is caused by the -XX:+PrintGCApplicationStoppedTime option . The rest of the messages are due to the normal loggc option.

As you can see, the application was paused for 0.0293479 seconds. This matches almost with the GC time above. So it means that this application stopped due to the GC happening.

Now, take a look at what happens at approximately 4.5 seconds:

4.551: [GC 70977K->5083K(158208K), 0.0170096 secs]
4.569: Total time for which application threads were stopped: 0.0173157 seconds
4.569: Total time for which application threads were stopped: 0.0002169 seconds
4.569: Total time for which application threads were stopped: 0.0002606 seconds
4.570: Total time for which application threads were stopped: 0.0001754 seconds
4.570: Total time for which application threads were stopped: 0.0001602 seconds
4.570: Total time for which application threads were stopped: 0.0001691 seconds

You can see that there are lot of messages which say that threads were stopped. These are not attributed to the GC events. These are the events when a safepoint might have taken place and the JVM forces the threads to stop. We can see these messages go down till approx 7.010 seconds. Note that in this case, we’re seeing a lot of small pauses apart from GC because the application (in this case, Jenkins) was starting and JVM had to probably load the classes and compile them. So it is expected.

We can use the -XX:+PrintGCApplicationStoppedTime switch along with the GC options to correlate and understand how much time the JVM had stopped the application outside of the GC events.

garbage collection Java (programming language) application

Opinions expressed by DZone contributors are their own.

Related

  • How Java Apps Litter Beyond the Heap
  • JVM Memory Architecture and GC Algorithm Basics
  • Java: How Object Reuse Can Reduce Latency and Improve Performance
  • All You Need To Know About Garbage Collection in Java

Partner Resources

×

Comments

The likes didn't load as expected. Please refresh the page and try again.

ABOUT US

  • About DZone
  • Support and feedback
  • Community research
  • Sitemap

ADVERTISE

  • Advertise with DZone

CONTRIBUTE ON DZONE

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

LEGAL

  • Terms of Service
  • Privacy Policy

CONTACT US

  • 3343 Perimeter Hill Drive
  • Suite 100
  • Nashville, TN 37211
  • support@dzone.com

Let's be friends: