looks like we deactivate pageMem concurrently with cp pageWrite, plz someone fill the ticket with appropriate logs.
>Среда, 9 декабря 2020, 4:52 +03:00 от 38797715 <38797...@qq.com>: > >Hi Ilya, >This issue is not easy to reproduce. >However, judging from the exception stack, the issue may be related to the >checkpoint process during the destruction of the cache. >在 2020/12/9 上午9:33, Ilya Kazakov 写道: >>Hello! Can you provide some details, or show some short reproducer? >> >>----------------- >>Ilya Kazakov >>пн, 7 дек. 2020 г. в 21:31, 38797715 < 38797...@qq.com >: >>>Hi community, >>>Call IgniteCache.destroy Method, NPE appears,logs are as follows: >>>2020-12-07 17:32:18.870 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.e.time - Started exchange init [topVer=AffinityTopologyVersion >>>[topVer= 1 , minorTopVer= 279 ], crd= true , evt=DISCOVERY_CUSTOM_EVT, >>>evtNode= 320935f6-3516-4b0b-9e5f-e80768696522 , >>>customEvt=DynamicCacheChangeBatch [id= >>>1f2a90e2671-562b8f51-fa6a-4094-928c-6976ce87614a , reqs=ArrayList >>>[DynamicCacheChangeRequest [cacheName=PksQuota, hasCfg= false , nodeId= >>>320935f6-3516-4b0b-9e5f-e80768696522 , clientStartOnly= false , stop= true , >>>destroy= false , disabledAfterStartfalse]], exchangeActions=ExchangeActions >>>[startCaches= null , stopCaches=[PksQuota], startGrps=[], >>>stopGrps=[PksQuota, destroy= true ], resetParts= null , stateChangeRequest= >>>null ], startCaches= false ], allowMerge= false , exchangeFreeSwitch= false ] >>>2020-12-07 17:32:18.873 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture - Finished waiting for >>>partition release future [topVer=AffinityTopologyVersion [topVer= 1 , >>>minorTopVer= 279 ], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED] >>>2020-12-07 17:32:18.873 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture - Finished waiting for >>>partitions release latch: ServerLatch [permits= 0 , pendingAcks=HashSet [], >>>super=CompletableLatch [id=CompletableLatchUid [id=exchange, >>>topVer=AffinityTopologyVersion [topVer= 1 , minorTopVer= 279 ]]]] >>>2020-12-07 17:32:18.873 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture - Finished waiting for >>>partition release future [topVer=AffinityTopologyVersion [topVer= 1 , >>>minorTopVer= 279 ], waitTime=0ms, futInfo=NA, mode=LOCAL] >>>2020-12-07 17:32:19.037 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture - >>>finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer= 1 , >>>minorTopVer= 279 ], resVer=AffinityTopologyVersion [topVer= 1 , minorTopVer= >>>279 ]] >>>2020-12-07 17:32:19.438 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture - Finish exchange future >>>[startVer=AffinityTopologyVersion [topVer= 1 , minorTopVer= 279 ], >>>resVer=AffinityTopologyVersion [topVer= 1 , minorTopVer= 279 ], err= null , >>>rebalanced= true , wasRebalanced= true ] >>>2020-12-07 17:32:20.870 [] [ db-c heckpoint-thread-# 75 %tradecore%] INFO >>>o.a.i.i.p.c.p.GridCacheDatabaseSharedManager - Checkpoint started >>>[checkpointId= f001018a-100e-4154-98c9-547dabf5015f , >>>startPtr=FileWALPointer [idx= 16 , fileOff= 1059360696 , len= 4770137 ], >>>checkpointBeforeLockTime=549ms, checkpointLockWait=0ms, >>>checkpointListenersExecuteTime=529ms, checkpointLockHoldTime=853ms, >>>walCpRecordFsyncDuration=17ms, writeCheckpointEntryDuration=7ms, >>>splitAndSortCpPagesDuration=4ms, pages= 10775 , reason= 'caches stop' ] >>>2020-12-07 17:32:21.255 [] [checkpoint-runner-# 79 %tradecore%] WARN >>>o.a.i.i.p.c.p.GridCacheDatabaseSharedManager - 1 checkpoint pages were not >>>written yet due to unsuccessful page write lock acquisition and will be >>>retried >>>2020-12-07 17:32:21.261 [] [exchange-worker-# 54 %tradecore%] ERROR >>>o.a.i.i.p.c.GridCacheProcessor - Failed to wait for checkpoint finish during >>>cache stop. >>>org.apache.ignite.IgniteCheckedException : Compound exception for >>>CountDownFuture. >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.addError(CountDownFuture.java:72) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.onDone(CountDownFuture.java:46) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.onDone(CountDownFuture.java:28) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:478) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.run(GridCacheDatabaseSharedManager.java:4546) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>> ~[?:1.8.0_272] >>>at >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>> ~[?:1.8.0_272] >>>at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272] >>>Suppressed: java.lang.NullPointerException >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.writePages(GridCacheDatabaseSharedManager.java:4584) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.run(GridCacheDatabaseSharedManager.java:4540) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>> ~[?:1.8.0_272] >>>at >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>> ~[?:1.8.0_272] >>>at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272] >>>2020-12-07 17:32:21.265 [] [exchange-worker-# 54 %tradecore%] INFO >>>o.a.i.i.p.c.GridCacheProcessor - Stopped cache [cacheName=PksQuota] >>>2020-12-07 17:32:21.268 [] [ db-c heckpoint-thread-# 75 %tradecore%] ERROR >>>c.j.i.i.c.IgniteConfig - Critical system error detected. Will be handled >>>accordingly to configured handler [hnd=StopNodeOrHaltFailureHandler >>>[tryStop= false , timeout= 0 , super=AbstractFailureHandler >>>[ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED, >>>SYSTEM_CRITICAL_OPERATION_TIMEOUT]]], failureCtx=FailureContext >>>[type=CRITICAL_ERROR, err=class o.a.i.IgniteCheckedException : Compound >>>exception for CountDownFuture.]] >>>org.apache.ignite.IgniteCheckedException : Compound exception for >>>CountDownFuture. >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.addError(CountDownFuture.java:72) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.onDone(CountDownFuture.java:46) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.CountDownFuture.onDone(CountDownFuture.java:28) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.util.future.GridFutureAdapter.onDone(GridFutureAdapter.java:478) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.run(GridCacheDatabaseSharedManager.java:4546) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>> ~[?:1.8.0_272] >>>at >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>> ~[?:1.8.0_272] >>>at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272] >>>Suppressed: java.lang.NullPointerException >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.writePages(GridCacheDatabaseSharedManager.java:4584) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$WriteCheckpointPages.run(GridCacheDatabaseSharedManager.java:4540) >>> ~[ignite-core-2.9.0.jar!/:2.9.0] >>>at >>>java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149) >>> ~[?:1.8.0_272] >>>at >>>java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624) >>> ~[?:1.8.0_272] >>>at java.lang.Thread.run(Thread.java:748) [?:1.8.0_272] >>>2020-12-07 17:32:21.558 [] [ db-c heckpoint-thread-# 75 %tradecore%] WARN >>>o.a.i.i.p.c.CacheDiagnosticManager - Page locks dump: >>>Thread=[name=Ims-PublishThread-sync0, id= 122 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=Ims-PublishThread-sync0 time=( 1607333541277 , >>>2020-12-07 17:32:21.277 ) >>>Thread=[name=MessageBus- 1 , id= 22 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=MessageBus- 1 time=( 1607333541276 , 2020-12-07 >>>17:32:21.276 ) >>>Thread=[name=MessageBus- 2 , id= 23 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=MessageBus- 2 time=( 1607333541276 , 2020-12-07 >>>17:32:21.276 ) >>>Thread=[name=MessageBus- 3 , id= 24 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=MessageBus- 3 time=( 1607333541276 , 2020-12-07 >>>17:32:21.276 ) >>>Thread=[name=MessageBus- 4 , id= 25 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=MessageBus- 4 time=( 1607333541276 , 2020-12-07 >>>17:32:21.276 ) >>>Thread=[name=checkpoint-runner-# 76 %tradecore%, id= 114 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=checkpoint-runner-# 76 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=checkpoint-runner-# 77 %tradecore%, id= 115 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=checkpoint-runner-# 77 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=checkpoint-runner-# 78 %tradecore%, id= 116 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=checkpoint-runner-# 78 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=checkpoint-runner-# 79 %tradecore%, id= 117 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=checkpoint-runner-# 79 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-0 -# 9 %tradecore%, id= 34 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-0 -# 9 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-1 -# 10 %tradecore%, id= 35 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-1 -# 10 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-2 -# 11 %tradecore%, id= 36 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-2 -# 11 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-3 -# 12 %tradecore%, id= 37 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-3 -# 12 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-4 -# 13 %tradecore%, id= 38 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-4 -# 13 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-5 -# 14 %tradecore%, id= 39 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-5 -# 14 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-6 -# 15 %tradecore%, id= 40 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-6 -# 15 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=data-streamer-strip e-7 -# 16 %tradecore%, id= 41 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=data-streamer-strip e-7 -# 16 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name= db-c heckpoint-thread-# 75 %tradecore%, id= 113 ], >>>state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name= db-c heckpoint-thread-# 75 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=dms-writer-thread-# 58 %tradecore%, id= 95 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=dms-writer-thread-# 58 %tradecore% time=( >>>1607333541277 , 2020-12-07 17:32:21.277 ) >>>Thread=[name=exchange-worker-# 54 %tradecore%, id= 91 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=exchange-worker-# 54 %tradecore% time=( 1607333541276 >>>, 2020-12-07 17:32:21.276 ) >>>Thread=[name=jdbc-request-handler-worker-# 29357 %tradecore%, id= 39238 ], >>>state=WAITING >>>Locked pages = [] >>>Locked pages log: name=jdbc-request-handler-worker-# 29357 %tradecore% >>>time=( 1607333541274 , 2020-12-07 17:32:21.274 ) >>>Thread=[name=vacuum-cleaner-# 67 %tradecore%, id= 105 ], state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 67 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 68 %tradecore%, id= 106 ], state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 68 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 69 %tradecore%, id= 107 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 69 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 70 %tradecore%, id= 108 ], state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 70 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 71 %tradecore%, id= 109 ], state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 71 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 72 %tradecore%, id= 110 ], state=RUNNABLE >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 72 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 73 %tradecore%, id= 111 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 73 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>Thread=[name=vacuum-cleaner-# 74 %tradecore%, id= 112 ], state=WAITING >>>Locked pages = [] >>>Locked pages log: name=vacuum-cleaner-# 74 %tradecore% time=( 1607333541277 >>>, 2020-12-07 17:32:21.277 ) >>>2020-12-07 17:32:21.558 [] [ db-c heckpoint-thread-# 75 %tradecore%] ERROR >>>c.j.i.i.c.IgniteConfig - JVM will be halted immediately due to the failure: >>>[failureCtx=FailureContext [type=CRITICAL_ERROR, err=class >>>o.a.i.IgniteCheckedException : Compound exception for CountDownFuture.]]
