Performance Engineering Series – Tuning for Performance - Case Study – 5

 JDK Nuances

JDK upgrades is one of the most discussed topics as it is something that just cannot be changed without looking in to the code. This problem becomes more evident for large enterprise class applications.

Despite the advances in JDK releases providing various optimizations / newer features, JDK8 we can still find JDK8 in being widely used.  This can perhaps be related to the development effort needed to upgrade the underlying code. 

Even after taking the step of upgrading  / recompiling the code on newer JDK’s like JDK11, there still come some issues which arise due to the enhancements and we will look at one such instance today in this brief blog post. 

To give a brief background this application is used for Indexing / Searching and uses Lucene to perform this task as I have described in the previous blog posts.   But one change from the previous posts was that the JDK was upgrade to JDK11 from JDK8 after which this particular problem started to surface.

I have described some tuning cases in the past and it can be recollected that one of the parameter that is passed is for the IHOP (Initiating Heap Occupancy Percentage).  This defaults to about 45% and the JDK provides an option to either increase / decrease it to either delay or speed up the marking cycle.  This was the case until JDK9.

From JDK9 onwards a new feature of AdaptiveIHOP was introduced which has been since evolving. 

In this specific case where this application is running on JDK11, the AdaptiveIHOP has been found to be buggy where in certain instances the threshold falls to 0 and it never goes back (or) it takes a lot of time to find its ground.

This results in the JVM doing back to back mixed collections resulting in poor GC throughput and effects application performance.

This problem has been by far addressed in various patches provided for JDK11 and by JDK15 it works without any issues. 

The following MOS article published by Oracle describes this problem –

https://support.oracle.com/knowledge/Middleware/2832809_1.html

One might need to login to view this, but these are some similar issues published in an open forum –

https://bugs.java.com/bugdatabase/view_bug?bug_id=8238163

https://bugs.openjdk.org/browse/JDK-8245511

As a work around to this problem, it is suggested to disable the AdaptiveIHOP by using this parameter –

-XX:-G1UseAdaptiveIHOP

Then later manually set the IHOP by the normal parameter –

-XX:InitiatingHeapOccupancyPercent=35

GC log messages show up like this -

 
2024-03-04T13:01:30.268+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17926455296B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.277+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17934843904B allocation request: 4432192B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.325+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17943232512B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.328+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17951621120B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.330+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17960009728B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.367+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17968398336B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.390+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17976786944B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.391+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17985175552B allocation request: 4432192B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.392+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 17993564160B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.402+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18001952768B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.408+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18010341376B allocation request: 4432192B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.413+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18018729984B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.433+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18027118592B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.435+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18035507200B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.437+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18043895808B allocation request: 4432192B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.443+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18052284416B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.445+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18060673024B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.454+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18069061632B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.456+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18077450240B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.508+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18085838848B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.510+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18094227456B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.535+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18102616064B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.595+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18111004672B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.599+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18119393280B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.601+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18127781888B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.607+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18136170496B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.670+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18144559104B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.670+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18152947712B allocation request: 4443328B threshold: 0B (0.00) source: concurrent humongous allocation

[2024-03-04T13:01:30.673+0000][debug][gc,ergo,ihop  ] Do not request concurrent cycle initiation (still doing mixed collections) occupancy: 18161336320B allocation request: 4443336B threshold: 0B (0.00) source: concurrent humongous allocation

Here one might also point to the Humongous allocation which is linked to the heap region size.  Although that is correct, in this particular scenario, changing just the region size manually might not help addressing the problem.  It might be required to change both the region size and also disable the AdaptiveIHOP to address the problem which needs to be evaluated and then decided.

In this particular case, the recommendation was to disable the AdaptiveIHOP after which the GC throughput had greatly improved and the application performance was stabilized. 

This is the GC pause time difference as described by one of the posts available online -









Happy Tuning!

Popular posts from this blog

Performance Engineering Series – Tuning for Performance - Case Study - 1

Image
Introduction This series of articles will introduce the reader to explore more about Performance Engineering, specifically how to deal with actual issues of the product in a production deployment scenario.   This is the most discussed area and most of the people I have interacted with look forward to getting in to this role and deal with actual issues and make their contribution.   This work requires knowledge and understanding from a multitude of aspects like –        The product design         Usage profile of the product         CPU and Memory and Disk configuration of the platform         Software configuration – Memory settings         Connected software components and their impact The reader is expected to look at the problem holistically to make the best use of the resources being deployed and then tune the application to obtain the required performance.   As t...
Read more

Performance Engineering Series – Tuning for Performance - Case Study – 4

Image
 ActiveMQ Crash Introduction In this article let us look at an interesting case of ActiveMQ crashing and the symptoms it showed up and how it was resolved.   ActiveMQ is a widely used message broker that talks via a wide range of sources.   In the current context, its used for the purpose of sending email notifications where the test application places a message on the queue for it to be consumed by other interfacing applications for email notification delivery.   The ActiveMQ runs in redundant mode with active standby.   If a node goes down for any reason, the other node immediately picks up the processing and continues until it goes down.   ActiveMQ is initiated using a wrapper which was designed off a community release version and not the regular commercial deployment version.   The limitation of this would be explained later in the article.   Problem It was observed that the ActiveMQ queue fills up due to pending messages (or) the mess...
Read more