You are viewing a plain text version of this content. The canonical link for it is here.
Posted to issues@ignite.apache.org by "Alexey Goncharuk (JIRA)" <ji...@apache.org> on 2017/07/31 07:38:00 UTC
[jira] [Assigned] (IGNITE-5793) Cache with constant time TTL for
entries and enabled persistence hangs for a long time when TTL expirations
start
[ https://issues.apache.org/jira/browse/IGNITE-5793?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexey Goncharuk reassigned IGNITE-5793:
----------------------------------------
Assignee: Alexey Goncharuk
> 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
> Assignee: Alexey Goncharuk
> Fix For: 2.2
>
> Attachments: ttl_hang.patch
>
>
> 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}
> 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.
--
This message was sent by Atlassian JIRA
(v6.4.14#64029)