[
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)
