Project

General

Profile

Bug #11037

Record not being evicted from FFCache

Added by Andrei Plugaru 9 months ago. Updated 14 days ago.

Status:
Test
Priority:
Normal
Target version:
-
Start date:
Due date:
% Done:

100%

billable:
No
vendor_id:
GCD
case_num:
version_reported:
version_resolved:
production:
No
env_name:
topics:

Related issues

Related to Database - Bug #10776: FFC.touch standing out in profiling Pending
Related to Database - Feature #11638: Reduce FastFindCache invalidation thrashing Internal Test

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

While testing the above solution on the unit tests from the large customer application, I found another case when the wrong record is returned because of the FF cache. The root cause seems to be that the reverse lookup and the main cache get out of sync when we remove all the records for a table from FFCache.cache, like how it happens in FFCache.invalidate(int dmoUid, Integer multiplex, boolean remove).
I mainly discovered 2 issues:
  1. Even though the entries from ReverseLookup.reverseCache will typically be removed when the Rec ids will not be hard referenced anywhere else, there is a problem for NO_RECORD. This is a class static filed, so it is always referenced, so the associated entries from ReverseLookup.reverseCache will never be deleted.
  2. There is at least one execution path when records from ReverseLookup.lruCache are 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 from FFCache.invalidate(int dmoUid, Integer multiplex, boolean remove)), they are not removed. This causes a real functional problem as in ReverseLookup.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 in ReverseLookup.put to 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 calling get was slow on the map from ReverseLookup.

#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).

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.

#5 Updated by Andrei Plugaru 9 months ago

  • Status changed from WIP to Review
  • reviewer Alexandru Lungu added

I have created 11037a and committed 11037a/16325 with the invalidation changes from #11037-1 and the ones from #11037-4 to check and remove the stale data before inserting in reverse lookup.
Alex, please review!

#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 nodeToRemove is inside the list? Can't you run nodeToRemove.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 contain Key with actual arguments, FQL, etc.
    • If the node is not in the value, then the remove() is no-op, removal from lruCache is done reasonably and setting of head won't be possible.
  • 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.

#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 nodeToRemove is inside the list? Can't you run nodeToRemove.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 contain Key with actual arguments, FQL, etc.
    • If the node is not in the value, then the remove() is no-op, removal from lruCache is done reasonably and setting of head won'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.

#11 Updated by Andrei Plugaru 7 months ago

I have ported the changes from 10776a into 11037a/rev. 16326.

#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.

Also available in: Atom PDF