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

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