[ https://issues.apache.org/jira/browse/IGNITE-5793?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Ivan Rakov updated IGNITE-5793: ------------------------------- Description: Right after expiration time, all threads from sys-stripe pool are busy with removing expired entries, example stacktrace: {noformat} 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) {noformat} Patch with reproducer test and expire metrics attached. Put/Get/Expire metrics when expirations start looks like that: {noformat} [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} {noformat} 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. Right after "expiresPerSec" becomes non-zero, "putsPerSec" and "getsPerSec" falls to zero level. They are still zero after one full checkpoint on both nodes. was: Right after expiration time, all threads from sys-stripe pool are busy with removing expired entries, example stacktrace: {noformat} 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) {noformat} 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. Patch with reproducer test and expire metrics attached. Put/Get/Expire metrics when expirations start looks like that: {noformat} [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} {noformat} Right after "expiresPerSec" becomes non-zero, "putsPerSec" and "getsPerSec" falls to zero level. They are still zero after one full checkpoint on both nodes. > Cache with constant time TTL for entries and enabled persistence hangs for a > long time when TTL expirations start > ----------------------------------------------------------------------------------------------------------------- > > Key: IGNITE-5793 > URL: https://issues.apache.org/jira/browse/IGNITE-5793 > Project: Ignite > Issue Type: Bug > Components: cache > Affects Versions: 2.0 > Reporter: Ivan Rakov > Fix For: 2.2 > > > Right after expiration time, all threads from sys-stripe pool are busy with > removing expired entries, example stacktrace: > {noformat} > 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) > {noformat} > Patch with reproducer test and expire metrics attached. Put/Get/Expire > metrics when expirations start looks like that: > {noformat} > [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} > {noformat} > 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. > Right after "expiresPerSec" becomes non-zero, "putsPerSec" and "getsPerSec" > falls to zero level. They are still zero after one full checkpoint on both > nodes. -- This message was sent by Atlassian JIRA (v6.4.14#64029)