High amount of Acquire and Release lock acquisition time being wasted on I18n localtiozation cost of low value message - ReadLockManager.addReadLock is being slow because of ConcurrencyUtil.createReadLockAcquisitionMetadata because of TraceLocalization.buildMessage("concurrency_util_read_lock_acquisition_metadata") #2152
Comments
|
Hello we did some logging performance improvement in #2174 . |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
All the massive dump information on this bug has been reported to Oracle via a private channel.
In a specific live application where the level of concurrency is really high, we have a very specific CacheKey that is extremely popular. We have encountered a MassiveDump being generated not because of a deadlock, but as a result of throttling the performance of the application attributed to this bottleneck cache key. The bottleneck cache key looks like this
CacheKey
(WhateverEntity):
(primaryKey: WhateverEntityPrimaryKey)
(object hash code: 1746196526)
(cacheKeyClass: org.eclipse.persistence.internal.identitymaps.HardCacheWeakIdentityMap.ReferenceCacheKey)
(cacheKey hash code: 1828274617)
(current cache key owner/activeThread: Null)
(getNumberOfReaders: 90)
(concurrencyManagerId: 105,503)
(concurrencyManagerCreationDate: 2024-05-06 05:53:07.768)
(totalNumberOfTimeCacheKeyAcquiredForReading: 22,594,187,969)
(totalNumberOfTimeCacheKeyReleasedForReading: 22,594,187,879)
Upon close examination of the cache key provided above, a few observations become evident:
High Number of Readers:
The current number of readers associated with this cache key is exceptionally high. Specifically, we have a total of 90 threads that currently own the cache key for reading. These threads may need to invoke the
org.eclipse.persistence.internal.helper.ConcurrencyManager.releaseReadLock(ConcurrencyManager.java:697)method at any given time.Potential Contention:
Additionally, there may be just as many threads (or even more) attempting to acquire this cache key for reading. These threads will contend for access to the synchronized block defined in the
org.eclipse.persistence.internal.helper.ConcurrencyManager.acquireReadLockNoWait(ConcurrencyManager.java:373)method.Addressing the Issue:
Our current focus is on resolving the specific problem related to this highly popular cache key.
Blocked Threads:
It's crucial to note that our extensive thread dump reveals a significant number of threads blocked on the synchronized block. These threads are actively competing to either increment or decrement the count of readers. As an illustration, I've included two examples of such threads from our massive dump (page 01).
Here is the example of thread BLOCKED trying to release this problematic CacheKey.
Next we have the example of another thread equally blocked trying to access this contentious cachekey, this time to increase the counter of readers.
Next we have the example of yet another thread blocked on different pattern to acquire read lock.
Understanding the Concurrency Challenges with the Cache Key
Up to this point, we should understand the following:
High Level of Concurrency:
Our application experiences an exceptionally high level of concurrency. It is in the nature of this application.
The sheer volume of concurrency requests places significant strain on the eclipselink cache.
The Fatal Cache Key:
One particular cache key stands out—it's incredibly popular. Unfortunately, its popularity becomes a bottleneck, affecting overall performance.
Read Lock Performance:
The code responsible for acquiring and releasing read locks is struggling to keep up with the demand generated by this highly accessed cache key. The sheer concurrency exacerbates the issue. While read lock acquisition/release performance is acceptable for your average CacheKey, it falls short for a CacheKey as popular as this one in an application under as much pressure and parallelism as this.
Identifying the Bottleneck:
Instead of focusing solely on reducing the number of accesses to this cache key, let's delve into the root cause of the slowdown. What specifically causes delays in the CacheKey code related to read locks?
Surprising Discovery:
The answer surprised me. As I expected, it is related to the logic of keeping the very valuable data about threads acquiring CacheKeys for reading. Yes, it is related to the code of the ReadLockManager. This much I expected. However, the surprising aspect is the specific code within the ReadLockManager that is at fault
When we explore the threads that are currently withing the synchronized CacheKey and we have a look at what they are doing we find patters such as the following.
I will only put a subset of the hits.
Now we have our answer.
The culprit is this line of code here:
at org.eclipse.persistence.internal.helper.ConcurrencyUtil.createReadLockAcquisitionMetadata(ConcurrencyUtil.java:1883).In short it is a mix of a lot of CPU time spent between gettig the i18n ResourceBundle of Eclipselink and the code behind MessageFormat.format.
Between
ResourceBundle.getBundleandjava.text.MessageFormat.formatA tremendous amount of CPU time is wasted on every single read lock acquisition.
If we now ask ourselves, what exactly this localized message are trying to get here.
let us have look at the code
The actual line of code that we are wanting to patch is this
This shocked me quite a bit.
I was expecting to be much deeper problem, some collection cost withig add/removing metadata.
But no, it is High Cpu cost just to initialize a constant with the text
{ "concurrency_util_read_lock_acquisition_metadata", "No stack trace take. isAllowTakingStackTraceDuringReadLockAcquisition is false."}
In the meantime, I will provide our project team a patched eclipselink where the line of code lookslike this,.
This change should significantly boost cache performance without compromising any of the precious metadata we want to retain.
However, I’d like to caution about the following: If possible, EclipseLink should avoid frequent calls to the ResourceBundle.getBundle code. The search for the resource bundle is expensive, and the LOCALE of a running server essentially never changes once it is set. Calls to APIs like EclipseLinkLocalization.buildMessage should minimize unnecessary loading of the resource bundle. Implementing some form of caching could provide the answer without additional overhead.
The text was updated successfully, but these errors were encountered: