[
https://issues.apache.org/jira/browse/IGNITE-12712?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=17041893#comment-17041893
]
Ignite TC Bot commented on IGNITE-12712:
----------------------------------------
{panel:title=Branch: [pull/7463/head] Base: [master] : No blockers
found!|borderStyle=dashed|borderColor=#ccc|titleBGColor=#D6F7C1}{panel}
[TeamCity *--> Run :: All*
Results|https://ci.ignite.apache.org/viewLog.html?buildId=5069465&buildTypeId=IgniteTests24Java8_RunAll]
> 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
> Priority: Major
> Time Spent: 10m
> Remaining Estimate: 0h
>
> 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)
