[IGNITE-5793] Cache with constant time TTL for entries and enabled persistence hangs for a long time when TTL expirations start

• Type: Bug
• Status: Resolved
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 2.0
• Fix Version/s: 2.3
• Component/s: cache
• Assignee: Alexey Goncharuk
• Reporter: Ivan Rakov
• Created: 20/Jul/17 14:10
• Updated: 28/Aug/17 16:39
• Resolved: 31/Jul/17 07:38

Description

Right after expiration time, all threads from sys-stripe pool are busy with removing expired entries, example stacktrace:

Thread [name="sys-stripe-3-#35%database.IgniteDbSnapshotWithEvictionsSelfTest1%", id=60, state=RUNNABLE, blockCnt=0, waitCnt=101794]
        at o.a.i.i.binary.BinaryObjectImpl.typeId(BinaryObjectImpl.java:278)
        at o.a.i.i.processors.cache.binary.CacheObjectBinaryProcessorImpl.typeId(CacheObjectBinaryProcessorImpl.java:672)
        at o.a.i.i.processors.query.GridQueryProcessor.typeByValue(GridQueryProcessor.java:1688)
        at o.a.i.i.processors.query.GridQueryProcessor.remove(GridQueryProcessor.java:2177)
        at o.a.i.i.processors.cache.query.GridCacheQueryManager.remove(GridCacheQueryManager.java:451)
        at o.a.i.i.processors.cache.IgniteCacheOffheapManagerImpl$CacheDataStoreImpl.finishRemove(IgniteCacheOffheapManagerImpl.java:1456)
        at o.a.i.i.processors.cache.IgniteCacheOffheapManagerImpl$CacheDataStoreImpl.remove(IgniteCacheOffheapManagerImpl.java:1419)
        at o.a.i.i.processors.cache.persistence.GridCacheOffheapManager$GridCacheDataStore.remove(GridCacheOffheapManager.java:1241)
        at o.a.i.i.processors.cache.IgniteCacheOffheapManagerImpl.remove(IgniteCacheOffheapManagerImpl.java:383)
        at o.a.i.i.processors.cache.GridCacheMapEntry.removeValue(GridCacheMapEntry.java:3221)
        at o.a.i.i.processors.cache.GridCacheMapEntry.onExpired(GridCacheMapEntry.java:3028)
        at o.a.i.i.processors.cache.GridCacheMapEntry.onTtlExpired(GridCacheMapEntry.java:2961)
        at o.a.i.i.processors.cache.GridCacheTtlManager$1.applyx(GridCacheTtlManager.java:61)
        at o.a.i.i.processors.cache.GridCacheTtlManager$1.applyx(GridCacheTtlManager.java:52)
        at o.a.i.i.util.lang.IgniteInClosure2X.apply(IgniteInClosure2X.java:38)
        at o.a.i.i.processors.cache.IgniteCacheOffheapManagerImpl.expire(IgniteCacheOffheapManagerImpl.java:1007)
        at o.a.i.i.processors.cache.GridCacheTtlManager.expire(GridCacheTtlManager.java:198)
        at o.a.i.i.processors.cache.GridCacheTtlManager.expire(GridCacheTtlManager.java:160)
        at o.a.i.i.processors.cache.GridCacheUtils.unwindEvicts(GridCacheUtils.java:854)
        at o.a.i.i.processors.cache.GridCacheIoManager.processMessage(GridCacheIoManager.java:1073)
        at o.a.i.i.processors.cache.GridCacheIoManager.onMessage0(GridCacheIoManager.java:561)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:378)
        at o.a.i.i.processors.cache.GridCacheIoManager.handleMessage(GridCacheIoManager.java:304)
        at o.a.i.i.processors.cache.GridCacheIoManager.access$100(GridCacheIoManager.java:99)
        at o.a.i.i.processors.cache.GridCacheIoManager$1.onMessage(GridCacheIoManager.java:293)
        at o.a.i.i.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1556)
        at o.a.i.i.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1184)
        at o.a.i.i.managers.communication.GridIoManager.access$4200(GridIoManager.java:126)
        at o.a.i.i.managers.communication.GridIoManager$9.run(GridIoManager.java:1097)
        at o.a.i.i.util.StripedExecutor$Stripe.run(StripedExecutor.java:483)
        at java.lang.Thread.run(Thread.java:745)

