Bug #11037
Record not being evicted from FFCache
100%
Related issues
History
#1 Updated by Andrei Plugaru 9 months ago
While investigating #10247, I found a scenario where an entry is not being evicted from FFcache at the invalidation stage. This happens when there are 2 queries for the same record. Only the entry associated to a query is deleted. This is a testcase to reproduce the issue:
def temp-table table3 field f1 as int field f2 as logical index idx_1 is primary unique f1. create table3. table3.f1 = 1. table3.f2 = false. find first table3 where f1 = 1 and not table3.f2 no-error. find first table3 where f1 < 10 and not table3.f2 no-error. assign table3.f2 = true . find first table3 where f1 = 1 and not table3.f2 no-error. message available(table3). //OE: false; FWD true
Basically, the last query returns the record from FFCache, as the entry associated with that query wasn't evicted.
The root cause is FastFindCache.ReverseLookup.Value.invalidate. Here it is the initial code:
private void invalidate(BitSet dirtyProps, LRUCache<Node, Value> lruCache) { for (Node node = head; node != null; node = node.next) { if (dirtyProps != null && node.key.k2.nonIndexedProps != null && !node.key.k2.nonIndexedProps.intersects(dirtyProps)) { continue; } if (node == head) { head = node.next; } node.remove(); lruCache.remove(node); } } }
The exact problem is that in
node.remove() the next reference is removed, however we still need it for the for loop, so it exits without iterating through the entire list. I managed to fix my testcase with this patch:
However, I will also look in other methods from there in order to understand if this pattern is used elsewhere.
#3 Updated by Andrei Plugaru 9 months ago
FFCache.cache, like how it happens in FFCache.invalidate(int dmoUid, Integer multiplex, boolean remove).I mainly discovered 2 issues:
- Even though the entries from
ReverseLookup.reverseCachewill typically be removed when the Rec ids will not be hard referenced anywhere else, there is a problem forNO_RECORD. This is a class static filed, so it is always referenced, so the associated entries fromReverseLookup.reverseCachewill never be deleted. - There is at least one execution path when records from
ReverseLookup.lruCacheare not deleted. We are only removing entries from there, when single records are invalidated. However, when the records for an entire dmo should be invalidated(like when called fromFFCache.invalidate(int dmoUid, Integer multiplex, boolean remove)), they are not removed. This causes a real functional problem as inReverseLookup.put(RecordIdentifier<String> recID, Map<L2Key, RecordIdentifier<String>> l3Cache, Key key)we check whether an entry already exists, so the entry is not inserted into reverse lookup, even though it is in the main cache from FFcache. This functional problem can be aleviated by performing some checks inReverseLookup.putto understand if the existing entry is valid or not. However, I feel like this is not the right way. The main downside is that we will consume memory for entries which are not valid, maybe leading to problems in this regard. I feel like we need a mechanism for eagerly removing the entries exactly in the moment when the dmo is invalidated, however also providing good performance results. This should also reduce the number of records in this map. I came across #10776, where it was mentioned that callinggetwas slow on the map fromReverseLookup.
#4 Updated by Andrei Plugaru 9 months ago
- Status changed from New to WIP
- Assignee set to Andrei Plugaru
After a discussion yesterday with Alex, we decided to tackle the problem of invalid records in ReverseLookup.lruCache wit this approach: always add the new entry in ReverseLookup.put no matter if the node currently exists or not. The solution would have looked like:
void put(RecordIdentifier<String> recID, Map<L2Key, RecordIdentifier<String>> l3Cache, Key key)
{
Node node = new Node(l3Cache, key);
Value value = reverseCache.get(recID);
if (value == null)
{
value = new Value(recID);
}
value.addNode(node);
reverseCache.put(recID, value);
if (lruCache.containsKey(node))
{
touch(l3Cache, key);
}
else
{
lruCache.put(node, value);
}
}
However, I have put more thought into that and realised this could cause a memory leak. The problem is that we would add the new Node instance to the Value, however this node instance won't be added into the lruCache as we already have an equivalent instance there. This would mean that this node instance won't be evicted from memory as it isn't tracked into the lruCache. We would basically have the Node and the associated Value objects hanging in memory.
My solution, currently is to identify if we have stale data in lruCache(if the current RecId associated to the Node is different then the recId we try to insert). If that is the case, we remove that node(both the entry node -> value from lruCache and also the links to this node in the linked list in Value).
Show
I have tested this solution, together with the one from #11037-1 and the problems in the unit tests from the large customer application are solved. I will put this into a branch soon in order to be properly reviewed.
#6 Updated by Alexandru Lungu 8 months ago
- Status changed from Review to WIP
- % Done changed from 0 to 90
Review of 11037a:
- Why do you need to actually check if
nodeToRemoveis inside the list? Can't you runnodeToRemove.remove()(and other operations related to head and lruCache@) directly? FYI, the list can be very large and iterating it may be very costly, considering that the nodes containKeywith actual arguments, FQL, etc.- If the node is not in the value, then the
remove()is no-op, removal fromlruCacheis done reasonably and setting ofheadwon't be possible.
- If the node is not in the value, then the
- I do not understand the changes in
invalidateand why they are required. They seem to rewrite the for loop in a while loop without any functional change.
#7 Updated by Alexandru Lungu 8 months ago
- Related to Bug #10776: FFC.touch standing out in profiling added
#8 Updated by Andrei Plugaru 8 months ago
Alexandru Lungu wrote:
- Why do you need to actually check if
nodeToRemoveis inside the list? Can't you runnodeToRemove.remove()(and other operations related to head and lruCache@) directly? FYI, the list can be very large and iterating it may be very costly, considering that the nodes containKeywith actual arguments, FQL, etc.
- If the node is not in the value, then the
remove()is no-op, removal fromlruCacheis done reasonably and setting ofheadwon't be possible.
nodeToRemove comes from ReverseLookup.put. There, a Node instance is created, however, only taking into account l3Cache and key. So, it doesn't have set the structures related to the linked list(prev and next). Therefore, only calling nodeToRemove.remove() won't actually remove it from the linked list. So, this is why I needed the exact instance that was already stored. I understand, however, the performance implications of this and I think that your solution from #10776 where we can access the Node based on the FastFindCacheEntry may come in handy.
I do not understand the changes in invalidate and why they are required. They seem to rewrite the for loop in a while loop without any functional change.
There is actually a slight functional change there:)). This is the diff for the change:
private void invalidate(BitSet dirtyProps, LRUCache<Node, Value> lruCache) { - for (Node node = head; node != null; node = node.next) + Node node = head; + + while (node != null) { - if (dirtyProps != null && - node.key.k2.nonIndexedProps != null && - !node.key.k2.nonIndexedProps.intersects(dirtyProps)) + Node nextNode = node.next; + + boolean shouldSkip = (dirtyProps != null + && node.key.k2.nonIndexedProps != null + && !node.key.k2.nonIndexedProps.intersects(dirtyProps)); + + if (shouldSkip) { + node = nextNode; continue; } - + if (node == head) { - head = node.next; - } - - node.remove(); - lruCache.remove(node); - + head = nextNode; + } + + node.remove(); // Safe to disconnect now + lruCache.remove(node); // Remove from cache + + // Advance the loop using the saved reference + node = nextNode; + } + }
The problem was that the next property is accessed after node.remove(); is called. Inside node.remove, next and prev properties are reset. So, node.next will return null. In my changes I save the reference to node.next right at the beginning of the while loop, so I can access it after node.remove is called.
#9 Updated by Alexandru Lungu 7 months ago
- % Done changed from 90 to 100
- Status changed from WIP to Review
Andrei, please embed the changes from 10776 into 11037a and let me review and test it as a whole (according to #10776-9)
#10 Updated by Andrei Plugaru 7 months ago
Alexandru Lungu wrote:
Andrei, please embed the changes from 10776 into 11037a and let me review and test it as a whole (according to #10776-9)
I'm on it, however, I don't think it is really ready for the review. Your changes from #10776 can allow a more performant solution as I said in the 1st paragraph from #11037-8. I will try to implement that.
#12 Updated by Andrei Plugaru 7 months ago
I have committed 11037a/rev. 16327. I removed the part where I was deleting the stale nodes at put operation. I have changed into removing the records from the reverse lookup when the invalidation in the main cache happens. This was possible as after 10776a, I have the FastFindCacheEntry objects there.
I have retested the testcase from #11037-1 and #10776-10 and they are solved.
Alex, please review!
#13 Updated by Alexandru Lungu 6 months ago
- Assignee changed from Andrei Plugaru to Alexandru Lungu
#14 Updated by Alexandru Lungu 22 days ago
- Assignee changed from Alexandru Lungu to Artur Școlnic
#15 Updated by Alexandru Lungu 22 days ago
- Related to Feature #11638: Reduce FastFindCache invalidation thrashing added
#16 Updated by Artur Școlnic 20 days ago
Alex, claude found a few issue with the changes, some of them were bogus or just style, but these 2 are legitimate.
1. A common query sequence throws a NullPointerException
Each cached query result now carries a pointer to its own slot in the reverse-lookup table, so a cache hit can refresh that slot directly instead of searching for it. The pointer is filled in when the result is registered — but the registration code does nothing at all when it finds an existing entry under the same key, so in that case the pointer is never filled in and stays null. The next cache hit hands that null straight to the LRU code, which dereferences it.
This isn't a corner case. It's reachable because bulk invalidation clears the results table but leaves the matching reverse-lookup entries behind — the cleanup added in rev 16327 runs after the clear instead of before it, so it always finds an empty map and does nothing, and three other invalidation paths never got the cleanup at all. So:
1. Run a FIND. It gets cached.
2. Create or modify a record in that table. The cached result is dropped, the reverse-lookup entry survives.
3. Run the same FIND again. It misses, and re-caches — with a null pointer, because the leftover entry is still there.
4. Run it once more. It hits, and throws.
The exception isn't caught anywhere on the way out; it surfaces inside the converted 4GL code. This is a regression from rev 16326 — the previous version of this code looked the slot up by key and handled "not found" harmlessly.
Worth knowing: rev 16325 had added a guard for exactly this leftover-entry situation, and rev 16327 deleted it. Simply restoring that guard won't help, though — it only fired when the re-cached query returned a different record, and the common case is the same record.
2. Closing a temp-table scope throws ConcurrentModificationException
The new cleanup routine walks a results map and, for each entry, removes the matching reverse-lookup node. But removing that node also deletes the entry from the map being walked. The map is a plain HashMap, so the walk fails as soon as there are two entries to visit.
Every temp-table scope close goes through this path. Two cached FINDs on one index is enough — the same query with two different parameter values, for instance. When it throws, the rest of the scope teardown never runs: the cache isn't dropped, the temp table isn't dropped, the multiplex bookkeeping is left half-done. The surrounding code only catches PersistenceException, so it escapes as a deferred application error.
The fixes are in rev 16328.
#17 Updated by Alexandru Lungu 20 days ago
- Status changed from Review to Internal Test
The fixes are in rev 16328.
Please take the time to generate unit tests for #11037. Use AI-Assisted_Testcases_Workflow
- Extract tests from a Redmine task
- Canonicalize a raw folder into tests/
These two should be enough. Please run them with trunk, 11037a before 16328 and 11037a after 16328. This will ensure that #11037-16 findings are properly captured by unit tests and eventually fixed. Expect for 30+ tests.
#18 Updated by Artur Școlnic 19 days ago
Unit tests for #11037 — r16327 vs r16328¶
32 ABLUnit tests added under tests/persistence/fast_find_cache/. Both #11037-16 findings reproduce, and both are fixed by r16328.
| OpenEdge 11.6 | 11037a r16327 | 11037a r16328 | |
|---|---|---|---|
TestStaleNodeRegistration (7) |
7/7 | 0/7 — NullPointerException | 7/7 |
TestTempTableScopeClose (7) |
7/7 | 1/7 — ConcurrentModificationException | 7/7 |
TestReverseLookupInvalidation (6) |
6/6 | 6/6 | 6/6 |
TestNoRecordInvalidation (5) |
5/5 | 4/5 (collateral NPE) | 5/5 |
TestSurroundingsCacheInvalidation (7) |
7/7 | 6/7 (collateral NPE) | 7/7 |
| Total | 32/32 | 17/32 | 32/32 |
Between the two runs only the two files r16328 touches were swapped to their r16327 content; everything else is identical (ant deploy.prepare, jar-only refresh).
Finding 1 — NullPointerException on a fast-find cache hit¶
Four statements are enough: cache a result, invalidate the table with any CREATE, re-run the query, then run it once more.
@Test.
method public void TestThirdFindAfterCreateReturnsRecord():
find item where item.itemNum = 100 no-lock.
Assert:Equals("alpha", item.itemName).
do transaction:
create item.
assign
item.itemNum = 101
item.itemName = "spacer"
item.price = 1
item.weight = 1.
end.
// re-registers the result; the stale node used to make this a no-op
find item where item.itemNum = 100 no-lock.
Assert:Equals("alpha", item.itemName).
// the cache hit that used to dereference the never-set LRU entry
find item where item.itemNum = 100 no-lock.
Assert:Equals("alpha", item.itemName).
Assert:Equals(decimal(10), item.price).
end method.
CREATE invalidates every index of the table, which clears the L3 map but leaves the reverse-lookup node behind. The second FIND re-registers, finds a stale node under an equal
key and skips the body, so cacheEntry stays null. The third FIND hits the cache and dereferences it:
java.lang.NullPointerException: Cannot read field "previous" because "removed" is null
at com.goldencode.cache.LRUCache.entryRemoved(LRUCache.java:262)
at com.goldencode.cache.LRUCache.entryAccessed(LRUCache.java:241)
at com.goldencode.cache.ExpiryCache.touch(ExpiryCache.java:364)
at com.goldencode.p2j.persist.FastFindCache$ReverseLookup.touch(FastFindCache.java:1184)
at com.goldencode.p2j.persist.FastFindCache.getImpl(FastFindCache.java:646)
at com.goldencode.p2j.persist.FastFindCache.get(FastFindCache.java:357)
at com.goldencode.p2j.persist.RandomAccessQuery.execute(RandomAccessQuery.java:4565)
at com.goldencode.p2j.persist.RandomAccessQuery.unique(RandomAccessQuery.java:3018)
at com.goldencode.p2j.persist.FindQuery.unique(FindQuery.java:1225)
at com.goldencode.testcases.tests.persistence.fast_find_cache.TestStaleNodeRegistration
.lambda$testThirdFindAfterCreateReturnsRecord$13(TestStaleNodeRegistration.java:162)
DELETE reaches the same defect identically — see TestThirdFindAfterDeleteReturnsRecord.
Finding 2 — ConcurrentModificationException on temp-table scope close¶
A procedure-scoped temp-table, two cached FINDs, then return:
block-level on error undo, throw.
define output parameter foundCount as integer no-undo.
define temp-table ttCache no-undo
field k as integer
field v as character
field w as decimal
index pk is unique primary k.
create ttCache. assign ttCache.k = 1 ttCache.v = "row1" ttCache.w = 1.
create ttCache. assign ttCache.k = 2 ttCache.v = "row2" ttCache.w = 2.
find ttCache where ttCache.k = 1 no-lock no-error.
if available ttCache then foundCount = foundCount + 1.
find ttCache where ttCache.k = 2 no-lock no-error.
if available ttCache then foundCount = foundCount + 1.
Invoked as run … tt_scope_two_cached_finds.p (output found). — the failure occurs on return, when the multiplex scope closes:
Caused by: java.util.ConcurrentModificationException
at java.base/java.util.HashMap$HashIterator.nextNode(HashMap.java:1597)
at java.base/java.util.HashMap$ValueIterator.next(HashMap.java:1625)
at com.goldencode.p2j.persist.FastFindCache$ReverseLookup.invalidateL3Cache(FastFindCache.java:1200)
at com.goldencode.p2j.persist.FastFindCache.lambda$invalidate$1(FastFindCache.java:492)
at java.base/java.util.LinkedHashMap.forEach(LinkedHashMap.java:721)
at com.goldencode.p2j.persist.FastFindCache.invalidate(FastFindCache.java:491)
at com.goldencode.p2j.persist.TemporaryBuffer.doCloseMultiplexScope(TemporaryBuffer.java:8108)
at com.goldencode.p2j.persist.TemporaryBuffer.closeMultiplexScope(TemporaryBuffer.java:7240)
at com.goldencode.p2j.persist.TemporaryBuffer$Multiplexer.finished(TemporaryBuffer.java:9336)
at com.goldencode.p2j.util.ProcedureManager$WorkArea.scopeFinished(ProcedureManager.java:5519)
at com.goldencode.p2j.util.TransactionManager.popScope(TransactionManager.java:4858)
at com.goldencode.p2j.util.BlockManager.externalProcedure(BlockManager.java:700)
at com.goldencode.testcases.tests.persistence.fast_find_cache.support
.TtScopeTwoCachedFinds.execute(TtScopeTwoCachedFinds.java:44)
The one test that passes at r16327 is TestScopeCloseWithOneCachedFind, which deliberately caches a single result. A single-entry map never asks the iterator for a second element,
so the walk cannot trip. That boundary case pins the failure to the map-mutation mechanism rather than to scope close in general.
Scope of the two regressions¶
Both regressions are branch-only. At r16324 — this branch's last merge from trunk — the machinery they break does not exist yet:
cacheEntry/setNode/getCacheEntry— 0 occurrences (the pointer whose nullness causes the NPE)invalidateL3Cache— 0 occurrences (the method that mutates the map it is iterating)
r16326 introduced the pointer, r16327 introduced invalidateL3Cache, and r16328 fixes both. No delivered build is affected, so r16328 is a pre-merge regression stop rather than a
field fix.
The field-affecting defect is the original one, fixed by r16325. At r16324 ReverseLookup.Value.invalidate() still walks the list as for (node = head; node != null; node =
node.next) while calling node.remove(), which nulls next — so eviction stops after the first node and a record with two or more cached queries keeps serving stale data.
Verification against OpenEdge¶
All 32 tests also pass on real OpenEdge 11.6 (ABLUnit via PCT against tstcasesdb), which confirms the 4GL is valid and the assertions encode correct 4GL semantics rather than
FWD-specific behaviour. Both reproducers are ordinary code: look-up / insert / look-up, and a procedure-scoped temp-table going out of scope.
Will continue with customer projects testing.
#19 Updated by Greg Shah 19 days ago
Nice! Please document these in Record Caching Tests.
#20 Updated by Artur Școlnic 16 days ago
Large gui app unit tests, etf housing tests and multi tenant app testing passed.
#21 Updated by Artur Școlnic 15 days ago
I am planning to run chui regression tests, if they are ok, can we merge?
#22 Updated by Alexandru Lungu 15 days ago
Artur Școlnic wrote:
I am planning to run chui regression tests, if they are ok, can we merge?
Yes, please.
#23 Updated by Artur Școlnic 14 days ago
Chui passed.
#24 Updated by Alexandru Lungu 14 days ago
- Status changed from Internal Test to Merge Pending
Please merge 11037a to trunk now.
#25 Updated by Artur Școlnic 14 days ago
- Status changed from Merge Pending to Test
11037a was merged to trunk/16711.