You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by 38797715 <38...@qq.com> on 2020/12/07 13:31:22 UTC
[2.9.0]NPE on invoke IgniteCache.destroy()
Hi community,
Call IgniteCache.destroy Method, NPE appears,logs are as follows:
2020-12-0717:32:18.870[] [exchange-worker-#54%tradecore%]
INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
INFOo.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-0717:32:19.037[] [exchange-worker-#54%tradecore%]
INFOo.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture-
finishExchangeOnCoordinator [topVer=AffinityTopologyVersion [topVer=1,
minorTopVer=279], resVer=AffinityTopologyVersion [topVer=1,
minorTopVer=279]]
2020-12-0717:32:19.438[] [exchange-worker-#54%tradecore%]
INFOo.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-0717:32:20.870[] [db-checkpoint-thread-#75%tradecore%]
INFOo.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-0717:32:21.255[] [checkpoint-runner-#79%tradecore%]
WARNo.a.i.i.p.c.p.GridCacheDatabaseSharedManager- 1checkpoint pages were
not written yet due to unsuccessful page write lock acquisition and will
be retried
2020-12-0717:32:21.261[] [exchange-worker-#54%tradecore%]
ERRORo.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-0717:32:21.265[] [exchange-worker-#54%tradecore%]
INFOo.a.i.i.p.c.GridCacheProcessor- Stopped cache [cacheName=PksQuota]
2020-12-0717:32:21.268[] [db-checkpoint-thread-#75%tradecore%]
ERRORc.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-0717:32:21.558[] [db-checkpoint-thread-#75%tradecore%]
WARNo.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-0717:32:21.277)
Thread=[name=MessageBus-1, id=22], state=WAITING
Locked pages = []
Locked pages log: name=MessageBus-1time=(1607333541276,
2020-12-0717:32:21.276)
Thread=[name=MessageBus-2, id=23], state=WAITING
Locked pages = []
Locked pages log: name=MessageBus-2time=(1607333541276,
2020-12-0717:32:21.276)
Thread=[name=MessageBus-3, id=24], state=WAITING
Locked pages = []
Locked pages log: name=MessageBus-3time=(1607333541276,
2020-12-0717:32:21.276)
Thread=[name=MessageBus-4, id=25], state=WAITING
Locked pages = []
Locked pages log: name=MessageBus-4time=(1607333541276,
2020-12-0717: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-0717: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-0717: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-0717: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-0717:32:21.277)
Thread=[name=data-streamer-stripe-0-#9%tradecore%, id=34], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-0-#9%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-1-#10%tradecore%, id=35], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-1-#10%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-2-#11%tradecore%, id=36], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-2-#11%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-3-#12%tradecore%, id=37], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-3-#12%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-4-#13%tradecore%, id=38], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-4-#13%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-5-#14%tradecore%, id=39], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-5-#14%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-6-#15%tradecore%, id=40], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-6-#15%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=data-streamer-stripe-7-#16%tradecore%, id=41], state=WAITING
Locked pages = []
Locked pages log: name=data-streamer-stripe-7-#16%tradecore%
time=(1607333541277, 2020-12-0717:32:21.277)
Thread=[name=db-checkpoint-thread-#75%tradecore%, id=113], state=RUNNABLE
Locked pages = []
Locked pages log: name=db-checkpoint-thread-#75%tradecore%
time=(1607333541277, 2020-12-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717:32:21.277)
2020-12-0717:32:21.558[] [db-checkpoint-thread-#75%tradecore%]
ERRORc.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.]]
Re: Re[2]: [2.9.0]NPE on invoke IgniteCache.destroy()
Posted by Ilya Kasnacheev <il...@gmail.com>.
Hello!
Why don't you do it yourself if you have the understanding of the issue? It
seems you're the only one ATM.
Regards,
--
Ilya Kasnacheev
ср, 9 дек. 2020 г. в 09:27, Zhenya Stanilovsky <ar...@mail.ru>:
> looks like we deactivate pageMem concurrently with cp pageWrite, plz
> someone fill the ticket with appropriate logs.
>
>
>
> Среда, 9 декабря 2020, 4:52 +03:00 от 38797715 <38...@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 <38797715@qq.com
> <//...@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-checkpoint-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-checkpoint-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-checkpoint-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-stripe-0-#9%tradecore%, id=34], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-0-#9%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-1-#10%tradecore%, id=35], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-1-#10%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-2-#11%tradecore%, id=36], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-2-#11%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-3-#12%tradecore%, id=37], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-3-#12%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-4-#13%tradecore%, id=38], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-4-#13%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-5-#14%tradecore%, id=39], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-5-#14%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-6-#15%tradecore%, id=40], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-6-#15%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-7-#16%tradecore%, id=41], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-7-#16%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=db-checkpoint-thread-#75%tradecore%, id=113], state=RUNNABLE
> Locked pages = []
> Locked pages log: name=db-checkpoint-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-checkpoint-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.]]
>
>
>
>
>
>
Re[2]: [2.9.0]NPE on invoke IgniteCache.destroy()
Posted by Zhenya Stanilovsky <ar...@mail.ru>.
looks like we deactivate pageMem concurrently with cp pageWrite, plz someone fill the ticket with appropriate logs.
>Среда, 9 декабря 2020, 4:52 +03:00 от 38797715 <38...@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 < 38797715@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.]]
Re: [2.9.0]NPE on invoke IgniteCache.destroy()
Posted by 38797715 <38...@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 <38797715@qq.com
> <ma...@qq.com>>:
>
> Hi community,
>
> Call IgniteCache.destroy Method, NPE appears,logs are as follows:
>
> 2020-12-0717:32:18.870[] [exchange-worker-#54%tradecore%]
> INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
> INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
> INFOo.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-0717:32:18.873[] [exchange-worker-#54%tradecore%]
> INFOo.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-0717:32:19.037[] [exchange-worker-#54%tradecore%]
> INFOo.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture-
> finishExchangeOnCoordinator [topVer=AffinityTopologyVersion
> [topVer=1, minorTopVer=279], resVer=AffinityTopologyVersion
> [topVer=1, minorTopVer=279]]
> 2020-12-0717:32:19.438[] [exchange-worker-#54%tradecore%]
> INFOo.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-0717:32:20.870[] [db-checkpoint-thread-#75%tradecore%]
> INFOo.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-0717:32:21.255[] [checkpoint-runner-#79%tradecore%]
> WARNo.a.i.i.p.c.p.GridCacheDatabaseSharedManager- 1checkpoint
> pages were not written yet due to unsuccessful page write lock
> acquisition and will be retried
> 2020-12-0717:32:21.261[] [exchange-worker-#54%tradecore%]
> ERRORo.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-0717:32:21.265[] [exchange-worker-#54%tradecore%]
> INFOo.a.i.i.p.c.GridCacheProcessor- Stopped cache [cacheName=PksQuota]
> 2020-12-0717:32:21.268[] [db-checkpoint-thread-#75%tradecore%]
> ERRORc.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-0717:32:21.558[] [db-checkpoint-thread-#75%tradecore%]
> WARNo.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-0717:32:21.277)
> Thread=[name=MessageBus-1, id=22], state=WAITING
> Locked pages = []
> Locked pages log: name=MessageBus-1time=(1607333541276,
> 2020-12-0717:32:21.276)
> Thread=[name=MessageBus-2, id=23], state=WAITING
> Locked pages = []
> Locked pages log: name=MessageBus-2time=(1607333541276,
> 2020-12-0717:32:21.276)
> Thread=[name=MessageBus-3, id=24], state=WAITING
> Locked pages = []
> Locked pages log: name=MessageBus-3time=(1607333541276,
> 2020-12-0717:32:21.276)
> Thread=[name=MessageBus-4, id=25], state=WAITING
> Locked pages = []
> Locked pages log: name=MessageBus-4time=(1607333541276,
> 2020-12-0717: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-0717: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-0717: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-0717: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-0717:32:21.277)
> Thread=[name=data-streamer-stripe-0-#9%tradecore%, id=34],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-0-#9%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-1-#10%tradecore%, id=35],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-1-#10%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-2-#11%tradecore%, id=36],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-2-#11%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-3-#12%tradecore%, id=37],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-3-#12%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-4-#13%tradecore%, id=38],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-4-#13%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-5-#14%tradecore%, id=39],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-5-#14%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-6-#15%tradecore%, id=40],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-6-#15%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=data-streamer-stripe-7-#16%tradecore%, id=41],
> state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-7-#16%tradecore%
> time=(1607333541277, 2020-12-0717:32:21.277)
> Thread=[name=db-checkpoint-thread-#75%tradecore%, id=113],
> state=RUNNABLE
> Locked pages = []
> Locked pages log: name=db-checkpoint-thread-#75%tradecore%
> time=(1607333541277, 2020-12-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717: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-0717:32:21.277)
> 2020-12-0717:32:21.558[] [db-checkpoint-thread-#75%tradecore%]
> ERRORc.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.]]
>
Re: [2.9.0]NPE on invoke IgniteCache.destroy()
Posted by Ilya Kazakov <ka...@gmail.com>.
Hello! Can you provide some details, or show some short reproducer?
-----------------
Ilya Kazakov
пн, 7 дек. 2020 г. в 21:31, 38797715 <38...@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-checkpoint-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-checkpoint-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-checkpoint-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-stripe-0-#9%tradecore%, id=34], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-0-#9%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-1-#10%tradecore%, id=35], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-1-#10%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-2-#11%tradecore%, id=36], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-2-#11%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-3-#12%tradecore%, id=37], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-3-#12%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-4-#13%tradecore%, id=38], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-4-#13%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-5-#14%tradecore%, id=39], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-5-#14%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-6-#15%tradecore%, id=40], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-6-#15%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=data-streamer-stripe-7-#16%tradecore%, id=41], state=WAITING
> Locked pages = []
> Locked pages log: name=data-streamer-stripe-7-#16%tradecore% time=(
> 1607333541277, 2020-12-07 17:32:21.277)
> Thread=[name=db-checkpoint-thread-#75%tradecore%, id=113], state=RUNNABLE
> Locked pages = []
> Locked pages log: name=db-checkpoint-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-checkpoint-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.]]
>
Re: [2.9.0]NPE on invoke IgniteCache.destroy()
Posted by "slava.koptilin" <sl...@gmail.com>.
Hello,
This is definitely a bug.
The good news is that it looks like
https://issues.apache.org/jira/browse/IGNITE-13207 &
https://issues.apache.org/jira/browse/IGNITE-13151 are fixing this issue.
Both fixes are included in AI-2.10
Thanks,
S.
--
Sent from: http://apache-ignite-users.70518.x6.nabble.com/