Project

General

Profile

Bug #10776

FFC.touch standing out in profiling

Added by Alexandru Lungu 9 months ago. Updated 4 months ago.

Status:
Pending
Priority:
High
Target version:
-
Start date:
Due date:
% Done:

100%

billable:
No
vendor_id:
GCD
case_num:
version_reported:
version_resolved:
reviewer:
Andrei Plugaru, Artur Școlnic
production:
No
env_name:
topics:

Related issues

Related to Database - Bug #11037: Record not being evicted from FFCache Review

History

#1 Updated by Alexandru Lungu 9 months ago

In a test for #10737, I am running 4 concurrent REST calls 100.000 times. Nearly 20% of the time across all sessions is spent in FFC.getImpl delegating most of the time to touch. Going deeper, most of the time seems to be spent in HashMap.get of the ReverseLookup cache.

The reverse look-up cache is quite big (initially sized to 100_000 elements). Looking up for a node in there can be indeed slow. I can't tell how this can be improved ... it is just strange that a REST API call happens to wait 20% just to update the "recently-used" policy of this cache. Removing it might be worse as it will evict precious entries.

The only feedback I have on this is that sometimes the HashMap look-up uses TreeNode to binary find the hash bucket, and maybe some of that is slow. I saw that HashMap has initial capacity and load factor. Maybe we should fine tune these for the ReverseLookup cache to better reflect the fact that the cache will usually be full :)

#3 Updated by Alexandru Lungu 7 months ago

  • Priority changed from Normal to High

I started profiling another application (#10981). There is a consistent performance downgrade comparing trunk with 7156e. Doing a simple sampling, I spot FFC.touch as 3.4s while running 8 times (so 0.42s per run) a scenario (15 * 8 = 120s roughly). The performance difference between 7156e and trunk is ~2s per run and if we relate 0.42s to that 2s gap, than it is about 20% of the performance downgrade.

I am bumping the priority of this.

PS: most of the time of FFC.touch is spent in ExpiryCache.get()

#4 Updated by Alexandru Lungu 7 months ago

  • % Done changed from 0 to 100
  • Assignee set to Alexandru Lungu
  • Status changed from New to Review
  • reviewer Andrei Plugaru, Artur Școlnic added

I prototyped a fix for this: cache the actual Cache.Entry in the FFC so that touch will be able to bypass the map look-up and simply call entryAccessed straight-away. This takes away some safety as the Cache.Entry should always be part of the cache, otherwise it might get corrupt. The safe-check will eventually nullify this performance improvement.

Committed 10776a/rev. 16325.

#5 Updated by Andrei Plugaru 7 months ago

Alex, I feel like there could be a issue regarding the single FastFindCacheEntry instance for the negative results(FastFindCache.NO_ENTRY). Having this single instance creates a one-to-one relation between the RecordIdentifier<String> - NO_RECORD and the Cache.Entry<ReverseLookup.Node, ReverseLookup.Value>. FastFindCache.NO_ENTRY will always hold only the last inserted Cache.Entry.

Consider this test case:

def temp-table tt_table3 field f1 as int field f2 as logical index idx_1 is primary unique f1.

find first tt_table3 where tt_table3.f1 = 1 no-error.
find first tt_table3 where tt_table3.f1 = 2 no-error.
find first tt_table3 where tt_table3.f1 = 1 no-error.

The problem is the last find will touch the Cache.Entry associated with tt_table3.f1 = 2.

On another note, also this code from FastFindCache.getImpl needs a null check:

       // Touch the corresponding entry from lruCache,
       // this puts it in from of the cache and postpones invalidation.
       FastFindCacheEntry entry = l3Cache.get(k.k2);
-      reverseLookup.touch(entry);
-      return entry.getRecordIdentifier();
+      if (entry != null)
+      {
+         reverseLookup.touch(entry);
+         return entry.getRecordIdentifier();
+      }
+      return null;
    }

#6 Updated by Alexandru Lungu 7 months ago

Alex, I feel like there could be a issue regarding the single FastFindCacheEntry instance for the negative results(FastFindCache.NO_ENTRY). Having this single instance creates a one-to-one relation between the RecordIdentifier<String> - NO_RECORD and the Cache.Entry<ReverseLookup.Node, ReverseLookup.Value>. FastFindCache.NO_ENTRY will always hold only the last inserted Cache.Entry.

