Anton Kalashnikov created IGNITE-12712:
------------------------------------------
Summary: NPE in checkpoint thread
Key: IGNITE-12712
URL: https://issues.apache.org/jira/browse/IGNITE-12712
Project: Ignite
Issue Type: Bug
Reporter: Anton Kalashnikov
Assignee: Anton Kalashnikov
NPE occured in checkpoint thread (rare reproducing):
{noformat}
[2019-11-04 20:54:58,018][INFO ][sys-#50][GridDhtPartitionsExchangeFuture]
Received full message, will finish exchange
[node=1784645d-3bef-44fe-8288-e0c16202f5e3, resVer=AffinityTopologyVersion
[topVer=4, minorTopVer=9]]
[2019-11-04 20:54:58,023][INFO ][sys-#50][GridDhtPartitionsExchangeFuture]
Finish exchange future [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=9], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=9],
err=null]
[2019-11-04 20:54:58,029][INFO ][sys-#50][GridCacheProcessor] Finish proxy
initialization, cacheName=SQL_PUBLIC_T8,
localNodeId=5b153e14-70f2-4408-a125-584752532ebd
[2019-11-04 20:54:58,030][INFO ][sys-#50][GridDhtPartitionsExchangeFuture]
Completed partition exchange [localNode=5b153e14-70f2-4408-a125-584752532ebd,
exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion
[topVer=4, minorTopVer=9], evt=DISCOVERY_CUSTOM_EVT, evtNode=TcpDiscoveryNode
[id=1784645d-3bef-44fe-8288-e0c16202f5e3, consistentId=1, addrs=ArrayList
[127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=1,
intOrder=1, lastExchangeTime=1572890071469, loc=false,
ver=8.7.8#20191101-sha1:e344ed04, isClient=false], done=true, newCrdFut=null],
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=9]]
[2019-11-04 20:54:58,030][INFO ][sys-#50][GridDhtPartitionsExchangeFuture]
Exchange timings [startVer=AffinityTopologyVersion [topVer=4, minorTopVer=9],
resVer=AffinityTopologyVersion [topVer=4, minorTopVer=9], stage="Waiting in
exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms),
stage="Update caches registry" (0 ms), stage="Start caches" (52 ms),
stage="Affinity initialization on cache group start" (1 ms), stage="Determine
exchange type" (0 ms), stage="Preloading notification" (0 ms), stage="WAL
history reservation" (0 ms), stage="Wait partitions release" (1 ms),
stage="Wait partitions release latch" (5 ms), stage="Wait partitions release"
(0 ms), stage="Restore partition states" (7 ms), stage="After states restored
callback" (10 ms), stage="Waiting for Full message" (59 ms), stage="Affinity
recalculation" (0 ms), stage="Full map updating" (4 ms), stage="Exchange done"
(7 ms), stage="Total time" (146 ms)]
[2019-11-04 20:54:58,030][INFO ][sys-#50][GridDhtPartitionsExchangeFuture]
Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=4,
minorTopVer=9], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=9],
stage="Affinity initialization on cache group start [grp=SQL_PUBLIC_T8]" (1 ms)
(parent=Affinity initialization on cache group start), stage="Restore partition
states [grp=SQL_PUBLIC_T8]" (6 ms) (parent=Restore partition states),
stage="Restore partition states [grp=ignite-sys-cache]" (3 ms) (parent=Restore
partition states), stage="Restore partition states [grp=cache_group_3]" (0 ms)
(parent=Restore partition states)]
[2019-11-04 20:54:58,037][INFO
][exchange-worker-#45][GridCachePartitionExchangeManager] Skipping rebalancing
(nothing scheduled) [top=AffinityTopologyVersion [topVer=4, minorTopVer=9],
force=false, evt=DISCOVERY_CUSTOM_EVT,
node=1784645d-3bef-44fe-8288-e0c16202f5e3]
[2019-11-04 20:54:58,713][INFO
][db-checkpoint-thread-#53][GridCacheDatabaseSharedManager] Checkpoint started
[checkpointId=82969270-b1a5-4480-9513-3af65bab0e17, startPtr=FileWALPointer
[idx=0, fileOff=3550077, len=12350], checkpointBeforeLockTime=8ms,
checkpointLockWait=4ms, checkpointListenersExecuteTime=56ms,
checkpointLockHoldTime=61ms, walCpRecordFsyncDuration=4ms,
writeCheckpointEntryDuration=8ms, splitAndSortCpPagesDuration=1ms, pages=178,
reason='timeout']
[2019-11-04 20:54:58,914][INFO ][exchange-worker-#45][time] Started exchange
init [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=10], crd=false,
evt=DISCOVERY_CUSTOM_EVT, evtNode=1784645d-3bef-44fe-8288-e0c16202f5e3,
customEvt=DynamicCacheChangeBatch
[id=8b06d873e61-af9e27a6-8fe9-4da1-bc0a-d19cd0eabd36, reqs=ArrayList
[DynamicCacheChangeRequest [cacheName=SQL_PUBLIC_T9, hasCfg=true,
nodeId=1784645d-3bef-44fe-8288-e0c16202f5e3, clientStartOnly=false, stop=false,
destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions
[startCaches=[SQL_PUBLIC_T9], stopCaches=null, startGrps=[cache_group_4],
stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false],
allowMerge=false]
[2019-11-04 20:54:58,930][INFO ][exchange-worker-#45][PageMemoryImpl] Started
page memory [memoryAllocated=200.0 MiB, pages=49630, tableSize=3.9 MiB,
checkpointBuffer=200.0 MiB]
[2019-11-04 20:54:58,933][ERROR][db-checkpoint-thread-#53][root] 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=SYSTEM_WORKER_TERMINATION,
err=java.lang.NullPointerException]]
java.lang.NullPointerException
at
org.apache.ignite.internal.processors.cache.persistence.pagemem.PageMemoryImpl.finishCheckpoint(PageMemoryImpl.java:1194)
at
org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$Checkpointer.markCheckpointEnd(GridCacheDatabaseSharedManager.java:4686)
at
org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$Checkpointer.doCheckpoint(GridCacheDatabaseSharedManager.java:4026)
at
org.apache.ignite.internal.processors.cache.persistence.GridCacheDatabaseSharedManager$Checkpointer.body(GridCacheDatabaseSharedManager.java:3782)
at
org.apache.ignite.internal.util.worker.GridWorker.run(GridWorker.java:119)
at java.base/java.lang.Thread.run(Thread.java:835)
[2019-11-04 20:54:58,938][WARN ][exchange-worker-#45][MvccProcessorImpl]
Attempting to start active vacuum.
[2019-11-04 20:54:58,938][INFO ][exchange-worker-#45][MvccProcessorImpl] Mvcc
processor started.
[2019-11-04 20:54:58,939][WARN ][db-checkpoint-thread-#53][FailureProcessor] No
deadlocked threads detected.
[2019-11-04 20:54:59,041][INFO ][exchange-worker-#45][GridCacheProcessor]
Started cache [name=SQL_PUBLIC_T9, id=-1691533654, group=cache_group_4,
dataRegionName=dataRegion4, mode=PARTITIONED, atomicity=TRANSACTIONAL_SNAPSHOT,
backups=2, mvcc=true]
[2019-11-04 20:54:59,044][INFO
][exchange-worker-#45][GridDhtPartitionsExchangeFuture] Finished waiting for
partition release future [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=10], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED]
[2019-11-04 20:54:59,047][INFO
][exchange-worker-#45][GridDhtPartitionsExchangeFuture] Finished waiting for
partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode
[id=1784645d-3bef-44fe-8288-e0c16202f5e3, consistentId=1, addrs=ArrayList
[127.0.0.1], sockAddrs=HashSet [/127.0.0.1:47500], discPort=47500, order=1,
intOrder=1, lastExchangeTime=1572890071469, loc=false,
ver=8.7.8#20191101-sha1:e344ed04, isClient=false], ackSent=true,
super=CompletableLatch [id=CompletableLatchUid [id=exchange,
topVer=AffinityTopologyVersion [topVer=4, minorTopVer=10]]]]
[2019-11-04 20:54:59,047][INFO
][exchange-worker-#45][GridDhtPartitionsExchangeFuture] Finished waiting for
partition release future [topVer=AffinityTopologyVersion [topVer=4,
minorTopVer=10], waitTime=0ms, futInfo=NA, mode=LOCAL]
[2019-11-04 20:54:59,051][WARN ][db-checkpoint-thread-#53][FailureProcessor]
Thread dump at 2019/11/04 20:54:59 MSK
{noformat}
--
This message was sent by Atlassian Jira
(v8.3.4#803005)