Patch with reproducer test and expire metrics attached. Put/Get/Expire metrics when expirations start looks like that:

[17:21:26,908][INFO ][db-checkpoint-thread-#62%database.TtlHangReproducerTest1%][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=9e564ba2-8c41-4cf9-bfa8-75e3d50c00dc, startPtr=FileWALPointer [idx=64, fileOffset=45383475, len=4459, forceFlush=true], checkpointLockWait=0ms, checkpointLockHoldTime=16ms, pages=259801, reason='timeout']
@@@ putsPerSec=5459  getsPerSec=3063 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=16846, pageReplaceRate=0.0, physicalMemoryPages=515034}
@@@ putsPerSec=15575  getsPerSec=5075 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=37868, pageReplaceRate=0.0, physicalMemoryPages=519291}
@@@ putsPerSec=19560  getsPerSec=9210 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=45664, pageReplaceRate=0.0, physicalMemoryPages=521435}
@@@ putsPerSec=24262  getsPerSec=12399 expiresPerSec=64 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=53016, pageReplaceRate=0.0, physicalMemoryPages=523663}
@@@ putsPerSec=25674  getsPerSec=12183 expiresPerSec=2962 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=63874, pageReplaceRate=0.0, physicalMemoryPages=525286}
@@@ putsPerSec=19178  getsPerSec=9408 expiresPerSec=7772 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=73770, pageReplaceRate=0.0, physicalMemoryPages=525803}
@@@ putsPerSec=19178  getsPerSec=7150 expiresPerSec=13738 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=80253, pageReplaceRate=0.0, physicalMemoryPages=525805}
@@@ putsPerSec=10848  getsPerSec=2903 expiresPerSec=22654 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=89288, pageReplaceRate=0.0, physicalMemoryPages=525807}
@@@ putsPerSec=14449  getsPerSec=255 expiresPerSec=33413 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=101825, pageReplaceRate=0.0, physicalMemoryPages=525837}
@@@ putsPerSec=3958  getsPerSec=92 expiresPerSec=41021 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=113817, pageReplaceRate=0.0, physicalMemoryPages=525868}
@@@ putsPerSec=3958  getsPerSec=92 expiresPerSec=43919 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=122591, pageReplaceRate=0.0, physicalMemoryPages=525932}
@@@ putsPerSec=3601  getsPerSec=92 expiresPerSec=49443 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=136329, pageReplaceRate=0.0, physicalMemoryPages=525932}
@@@ putsPerSec=0  getsPerSec=85 expiresPerSec=53362 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=150831, pageReplaceRate=0.0, physicalMemoryPages=525938}
@@@ putsPerSec=0  getsPerSec=8 expiresPerSec=59473 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=171073, pageReplaceRate=0.0, physicalMemoryPages=525941}
@@@ putsPerSec=0  getsPerSec=1 expiresPerSec=58999 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=182364, pageReplaceRate=0.0, physicalMemoryPages=525944}
@@@ putsPerSec=0  getsPerSec=1 expiresPerSec=67785 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=195052, pageReplaceRate=0.0, physicalMemoryPages=525945}
@@@ putsPerSec=0  getsPerSec=2 expiresPerSec=72120 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=209057, pageReplaceRate=0.0, physicalMemoryPages=525945}
@@@ putsPerSec=0  getsPerSec=1 expiresPerSec=72176 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=219386, pageReplaceRate=0.0, physicalMemoryPages=525947}
@@@ putsPerSec=0  getsPerSec=2 expiresPerSec=71341 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=233395, pageReplaceRate=0.0, physicalMemoryPages=525949}
@@@ putsPerSec=0  getsPerSec=2 expiresPerSec=77004 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=247592, pageReplaceRate=0.0, physicalMemoryPages=525949}
@@@ putsPerSec=0  getsPerSec=1 expiresPerSec=69599 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=248350, pageReplaceRate=0.0, physicalMemoryPages=525949}
@@@ putsPerSec=0  getsPerSec=1 expiresPerSec=66669 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=254189, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=58550 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259141, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=42356 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259141, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=26547 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259141, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=18241 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259141, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259141, pageReplaceRate=0.0, physicalMemoryPages=525950}
[17:21:54,587][INFO ][db-checkpoint-thread-#63%database.TtlHangReproducerTest0%][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=4efda3bc-6041-49b9-bdf6-073d9d181550, pages=199312, markPos=FileWALPointer [idx=49, fileOffset=37208218, len=3847, forceFlush=true], walSegmentsCleared=10, markDuration=20ms, pagesWrite=30576ms, fsync=1008ms, total=31604ms]
[17:21:54,607][INFO ][db-checkpoint-thread-#63%database.TtlHangReproducerTest0%][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=1295c157-b086-4dad-9b72-0ab7658b1f97, startPtr=FileWALPointer [idx=60, fileOffset=62012992, len=3847, forceFlush=true], checkpointLockWait=0ms, checkpointLockHoldTime=16ms, pages=259364, reason='timeout']
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=1853 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=14497, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=6554 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=33138, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=10293 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=43258, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=16456 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=58137, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=22189 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=71228, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=29674 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=92946, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=36096 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=116665, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=42013 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=136855, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=44661 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=154219, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=43233 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=163588, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=40477 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=177747, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=34889 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=187927, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=34826 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=204958, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=34378 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=219286, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=38136 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=233723, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=38591 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=247524, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=40392 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=31211 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=23150 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=14941 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=0 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
[17:22:21,443][INFO ][db-checkpoint-thread-#62%database.TtlHangReproducerTest1%][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=9e564ba2-8c41-4cf9-bfa8-75e3d50c00dc, pages=259801, markPos=FileWALPointer [idx=64, fileOffset=45383475, len=4459, forceFlush=true], walSegmentsCleared=17, markDuration=37ms, pagesWrite=50846ms, fsync=3689ms, total=54573ms]
[17:22:21,462][INFO ][db-checkpoint-thread-#62%database.TtlHangReproducerTest1%][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=e60ba84b-a022-45b3-a94b-ffa0d715e054, startPtr=FileWALPointer [idx=78, fileOffset=1627544, len=4459, forceFlush=true], checkpointLockWait=0ms, checkpointLockHoldTime=15ms, pages=305727, reason='timeout']
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=4574 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=13605 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=18070 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=27029 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=37173 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=259221, pageReplaceRate=0.0, physicalMemoryPages=525950}
[17:22:25,987][INFO ][db-checkpoint-thread-#63%database.TtlHangReproducerTest0%][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=1295c157-b086-4dad-9b72-0ab7658b1f97, pages=259364, markPos=FileWALPointer [idx=60, fileOffset=62012992, len=3847, forceFlush=true], walSegmentsCleared=15, markDuration=20ms, pagesWrite=28284ms, fsync=3095ms, total=31399ms]
[17:22:26,029][INFO ][db-checkpoint-thread-#63%database.TtlHangReproducerTest0%][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=f5a2ead4-5516-4a94-a3f9-a680eefd2fa7, startPtr=FileWALPointer [idx=71, fileOffset=21152698, len=3847, forceFlush=true], checkpointLockWait=0ms, checkpointLockHoldTime=10ms, pages=259444, reason='timeout']
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=44164 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=42412, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=53544 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=54630, pageReplaceRate=0.0, physicalMemoryPages=525950}
@@@ putsPerSec=0  getsPerSec=0 expiresPerSec=57466 MemoryMetricsSnapshot{name='dfltMemPlc', totalAllocatedPages=0, allocationRate=0.0, evictionRate=0.0, largeEntriesPagesPercentage=0.0, pagesFillFactor=0.0, dirtyPages=65838, pageReplaceRate=0.0, physicalMemoryPages=525950}

Right after "expiresPerSec" becomes non-zero, "putsPerSec" and "getsPerSec" falls to zero level. System totally stops responding to user get/put/etc operations. The freeze can last for several checkpoints. Most likely, system fills cache with new entries faster than expiring old. As a result, old entries pile up.