perf: fix the L2 cache region-lock convoy on concurrent metadata-heavy load - #24810
perf: fix the L2 cache region-lock convoy on concurrent metadata-heavy load#24810netroms wants to merge 4 commits into
Conversation
d800cc6 to
6fc9f6c
Compare
6fc9f6c to
4ffddfa
Compare
Master's #24810 predefines hot Hibernate L2 regions as ehcache-native caches to escape hibernate-jcache's forced store-by-value on JSR-107-created caches. That specific problem doesn't apply here: Ehcache 2's native API is always store-by-reference regardless of whether a region is predefined or created on demand via CacheManager#addCacheIfAbsent, so 2.41 never paid the SerializingCopier cost #24810 fixes. What does carry over: without an explicit entry, each of these regions falls back to defaultCache and shares its single 1,000,000-entry cap with everything else. Porting #24810's measured hot-region list and heap bounds into Ehcache 2's native XML syntax gives the busiest regions their own sized, bounded cache instead of competing for headroom in the shared default. org.hisp.dhis.option.OptionSet.options is deliberately excluded: that collection is intentionally left uncached on 2.41 (see OptionSet.hbm.xml) to avoid an N+1 where a cached id list combined with an entity-cache miss makes Hibernate resolve ids one at a time. Predefining the region here would be dead configuration at best. Verified by loading the file through net.sf.ehcache's own ConfigurationFactory/CacheManager: all 29 regions parse and register. Co-Authored-By: Claude Sonnet 5 <noreply@anthropic.com>
Every cached region in DHIS2 uses READ_WRITE, whose access strategy holds one ReentrantReadWriteLock PER REGION (not per key): every get takes the region read lock and every putFromLoad takes the region WRITE lock, even when it writes nothing (entities are unversioned, so an existing entry is never overwritten from a load). Under concurrent load on option-heavy metadata this serialises a whole region behind single-key work: measured 14-15% of ALL JVM wall samples parked in AbstractReadWriteAccess. Switches the static reference bucket (Option*, PeriodType, DataElement, Category*, OptionSet.options, Legend*, Indicator*, OrgUnit hierarchy; 30 files, 71 declarations) to NONSTRICT_READ_WRITE, which has no region lock. Trade-off: a brief staleness window after a write, accepted for reference metadata (sign-off: Morten, 2026-08-07). Period/RelativePeriods stay READ_WRITE. Measured on a tracker-import ramp: parked-in-region-lock 14.15% -> 0.05%, p99 at 100 concurrent users 58.4s -> 20.7s as an isolated change. AI Assisted
Regions created on demand through the jsr107 template are store-by-value: every get and put copies the entry through SerializingCopier, inside the READ_WRITE region lock critical section. Predefining a region in ehcache.xml keeps ehcache-native store-by-reference semantics (Hibernate caches disassembled, immutable entries, so by-reference is safe; 2.41 ran Ehcache 2 by-reference for years). Region list and heap bounds come from measured traffic: the hot metadata regions from a read/write metadata ramp, plus the tracker-import hot set (the Option region alone takes ~98M gets per 25 minute import run). Measured effect in the full combination: SerializingCopier wall samples 236,287 -> 1,057. AI Assisted
dataElementCountDoesNotScaleQueryCount compares a metadata export with 3 data elements against one with 8 and asserted the two select counts were equal. With the cache changes in this branch the second export legitimately issues FEWER selects (21 vs 22): what the first export loaded is still cached during the second. Assert the invariant the test name and comment state - the count must not grow - so the test keeps catching a reintroduced N+1 without failing on a cache improvement. AI Assisted
8801934 to
a128a2e
Compare
|
Rebased onto current master and removed the duplicate scheduler commit entirely — sorry for the noise, @teleivo. This branch previously carried a standalone subset of your wipe fix so it could be measured on its own. Now that #24803 has merged, that commit is gone from the history rather than merged away: the branch is 3 commits, takes the wipe fix from master, and The rewrite is content-neutral — the resulting tree is byte-identical to the one CI just went green on ( What remains here is the other two ingredients: the AI Assisted |
teleivo
left a comment
There was a problem hiding this comment.
NONSTRICT_READ_WRITE can strand a stale entry for up to 6 hours, affecting each key written independently, not just for a brief post-write window. Worth stating explicitly in the trade-off section, since it is otherwise only derivable from the Hibernate source.
The mechanism: a writer under NONSTRICT_READ_WRITE never installs a cache value, it only removes one, and it does so twice per update. Once at flush, EntityUpdateAction.execute -> cacheUpdate -> update(), per entity and early; once after commit, doAfterTransactionCompletion -> afterUpdate -> unlockItem, per transaction and late. Both resolve to removeFromCache on the same key. Between them the row is written but not committed, so a concurrent reader misses, loads the old committed row, and installs it via putFromLoad. Normally the post-commit evict removes it. But that is a point-in-time deletion, not a barrier, so a reader whose put lands after it leaves the old value with nothing left to remove it:
T1 (writer) T2 (reader)
flush: evict-at-flush
get() -> miss
DB load -> old committed row
COMMIT
evict-after-commit
putFromLoad -> installs STALE value <-- survives both evicts
The put succeeds because NONSTRICT_READ_WRITE inherits the unguarded putFromLoad with no version or timestamp check. Previous, READ_WRITE overrides it: lockItem leaves a SoftLockImpl in the slot for the whole window and putFromLoad tests isWriteable against it and returns false, so the late put is refused rather than raced. That override is the entire difference on the read path.
No ordering is guaranteed between the reader's put and the post-commit evict, so this cannot be argued away on probability: it will occur under enough concurrency. No counter distinguishes a stale hit from a valid one, and reproducing it means winning a scheduling race, so it will surface only as an unexplained "metadata edit did not take effect".
With nothing left to remove it, the stale entry survives until the configured 6h ttl, the next write to that key, or a manual evict, and since these entities carry their Sharing JSONB that 6h is also the worst-case ACL-revocation lag.
| <!-- Entity regions --> | ||
| <cache alias="org.hisp.dhis.organisationunit.OrganisationUnit"> | ||
| <expiry><ttl unit="seconds">21600</ttl></expiry> | ||
| <resources><heap unit="entries">200000</heap></resources> |
There was a problem hiding this comment.
How did you come up with the number of entries per metadata?
There was a problem hiding this comment.
This should be slightly higher and may also require people to use a custom ehcache.xml file, if they have extremely large amounts of orgunits for example. The vast majority of the time, most DBs will not have this many orgunits but there are cases when it exceeds this. All of these seem like reasonable default values, but we should probably have a second look.
The previous six hour TTL was inherited from the old Ehcache 2 configuration. TTL is the upper bound on how long a stale cache entry can survive, whether it went stale through an out-of-band database change (no load ever refreshes an existing entry for unversioned entities) or through a late cache-put re-inserting a value just evicted by a concurrent write under NONSTRICT_READ_WRITE. One hour tightens that bound for every region at the cost of one reload per entry per hour, which is noise at production request rates. Instances with stricter staleness expectations can override the whole file via cache.ehcache.config.file. Also rewrites the region declaration comments in neutral terms: why declared caches are store-by-reference while runtime-created ones are forced store-by-value by the JCache defaults, how the region list and heap bounds were chosen, and how to tune both from the per-region metrics exposed at /api/metrics. AI Assisted
|
The reported performance improvements look good - nice job 👍 Some questions:
I think the worst case risk (taking into account the low probability) from a stale value needs to be stated very clearly and accepted by Product. |
|
The performance improvements are definitely mouth watering. Nice work @netroms Would it be possible to use our performance test gh pipeline to generate a perf test comparison report (baseline as master and candidate as this PR)? |
|
Adds the tracker import simulation to the ramp harness: synchronous POST /api/tracker of synthetic events against an option-heavy event program (14,000-option option set on the Sierra Leone demo database), interleaved with capture-style metadata reads, in single-event and batched payload modes. This is the workload that reproduces the second level cache collapse under concurrent load and the one the numbers in dhis2#24810 were measured with. Together with the read-heavy and write-mixed ramps and the sampling sidecar already in this branch, this completes the measurement kit: runnable locally via run-simulation-sidecars.sh, or through the performance-tests workflow (the simulations and PROF_ARGS profiling need nothing outside dhis-test-performance). AI Assisted
@ameenhere done. Two dispatches of Runs, with the full Gatling reports and wall-clock flame graphs as artifacts:
Successful imports per second, per concurrency step (an import only counts as OK if the
Over the whole run master completed 443 imports with a 33.7% error rate across all Two things to know when reading the baseline report so nobody misreads it:
If you want to run it yourself the exact dispatch recipe (one |
teleivo
left a comment
There was a problem hiding this comment.
Thank you @netroms for updating the PR and re-running the tests! The numbers do look great 😄 (which is also understandable given we remove locks from the cache algorithm).
Both "rare" and "a few milliseconds" are unmeasured. We don't know the frequency, and the window is not how much code runs between commit and eviction but how long that code takes in wall-clock time. OS scheduling affects that, and the delay grows under exactly the load this PR targets. Stranding is simply a possibility with an unknown rate, which means the decision has to be based on whether the worst case is acceptable at any frequency.
Worst case scenario is server crash which we have seen multiple times. The increase RPS here is a great by-product, but that is not the actual point of this PR. It is to prevent the server from locking up. |
What this PR changes
Two changes to how the Hibernate second-level cache treats static reference metadata, plus one
config tightening:
READ_WRITE→NONSTRICT_READ_WRITEfor the reference-metadata regions (options,category structures, data elements, org unit hierarchy, indicators, legends, and friends).
ehcache.xml, sized deliberately andstored by reference instead of by serialized copy.
outlive an hour.
The result on concurrent tracker imports: 26 → 127 rps at 100 concurrent users (4.9x), with
p99 latency 13.9 s → 6.9 s. At 400 users: 26 → 110 rps, p99 39.8 s → 9.9 s. Both builds are
identical except for these commits. Full table and method at the bottom.
The problem: what a cache read actually costs today
Picture a busy instance: a few hundred data clerks submitting tracker events. Every single
submission validates its data values against the same reference metadata: the data elements,
their option sets, the options themselves. With an option-heavy program (think a 14,000-option
diagnosis code list), one submission triggers thousands of cache reads. That is the workload the
second-level cache exists for, and today each of those reads pays two taxes.
Tax 1: one lock per region, paid on every read
READ_WRITE's access strategy guards each region with a single lock. Not per entry, perregion:
Every
gettakes the read lock; everyputFromLoadtakes the write lock, the exclusiveone. All 14,000 options share one turnstile, and every query that loads options from the
database grabs that turnstile exclusively to re-insert what it just read.
Here is the part that makes it absurd for DHIS2 specifically: our entities are unversioned,
and
READ_WRITErefuses to overwrite an existing cache entry from a load unless the incomingversion is newer:
So the sequence on every re-load of an already-cached option is: take the region's exclusive
write lock → inspect the entry → decide it must not be written → release the lock → put
nothing. A few hundred concurrent users all paying exclusive-lock prices for a no-op, on the
hottest region in the system. Under load this shows up directly in wall-clock profiles.
On the metadata read/write workload, 14.2% of all JVM wall samples sit parked inside
AbstractReadWriteAccesson the unmodified build; this PR takes it to 0.1%.What is that machinery for? It exists so that concurrent writes to cached entities cannot leave
readers with torn or resurrected state. That is the right trade for entities that change under
concurrency. Reference metadata does not: an option list changes when an implementer configures
the system, not when a user submits an event. We are paying a per-read cost for a per-write
guarantee on data that is, in production, read millions of times between writes.
Tax 2: every read photocopies the entry
The JCache (JSR-107) spec defaults to store-by-value:
Hibernate creates any region that is not declared in
ehcache.xmlat runtime, through exactlythat API (
JCacheRegionFactory.createCache), so every runtime-created region gets Ehcache'sSerializingCopierinstalled, and it copies in both directions:Reading a cached option does not hand you the cached object. It serializes the stored entry to a
ByteBufferand deserializes a fresh copy, like a library that photocopies the page every timesomeone wants to read it. On every get. On every put. And under
READ_WRITE, inside theregion lock's critical section, so tax 2 lengthens exactly the time everyone else spends queued
on tax 1. On the tracker import workload the copier accounts for 227,514 wall samples on the
unmodified build vs 1,086 with this PR.
Change 1:
NONSTRICT_READ_WRITEfor reference metadataWhat
READ_WRITEactually guarantees (i.e. what we are giving up)Worth being precise about, because the guarantee does not come from the read path. An
already-cached entry is never refreshed by a load:
Item.isWriteablereturnsversion != null && …, and our entities are unversioned, so a load can never overwrite it.Freshness comes entirely from the write path:
So a metadata write under
READ_WRITEruns like this:lockItem(), pre-commitafterUpdate(), post-commitAnd the racing load (the one that read the old row just before the write) meets the soft lock on
its way back in and is refused. That refusal is the protection, not a gap: the entry it declines
to overwrite is the correct one, because the write path just put it there. This is what Change 1
gives up, and the trade-off below is the honest price.
One thing
READ_WRITEdoes not protect against, which matters for the TTL discussion: a rowchanged outside Hibernate (raw JDBC, a native
executeUpdatethat does not invalidate, adirect database edit) leaves a cached entry that no load will ever refresh, for the same
"never writeable" reason. Under
READ_WRITEas it ships today, that entry is stale until TTL,eviction, or the next Hibernate-managed write to that key.
What
NONSTRICT_READ_WRITEdoes insteadNONSTRICT_READ_WRITEremoves the lock machinery entirely. Reads are plain cache gets; a writeevicts the key twice, once during the transaction and once after commit, instead of soft-locking
it:
The trade-off, stated precisely
Giving up the locks buys the throughput and costs two well-defined staleness windows. Both
require a write to the metadata. No write, no staleness, ever.
Window 1: the post-write gap. Between the database commit and the second eviction, a
concurrent reader can still be served the previous value. Duration: milliseconds, at worst
seconds. Realistically: an admin renames an option while data entry is running, and a handful of
requests in flight at that exact moment still render the old name. The next request sees the new
one.
Window 2: the stranded key. Rarer, and the reason the TTL matters. A reader that loaded the
previous value from the database can complete its cache-put after the writer's final
eviction, re-inserting the stale value. Nothing refuses that late put; the refusal logic was
precisely the lock we removed. That single key then serves the old value until the next write to
that key, or until TTL expiry, with this PR at most one hour.
Step by step.
Ris a request thread loading metadata;Wis a transaction saving a change tothe same key:
Wstarts its update. It evicts the key (first eviction) and updates the database row. Ithas not committed yet.
Rgets a cache miss (the key was just evicted) and reads the row from the database.Whas not committed, so
Rsees the old value.Wcommits, then evicts the key again (the post-commit eviction). The cache is now empty forthis key. Everything is still correct.
Rcompletes its cache-put with the value it read in step 2. The cache now holds the oldvalue again. Nothing rejects the late put: the check that would reject it is part of the lock
machinery this PR removes.
The same race as a sequence diagram:
sequenceDiagram participant R as R (request thread) participant C as L2 cache participant DB as Database participant W as W (metadata write) W->>C: 1. evict(key) W->>DB: 1. UPDATE row (uncommitted) R->>C: 2. get(key) C-->>R: miss (key was just evicted) R->>DB: 2. SELECT row DB-->>R: old value (W not committed yet) W->>DB: 3. COMMIT W->>C: 3. evict(key), post-commit Note over C: empty, still correct R->>C: 4. put(key, old value), nothing rejects it Note over C: STALE: every read is now a hit,<br/>no reader returns to the database.<br/>Cleared by the next write to this key, or TTL (max 1 h)From step 4 on, every read of this key is a cache hit. No reader goes back to the database, so
nothing corrects the entry. It survives until the next write to this key, or until TTL expiry,
with this PR at most one hour.
How likely is step 4?
Rmust read the row in the final moments beforeWcommits, and itscache-put must land just after
W's post-commit eviction, which follows the commit within abouta millisecond. The race window is a few milliseconds wide, and it exists only while a metadata
write is in flight. Metadata writes are rare events: an option set is edited a few times a
month, not continuously. Between writes the risk is exactly zero. But writes happen during
working hours, when data entry traffic peaks and hundreds of reads are in flight. Over months on
a busy instance, expect the occasional hit. That is why the defence is the bound, not the
odds. The failure mode is one stale option label for at most an hour, once in a while, not data
corruption. Data values never live in these regions; a stale option list cannot change what was
stored, only what one node briefly believes the list looks like.
Concrete worst cases, honestly stated:
every node sees it within milliseconds-to-seconds. Only a window-2 stranding could pin the old
option list on one key; in that case imports using the new option could be rejected on that
node for up to an hour. Re-saving the option set evicts the stale entry immediately.
sharing for up to the same hour; revoking a user's access to a data element is not guaranteed
to be instantaneous on a key that lost the race. Same bound, same probability structure, and
the reason the TTL cap is part of this PR rather than a follow-up.
Why one hour
The previous six-hour TTL was inherited from the old configuration. Six hours was invisible
before because nothing lived that long anyway; with the cache actually working, TTL becomes the
real bound on window 2, so this PR lowers it to 3600s across the board. Cost: each cached entry
reloads once per hour, which at measured request rates is noise. If even one hour is too long for
a deployment's ACL expectations, the file is overridable per instance (see Tuning below).
Note that this cap is not only a concession for Change 1. As shown above, a cached entry that
goes stale through an out-of-band write is bound by TTL under
READ_WRITEtoo, so on mastertoday that bound is six hours. Lowering it to one hour tightens an existing exposure for every
region, whichever strategy it uses.
Period/RelativePeriodsstayREAD_WRITEdeliberately: they are written at runtime by periodgeneration, which is exactly the workload
READ_WRITEis for.Change 2: declare the hot regions, store them by reference
Store-by-reference cannot be switched on globally: the copier is installed by the JCache layer
for every cache created at runtime (see Tax 2), and the only way out is for the cache to already
exist, i.e. to be declared in
ehcache.xml. So this PR declares the measured-hottestregions explicitly (options, category combos and their option combos, data elements, org units,
users, and the other regions that dominate get-counts under tracker load; the option region alone
out-reads the next region by two orders of magnitude on this workload).
Declared regions hold a reference to the stored entry instead of round-tripping it through a
serializer. This is safe for how Hibernate uses the cache: it never caches live entity objects.
It caches the entity's disassembled state (an array of property values) and reassembles a
fresh entity instance from that array on every cache hit. The cached array is never handed to
application code and never mutated in place, so sharing it by reference cannot leak writes
between sessions.
Declaring the regions also forces the sizing question into the open instead of leaving every
region at the template's one-million-entry default:
These are deliberate over-provisions above the row counts of large real-world databases. The
point is that they are now explicit, bounded, and per-region tunable instead of implicit and
uniform. They are defaults, not claims of optimality; the next section is how to correct them
with data instead of guesswork.
Measured effect
Same-parent comparison: two builds from the same master commit, differing only by this PR's
commits. Gatling closed-model ramp, 10 → 400 concurrent users with 60s plateaus; synchronous
POST /api/trackersingle-event imports of an option-heavy event program (14,000-option optionset) interleaved with capture-style metadata reads; batched-payload and metadata write-mixed
profiles as separate cells; Sierra Leone demo DB; n=3 runs per cell; async-profiler wall-clock
profiling on every run.
SerializingCopier(tracker)* 60,001 ms is the 60 s request timeout: at 400 users the unmodified build's batched imports
time out rather than complete. Run-to-run spread is within ±1 rps on all cells except
write-mixed with this PR (±10).
Anatomy of the timeout. Why does the unmodified build time out rather than just slow down?
Connection hold time. An import holds its pooled connection for its whole transaction,
including all the time its thread spends inside the JVM rather than in the database. At the
400-user plateau the pool runs full in both builds; the difference is what a connection is held
for. On the unmodified build, Hikari reports 78 of 80 connections checked out while
pg_stat_activityshows only about one of them executing SQL. The other 78 sit idle intransaction, the oldest for around 20 seconds, their owning threads copying cache entries and
queuing on the region lock. Each request occupies a pool slot for tens of seconds, arrivals
outpace turnover, the queue for a free connection compounds, and requests cross the 60 s
timeout. With this PR the holds are about four times shorter (oldest idle-in-transaction around
5 seconds), the same 80-slot pool turns over 2.5x faster (35 rps vs 14), and every request
completes. A residual of 57 idle-in-transaction connections remains and is expected: holding
the connection across the import transaction, including its legitimate in-JVM phases, is how
the import is structured. This PR shortens the hold; it does not claim to remove it.
The two profile rows attribute the gain to its causes: the parked-lock share (visible on the
write-mixed profile) is what Change 1 removes; the copier samples (dominant on the tracker
profile) are what Change 2 removes. Note the last row: SQL volume per request is unchanged. The
PR serves roughly five times the requests at the same eight SELECTs per request; the gain is
in-JVM contention removed, not database work avoided.
Tuning and operations
Nothing here is hardcoded policy. The numbers are defaults with a feedback loop:
gets,hits,puts,evictionsvia/api/metrics(Prometheus) whenmonitoring.ehcache.enabledis on. No restart needed to look.evictions > 0while hot is undersized; raise its heap entries.declaration (and with it, by-reference storage).
law.
cache.ehcache.config.filepoints an instance at its own copy of thefile: config change and restart, no rebuild.
Test changes
Two integration tests pinned the previous configuration and are updated to pin the new one:
HibernateEhcacheConfigFileTestnow asserts both heap-bound paths (a template-inherited regionand an explicitly declared one) instead of assuming every entity region inherits the template;
DataSetMetadataExportServiceQueryCountTestasserts the query count does not grow instead ofexact equality, which is what its own comment says it means (this PR makes the second export
cheaper).
AI Assisted