You are right, this is a problem indeed! The node stored by FastFindCacheEntry will be replaced on each put. The reverseLookup.put should always receive a cacheVal with null node. Fixed it!

On another note, also this code from FastFindCache.getImpl needs a null check:

Got it!

The concerns are now fixed in 10776a/16326. Please do a final review.

PS: I am a bit worried that these changes in 10776a are dependent upon the (very) well-functioning of FFCache that was also explored in #11037. In other words, I would prefer to merge 10776a (if review is OK) into 11037a are test them together very thoroughly (performance, functionality). The leak detected in #11037 may spoil the low-level interaction with the cache and cause havoc.

#7 Updated by Alexandru Lungu 7 months ago

  • Related to Bug #11037: Record not being evicted from FFCache added

#8 Updated by Andrei Plugaru 6 months ago

I checked 10776a branch again and, indeed, my original concerns are solved!
There is a small syntax error at the end of this line:

-   public static final FastFindCacheEntry NO_ENTRY = new FastFindCacheEntry(NO_RECORD, null);
+   public static final RecordIdentifier<String> NO_RECORD = new RecordIdentifier<>("", -1L);`

Apart from this, I don't see any other issue.

I would prefer to merge 10776a (if review is OK) into 11037a are test them together very thoroughly (performance, functionality). The leak detected in #11037 may spoil the low-level interaction with the cache and cause havoc.

I agree on that, I think the changes on this task can help me get to a more performant solution in #11037.

#9 Updated by Alexandru Lungu 6 months ago

Andrei, please merge 10776a in #11037 and lets test them together. I will look into #11037 for review once ready.

#10 Updated by Andrei Plugaru 5 months ago

Alex, while working on finishing #11037, I discovered a problem in the solution from #10776 for this testcase:

def temp-table tt_table3 field f1 as int field f2 as logical index idx_1 is primary unique f1.

procedure p1:
    def buffer b_table3 for tt_table3.
    def input parameter should_create as logical.
    if should_create then do:
        create b_table3.
        b_table3.f1 = 1.
        b_table3.f2 = false.
    end.
    find first b_table3 where b_table3.f1 = 1 and not  b_table3.f2 no-error.
    if available(b_table3) then do:
        assign
        b_table3.f2 = true
        .
        find first b_table3 where b_table3.f1 = 1 and not  b_table3.f2 no-error.
        message available(b_table3).    
    end.
end.

run p1(false).
run p1(true).

Caused by: 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:1166)
        at com.goldencode.p2j.persist.FastFindCache.getImpl(FastFindCache.java:625)
        at com.goldencode.p2j.persist.FastFindCache.get(FastFindCache.java:350)
        at com.goldencode.p2j.persist.RandomAccessQuery.execute(RandomAccessQuery.java:4565)
        at com.goldencode.p2j.persist.RandomAccessQuery.first(RandomAccessQuery.java:1682)
        at com.goldencode.p2j.persist.FindQuery.first(FindQuery.java:746)
        at com.goldencode.p2j.persist.RandomAccessQuery.first(RandomAccessQuery.java:1545)
        at com.goldencode.p2j.persist.FindQuery.first(FindQuery.java:666)
        at com.goldencode.p2j.persist.AbstractQuery.silentFirst(AbstractQuery.java:3560)
        at com.goldencode.dataset.InfLoop2.lambda$p1$1(InfLoop2.java:65)
        at com.goldencode.p2j.util.Block.body(Block.java:636)
        at com.goldencode.p2j.util.BlockManager.processBody(BlockManager.java:9703)
        at com.goldencode.p2j.util.BlockManager.topLevelBlock(BlockManager.java:9311)
        at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:860)
        at com.goldencode.p2j.util.BlockManager.internalProcedure(BlockManager.java:837)
        at com.goldencode.dataset.InfLoop2.p1(InfLoop2.java:49)

#11 Updated by Andrei Plugaru 5 months ago

Actually, the root cause for the problem exposed in #10776-10 is not because of the changes per-se on this branch. It is just activated with these changes. The root cause is still the desynchronization between the main cache in FFCache and the reverse lookup. I think I have a fix for this. I will post it on #11037.

#12 Updated by Alexandru Lungu 4 months ago

  • Status changed from Review to Pending

This effort was integrated in #11037

Also available in: Atom PDF