I also have this problem with ignite 2.6.0. Spend more than 350 seconds to restart a ignite node.
Here is the system usage during partition map exchange: <http://apache-ignite-users.70518.x6.nabble.com/file/t2000/1.png> The CPU is at a low level and memory is enough. Here is the logs, we can find that applying WAL changes takes a long time, about 375664ms. >>> __________ ________________ >>> / _/ ___/ |/ / _/_ __/ __/ >>> _/ // (7 7 // / / / / _/ >>> /___/\___/_/|_/___/ /_/ /___/ >>> >>> ver. 2.6.0#20180710-sha1:669feacc >>> 2018 Copyright(C) Apache Software Foundation >>> >>> Ignite documentation: http://ignite.apache.org 2019-01-18 09:17:27:979 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Config URL: file:/opt/ignite/config/ignite-config-benchmark-cn.xml 2019-01-18 09:17:27:996 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - IgniteConfiguration [igniteInstanceName=ignite-server, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=16, mgmtPoolSize=4, igfsPoolSize=8, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=16, igniteHome=/opt/ignite/apache-ignite-fabric, igniteWorkDir=/opt/ignite/apache-ignite-fabric/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@6f94fa3e, nodeId=67815159-8a6d-4c3a-b626-a82e5bea1a65, marsh=org.apache.ignite.internal.binary.BinaryMarshaller@72ade7e3, marshLocJobs=false, daemon=false, p2pEnabled=false, netTimeout=5000, sndRetryDelay=1000, sndRetryCnt=3, metricsHistSize=10000, metricsUpdateFreq=2000, metricsExpTime=9223372036854775807, discoSpi=ZookeeperDiscoverySpi [zkRootPath=/ignite/discovery, zkConnectionString=10.0.230.12:2181,10.0.223.106:2181,10.0.247.246:2181, joinTimeout=10000, sesTimeout=30000, clientReconnectDisabled=false, internalLsnr=null, stats=org.apache.ignite.spi.discovery.zk.internal.ZookeeperDiscoveryStatistics@560348e6], segPlc=STOP, segResolveAttempts=2, waitForSegOnStart=true, allResolversPassReq=true, segChkFreq=10000, commSpi=TcpCommunicationSpi [connectGate=null, connPlc=null, enableForcibleNodeKill=false, enableTroubleshootingLog=false, srvLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi$2@1df8b5b8, locAddr=null, locHost=null, locPort=47174, locPortRange=100, shmemPort=-1, directBuf=true, directSndBuf=false, idleConnTimeout=600000, connTimeout=5000, maxConnTimeout=600000, reconCnt=10, sockSndBuf=32768, sockRcvBuf=32768, msgQueueLimit=1024, slowClientQueueLimit=0, nioSrvr=null, shmemSrv=null, usePairedConnections=false, connectionsPerNode=1, tcpNoDelay=true, filterReachableAddresses=false, ackSndThreshold=32, unackedMsgsBufSize=0, sockWriteTimeout=2000, lsnr=null, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=4, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@23202fce[Count = 1], stopping=false, metricsLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationMetricsListener@7b993c65], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@37911f88, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [lsnr=null], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@4ea5b703, addrRslvr=null, clientMode=false, rebalanceThreadPoolSize=4, txCfg=org.apache.ignite.configuration.TransactionConfiguration@2a7ed1f, cacheSanityCheckEnabled=true, discoStartupDelay=60000, deployMode=SHARED, p2pMissedCacheSize=100, locHost=null, timeSrvPortBase=31100, timeSrvPortRange=100, failureDetectionTimeout=10000, clientFailureDetectionTimeout=30000, metricsLogFreq=60000, hadoopCfg=null, connectorCfg=org.apache.ignite.configuration.ConnectorConfiguration@3fa247d1, odbcCfg=null, warmupClos=null, atomicCfg=AtomicConfiguration [seqReserveSize=1000, cacheMode=PARTITIONED, backups=1, aff=null, grpName=null], classLdr=null, sslCtxFactory=null, platformCfg=null, binaryCfg=null, memCfg=null, pstCfg=null, dsCfg=DataStorageConfiguration [sysRegionInitSize=41943040, sysCacheMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=default, maxSize=3119855206, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], storagePath=/data/ignite/persistence, checkpointFreq=360000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=10, walSegments=10, walSegmentSize=67108864, walPath=/ignite-wal/ignite/wal, walArchivePath=/ignite-wal/ignite/wal/archive, metricsEnabled=false, walMode=BACKGROUND, walTlbSize=131072, walBuffSize=0, walFlushFreq=2000, walFsyncDelay=1000, walRecordIterBuffSize=67108864, alwaysWriteFullPages=false, fileIOFactory=org.apache.ignite.internal.processors.cache.persistence.file.AsyncFileIOFactory@4f4c4b1a, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=true, walCompactionEnabled=false], activeOnStart=true, autoActivation=true, longQryWarnTimeout=3000, sqlConnCfg=null, cliConnCfg=ClientConnectorConfiguration [host=null, port=10800, portRange=100, sockSndBufSize=0, sockRcvBufSize=0, tcpNoDelay=true, maxOpenCursorsPerConn=128, threadPoolSize=8, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], authEnabled=false, failureHnd=null, commFailureRslvr=DefaultCommunicationFailureResolver []] 2019-01-18 09:17:27:997 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Daemon mode: off 2019-01-18 09:17:27:998 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - OS: Linux 3.10.0-862.14.4.el7.x86_64 amd64 2019-01-18 09:17:27:998 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - OS user: root 2019-01-18 09:17:27:999 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - PID: 103 2019-01-18 09:17:28:000 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Language runtime: Java Platform API Specification ver. 1.8 2019-01-18 09:17:28:000 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - VM information: OpenJDK Runtime Environment 1.8.0_171-b11 Oracle Corporation OpenJDK 64-Bit Server VM 25.171-b11 2019-01-18 09:17:28:002 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - VM total memory: 3.0GB 2019-01-18 09:17:28:003 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Remote Management [restart: on, REST: on, JMX (remote: on, port: 49113, auth: off, ssl: off)] 2019-01-18 09:17:28:003 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Logger: Log4J2Logger [quiet=false, config=log4j2.xml] 2019-01-18 09:17:28:004 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - IGNITE_HOME=/opt/ignite/apache-ignite-fabric 2019-01-18 09:17:28:004 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - VM arguments: [-Xms3g, -Xmx3g, -XX:+AlwaysPreTouch, -XX:+UseG1GC, -XX:+ScavengeBeforeFullGC, -XX:+DisableExplicitGC, -XX:+PrintGCApplicationStoppedTime, -XX:+PrintGCApplicationConcurrentTime, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=/mnt/heapdump/ignite, -XX:+ExitOnOutOfMemoryError, -XX:+PrintGCDetails, -XX:+PrintGCTimeStamps, -XX:+PrintGCDateStamps, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=10, -XX:GCLogFileSize=100M, -Xloggc:/mnt/logs/apps/ignite/gc.log, -DIGNITE_QUIET=true, -DIGNITE_SUCCESS_FILE=/opt/ignite/apache-ignite-fabric/work/ignite_success_8719edab-bf99-496e-add5-309d532f9c9b, -Dcom.sun.management.jmxremote, -Dcom.sun.management.jmxremote.port=49113, -Dcom.sun.management.jmxremote.authenticate=false, -Dcom.sun.management.jmxremote.ssl=false, -DIGNITE_HOME=/opt/ignite/apache-ignite-fabric, -DIGNITE_PROG_NAME=/opt/ignite/apache-ignite-fabric/bin/ignite.sh] 2019-01-18 09:17:28:005 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemCacheMemorySize property to change the setting. 2019-01-18 09:17:28:017 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']] 2019-01-18 09:17:28:022 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - 3-rd party licenses can be found at: /opt/ignite/apache-ignite-fabric/libs/licenses 2019-01-18 09:17:28:114 [main] INFO o.a.i.i.p.p.IgnitePluginProcessor:478 - Configured plugins: 2019-01-18 09:17:28:114 [main] INFO o.a.i.i.p.p.IgnitePluginProcessor:478 - ^-- None 2019-01-18 09:17:28:114 [main] INFO o.a.i.i.p.p.IgnitePluginProcessor:478 - 2019-01-18 09:17:28:116 [main] INFO o.a.i.i.p.f.FailureProcessor:478 - Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0]] 2019-01-18 09:17:28:187 [main] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Successfully bound communication NIO server to TCP port [port=47174, locHost=0.0.0.0/0.0.0.0, selectorsCnt=4, selectorSpins=0, pairedConn=false] 2019-01-18 09:17:28:213 [main] WARN o.a.i.s.c.n.NoopCheckpointSpi:488 - Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation) 2019-01-18 09:17:28:248 [main] WARN o.a.i.i.m.c.GridCollisionManager:488 - Collision resolution is disabled (all jobs will be activated upon arrival). 2019-01-18 09:17:28:249 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Security status [authentication=off, tls/ssl=off] 2019-01-18 09:17:28:379 [main] INFO o.a.i.i.p.c.p.f.PdsFoldersResolver:478 - Successfully locked persistence storage folder [/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330] 2019-01-18 09:17:28:380 [main] INFO o.a.i.i.p.c.p.f.PdsFoldersResolver:478 - Consistent ID used for local node is [4fa65519-a24b-4a05-a143-d39a39b9c330] according to persistence data storage folders 2019-01-18 09:17:28:380 [main] INFO o.a.i.i.p.c.b.CacheObjectBinaryProcessorImpl:478 - Resolved directory for serialized binary metadata: /opt/ignite/apache-ignite-fabric/work/binary_meta/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:28:745 [main] INFO o.a.i.i.p.c.p.f.FilePageStoreManager:478 - Resolved page store work directory: /data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:28:746 [main] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Resolved write ahead log work directory: /ignite-wal/ignite/wal/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:28:746 [main] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Resolved write ahead log archive directory: /ignite-wal/ignite/wal/archive/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:28:772 [main] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Started write-ahead log manager [mode=BACKGROUND] 2019-01-18 09:17:28:792 [main] WARN o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:488 - Page eviction mode set for [3G_DataRegion] data will have no effect because the oldest pages are evicted automatically if Ignite persistence is enabled. 2019-01-18 09:17:28:821 [main] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Read checkpoint status [startMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-START.bin, endMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-END.bin] 2019-01-18 09:17:28:841 [main] INFO o.a.i.i.p.c.p.p.PageMemoryImpl:478 - Started page memory [memoryAllocated=100.0 MiB, pages=24808, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] 2019-01-18 09:17:28:842 [main] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Checking memory state [lastValidPos=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastMarked=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastCheckpointId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8] 2019-01-18 09:17:28:874 [main] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Found last checkpoint marker [cpId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8, pos=FileWALPointer [idx=508, fileOff=43025380, len=14626]] 2019-01-18 09:17:34:366 [main] WARN o.a.i.i.p.c.p.w.FileWriteAheadLogManager:488 - WAL segment tail is reached. [ Expected next state: {Index=540,Offset=11065132}, Actual state : {Index=9024937041086329393,Offset=23034} ] 2019-01-18 09:17:34:405 [main] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastCheckpointId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8] 2019-01-18 09:17:39:766 [main] WARN o.a.i.i.p.c.p.w.FileWriteAheadLogManager:488 - WAL segment tail is reached. [ Expected next state: {Index=540,Offset=11065132}, Actual state : {Index=9024937041086329393,Offset=23034} ] 2019-01-18 09:17:39:767 [main] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Finished applying WAL changes [updatesApplied=0, time=5366ms] 2019-01-18 09:17:39:816 [main] INFO o.a.i.i.p.c.GridClusterStateProcessor:478 - Restoring history for BaselineTopology[id=2] 2019-01-18 09:17:39:967 [main] INFO o.a.i.i.p.o.ClientListenerProcessor:478 - Client connector processor has started on TCP port 10800 2019-01-18 09:17:40:047 [main] INFO o.a.i.i.p.r.p.t.GridTcpRestProtocol:478 - Command protocol successfully started [name=TCP binary, host=0.0.0.0/0.0.0.0, port=11211] 2019-01-18 09:17:40:559 [main] INFO o.a.i.i.p.r.p.h.j.GridJettyRestProtocol:478 - Command protocol successfully started [name=Jetty REST, host=/0.0.0.0, port=8080] 2019-01-18 09:17:40:595 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Non-loopback local IPs: 10.0.230.117, 172.17.0.1, fe80:0:0:0:48a:c9ff:fe24:4b10%ens3 2019-01-18 09:17:40:596 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Enabled local MACs: 024212517DB3, 068AC9244B10 2019-01-18 09:17:40:605 [main] INFO o.a.i.s.d.z.ZookeeperDiscoverySpi:478 - Start Zookeeper discovery [zkConnectionString=10.0.230.12:2181,10.0.223.106:2181,10.0.247.246:2181, sessionTimeout=30000, zkRootPath=/ignite/discovery] 2019-01-18 09:17:40:753 [zk-ignite-server-EventThread] INFO o.a.i.s.d.z.i.ZookeeperClient:478 - ZooKeeper client state changed [prevState=Disconnected, newState=Connected] 2019-01-18 09:17:40:783 [main] INFO o.a.i.s.d.z.i.ZookeeperDiscoveryImpl:478 - Node started join [nodeId=67815159-8a6d-4c3a-b626-a82e5bea1a65, instanceName=ignite-server, zkSessionId=0x167775ea5d90428, joinDataSize=13674, consistentId=4fa65519-a24b-4a05-a143-d39a39b9c330, initTime=56, nodePath=/ignite/discovery/n/ebd81838-6ce4-4335-8eba-52b1842972d6:67815159-8a6d-4c3a-b626-a82e5bea1a65:80|0000001109] 2019-01-18 09:17:40:793 [zk-ignite-server-EventThread] INFO o.a.i.s.d.z.i.ZookeeperDiscoveryImpl:478 - Discovery coordinator already exists, watch for previous server node [locId=67815159-8a6d-4c3a-b626-a82e5bea1a65, watchPath=b179406c-8f94-4bc1-a400-9731c169b66b:23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb:80|0000001107] 2019-01-18 09:17:40:852 [zk-ignite-server-EventThread] INFO o.a.i.s.d.z.i.ZookeeperDiscoveryImpl:478 - Local join event data: ZkJoinedNodeData [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, order=18]] 2019-01-18 09:17:40:963 [main] WARN o.a.i.i.IgniteKernal%ignite-server:488 - Nodes started on local machine require more than 20% of physical RAM what can lead to significant slowdown due to swapping (please decrease JVM heap size, data region size or checkpoint buffer size) [required=17667MB, available=14876MB] 2019-01-18 09:17:40:982 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.e.time:478 - Started exchange init [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=67815159-8a6d-4c3a-b626-a82e5bea1a65, customEvt=null, allowMerge=true] 2019-01-18 09:17:40:982 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.f.FilePageStoreManager:478 - Resolved page store work directory: /data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:40:983 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Resolved write ahead log work directory: /ignite-wal/ignite/wal/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:40:983 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Resolved write ahead log archive directory: /ignite-wal/ignite/wal/archive/node00-4fa65519-a24b-4a05-a143-d39a39b9c330 2019-01-18 09:17:40:986 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Started write-ahead log manager [mode=BACKGROUND] 2019-01-18 09:17:41:000 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.p.PageMemoryImpl:478 - Started page memory [memoryAllocated=100.0 MiB, pages=24808, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] 2019-01-18 09:17:41:004 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.p.PageMemoryImpl:478 - Started page memory [memoryAllocated=100.0 MiB, pages=24808, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] 2019-01-18 09:17:41:013 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.p.PageMemoryImpl:478 - Started page memory [memoryAllocated=1.0 GiB, pages=254104, tableSize=19.8 MiB, checkpointBuffer=256.0 MiB] 2019-01-18 09:17:41:045 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.p.PageMemoryImpl:478 - Started page memory [memoryAllocated=5.0 GiB, pages=1270520, tableSize=98.8 MiB, checkpointBuffer=2.0 GiB] 2019-01-18 09:17:42:442 [grid-nio-worker-tcp-comm-0-#25%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.251.89:33706] 2019-01-18 09:17:42:912 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Read checkpoint status [startMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-START.bin, endMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-END.bin] 2019-01-18 09:17:42:913 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Checking memory state [lastValidPos=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastMarked=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastCheckpointId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8] 2019-01-18 09:17:42:930 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Found last checkpoint marker [cpId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8, pos=FileWALPointer [idx=508, fileOff=43025380, len=14626]] 2019-01-18 09:17:48:321 [exchange-worker-#42%ignite-server%] WARN o.a.i.i.p.c.p.w.FileWriteAheadLogManager:488 - WAL segment tail is reached. [ Expected next state: {Index=540,Offset=11065132}, Actual state : {Index=9024937041086329393,Offset=23034} ] 2019-01-18 09:17:48:333 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.w.FileWriteAheadLogManager:478 - Resuming logging to WAL segment [file=/ignite-wal/ignite/wal/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/0000000000000000.wal, offset=11065132, ver=2] 2019-01-18 09:17:48:397 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridClusterStateProcessor:478 - Writing BaselineTopology[id=2] 2019-01-18 09:17:48:859 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridCacheProcessor:478 - Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647] 2019-01-18 09:17:48:872 [exchange-worker-#42%ignite-server%] INFO c.t.i.c.c.DataSourceConfiguration:29 - Begin to load external configuration... 2019-01-18 09:17:48:876 [exchange-worker-#42%ignite-server%] INFO c.t.i.c.c.DataSourceConfiguration:50 - Initializing configuration url=jdbc:mysql://tuya-shadows-cluster-1.cluster-cmu36ckfhd7h.rds.cn-northwest-1.amazonaws.com.cn:3306/tuya_shadows?characterEncoding=utf-8&useUnicode=true&autoReconnect=true&allowMultiQueries=true&rewriteBatchedStatements=true,username=tuya_shadows_rw,dns cache time=30 2019-01-18 09:17:48:983 [exchange-worker-#42%ignite-server%] WARN o.a.i.i.p.c.s.CacheOsStoreManager:488 - <data_point_new> Both Ignite native persistence and CacheStore are configured for cache 'data_point_new'. This configuration does not guarantee strict consistency between CacheStore and Ignite data storage upon restarts. Consult documentation for more details. 2019-01-18 09:17:49:086 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridCacheProcessor:478 - Started cache [name=data_point_new, id=-2047491044, memoryPolicyName=5G_DataRegion, mode=PARTITIONED, atomicity=ATOMIC, backups=1] 2019-01-18 09:17:49:110 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], waitTime=0ms, futInfo=NA] 2019-01-18 09:17:49:112 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], waitTime=0ms, futInfo=NA] 2019-01-18 09:17:49:113 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Read checkpoint status [startMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-START.bin, endMarker=/data/ignite/persistence/node00-4fa65519-a24b-4a05-a143-d39a39b9c330/cp/1547802739471-37b53ea8-1fc7-4e05-901b-6a9e32b477a8-END.bin] 2019-01-18 09:17:49:114 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=508, fileOff=43025380, len=14626], lastCheckpointId=37b53ea8-1fc7-4e05-901b-6a9e32b477a8] 2019-01-18 09:17:50:972 [ignite-update-notifier-timer] WARN o.a.i.i.p.c.GridUpdateNotifier:488 - New version is available at ignite.apache.org: 2.7.0 2019-01-18 09:18:00:978 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Failed to wait for initial partition map exchange. Possible reasons are: ^-- Transactions in deadlock. ^-- Long running transactions (ignore if this is the case). ^-- Unreleased explicit locks. 2019-01-18 09:18:20:980 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:18:40:981 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:19:40:986 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:20:00:988 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:20:40:992 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:21:00:993 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:21:20:994 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:21:40:996 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:22:00:997 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:22:20:998 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:22:40:999 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:23:01:001 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:23:41:003 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:24:01:004 [main] WARN o.a.i.i.p.c.GridCachePartitionExchangeManager:488 - Still waiting for initial partition map exchange [fut=GridDhtPartitionsExchangeFuture [firstDiscoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], crd=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], exchId=GridDhtPartitionExchangeId [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], discoEvt=DiscoveryEvent [evtNode=ZookeeperClusterNode [id=67815159-8a6d-4c3a-b626-a82e5bea1a65, addrs=[172.17.0.1, 10.0.230.117, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=18, loc=true, client=false], topVer=18, nodeId8=67815159, msg=null, type=NODE_JOINED, tstamp=1547803060924], nodeId=67815159, evt=NODE_JOINED], added=true, initFut=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=1766610307], init=false, lastVer=null, partReleaseFut=PartitionReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[ExplicitLockReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AtomicUpdateReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], DataStreamerReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], LocalTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]], AllTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[RemoteTxReleaseFuture [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], futures=[]]]]]], exchActions=ExchangeActions [startCaches=null, stopCaches=null, startGrps=[], stopGrps=[], resetParts=null, stateChangeRequest=null], affChangeMsg=null, initTs=1547803060975, centralizedAff=false, forceAffReassignment=false, changeGlobalStateE=null, done=false, state=SRV, evtLatch=0, remaining=[bea075f4-a7b2-409d-8c78-5ea420d4ebd4, 23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb], super=GridFutureAdapter [ignoreInterrupts=false, state=INIT, res=null, hash=34788805]]] 2019-01-18 09:24:04:775 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Finished applying WAL changes [updatesApplied=1320211, time=375664ms] 2019-01-18 09:24:04:881 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.e.time:478 - Finished exchange init [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], crd=false] 2019-01-18 09:24:04:917 [sys-#48%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Received full message, will finish exchange [node=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, resVer=AffinityTopologyVersion [topVer=18, minorTopVer=0]] 2019-01-18 09:24:05:002 [sys-#48%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finish exchange future [startVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], err=null] 2019-01-18 09:24:05:057 [grid-nio-worker-tcp-comm-1-#26%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.216.155:51920] 2019-01-18 09:24:05:265 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridCachePartitionExchangeManager:478 - Rebalancing scheduled [order=[ignite-sys-cache, data_point_new]] 2019-01-18 09:24:05:267 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridCachePartitionExchangeManager:478 - Rebalancing started [top=AffinityTopologyVersion [topVer=18, minorTopVer=0], evt=NODE_JOINED, node=67815159-8a6d-4c3a-b626-a82e5bea1a65] 2019-01-18 09:24:05:268 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Starting rebalancing [grp=ignite-sys-cache, mode=SYNC, fromNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, partitionsCount=51, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:24:05:285 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Starting rebalancing [grp=ignite-sys-cache, mode=SYNC, fromNode=23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb, partitionsCount=49, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:24:05:791 [db-checkpoint-thread-#63%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Checkpoint started [checkpointId=d1455b4d-cee7-4909-8417-fdadc515db7e, startPtr=FileWALPointer [idx=564, fileOff=60228974, len=12726], checkpointLockWait=0ms, checkpointLockHoldTime=53ms, walCpRecordFsyncDuration=219ms, pages=145395, reason='timeout'] 2019-01-18 09:24:20:905 [grid-nio-worker-tcp-comm-2-#27%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.251.89:33710] 2019-01-18 09:24:20:907 [grid-nio-worker-tcp-comm-2-#27%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Received incoming connection when already connected to this node, rejecting [locNode=67815159-8a6d-4c3a-b626-a82e5bea1a65, rmtNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4] 2019-01-18 09:24:21:111 [grid-nio-worker-tcp-comm-3-#28%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.251.89:33712] 2019-01-18 09:24:24:201 [grid-nio-worker-tcp-comm-0-#25%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.216.155:51946] 2019-01-18 09:24:24:203 [grid-nio-worker-tcp-comm-0-#25%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Received incoming connection when already connected to this node, rejecting [locNode=67815159-8a6d-4c3a-b626-a82e5bea1a65, rmtNode=23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb] 2019-01-18 09:24:24:406 [grid-nio-worker-tcp-comm-1-#26%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.216.155:51948] 2019-01-18 09:25:30:367 [db-checkpoint-thread-#63%ignite-server%] INFO o.a.i.i.p.c.p.GridCacheDatabaseSharedManager:478 - Checkpoint finished [cpId=d1455b4d-cee7-4909-8417-fdadc515db7e, pages=145395, markPos=FileWALPointer [idx=564, fileOff=60228974, len=12726], walSegmentsCleared=37, markDuration=993ms, pagesWrite=24067ms, fsync=60505ms, total=85565ms] 2019-01-18 09:26:42:954 [utility-#71%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed rebalancing [fromNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, cacheOrGroup=ignite-sys-cache, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], time=157682 ms] 2019-01-18 09:26:42:968 [utility-#74%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed (final) rebalancing [fromNode=23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb, cacheOrGroup=ignite-sys-cache, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], time=157692 ms] 2019-01-18 09:26:42:969 [utility-#74%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed rebalance future: RebalanceFuture [grp=CacheGroupContext [grp=ignite-sys-cache], topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:26:42:970 [utility-#74%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Starting rebalancing [grp=data_point_new, mode=ASYNC, fromNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, partitionsCount=337, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:26:42:971 [utility-#74%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Starting rebalancing [grp=data_point_new, mode=ASYNC, fromNode=23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb, partitionsCount=330, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:26:43:142 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Performance suggestions for grid 'ignite-server' (fix if possible) 2019-01-18 09:26:43:142 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true 2019-01-18 09:26:43:143 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - ^-- Disable grid events (remove 'includeEventTypes' from configuration) 2019-01-18 09:26:43:143 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options) 2019-01-18 09:26:43:143 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - ^-- Decrease number of backups (set 'backups' to 0) 2019-01-18 09:26:43:146 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning 2019-01-18 09:26:43:146 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - 2019-01-18 09:26:43:146 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - To start Console Management & Monitoring run ignitevisorcmd.{sh|bat} 2019-01-18 09:26:43:147 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - 2019-01-18 09:26:43:149 [main] INFO o.a.i.i.IgniteKernal%ignite-server:478 - >>> +----------------------------------------------------------------------+ >>> Ignite ver. 2.6.0#20180710-sha1:669feacc5d3a4e60efcdd300dc8de99780f38eed >>> +----------------------------------------------------------------------+ >>> OS name: Linux 3.10.0-862.14.4.el7.x86_64 amd64 >>> CPU(s): 8 >>> Heap: 3.0GB >>> VM name: 103@nx-s-ignite-002 >>> Ignite instance name: ignite-server >>> Local node [ID=67815159-8A6D-4C3A-B626-A82E5BEA1A65, order=18, >>> clientMode=false] >>> Local node addresses: [172.17.0.1/172.17.0.1, >>> nx-s-ignite-002/10.0.230.117, /0:0:0:0:0:0:0:1%lo, /127.0.0.1] >>> Local ports: TCP:8080 TCP:10800 TCP:11211 TCP:47174 2019-01-18 09:26:43:155 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - Topology snapshot [ver=18, servers=3, clients=1, CPUs=32, offheap=36.0GB, heap=17.0GB] 2019-01-18 09:26:43:155 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- Node [id=67815159-8A6D-4C3A-B626-A82E5BEA1A65, clusterState=ACTIVE] 2019-01-18 09:26:43:156 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- Baseline [id=2, size=3, online=3, offline=0] 2019-01-18 09:26:43:156 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - Data Regions Configured: 2019-01-18 09:26:43:158 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- default [initSize=256.0 MiB, maxSize=2.9 GiB, persistenceEnabled=false] 2019-01-18 09:26:43:159 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- 1G_DataRegion [initSize=512.0 MiB, maxSize=1.0 GiB, persistenceEnabled=true] 2019-01-18 09:26:43:159 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- 3G_DataRegion [initSize=512.0 MiB, maxSize=3.0 GiB, persistenceEnabled=false] 2019-01-18 09:26:43:160 [main] INFO o.a.i.i.m.d.GridDiscoveryManager:478 - ^-- 5G_DataRegion [initSize=512.0 MiB, maxSize=5.0 GiB, persistenceEnabled=true] 2019-01-18 09:26:47:855 [grid-nio-worker-tcp-comm-2-#27%ignite-server%] INFO o.a.i.s.c.t.TcpCommunicationSpi:478 - Accepted incoming communication connection [locAddr=/10.0.230.117:47174, rmtAddr=/10.0.214.219:36298] 2019-01-18 09:27:43:141 [grid-timeout-worker-#23%ignite-server%] INFO o.a.i.i.IgniteKernal%ignite-server:478 - Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=67815159, name=ignite-server, uptime=00:01:00.005] ^-- H/N/C [hosts=4, nodes=4, CPUs=32] ^-- CPU [cur=70.6%, avg=12.89%, GC=0.53%] ^-- PageMemory [pages=1130803] ^-- Heap [used=2230MB, free=27.39%, comm=3072MB] ^-- Non heap [used=75MB, free=-1%, comm=77MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=6, idle=10, qSize=0] 2019-01-18 09:28:10:913 [sys-#43%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed rebalancing [fromNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, cacheOrGroup=data_point_new, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], time=87942 ms] 2019-01-18 09:28:15:627 [sys-#46%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed (final) rebalancing [fromNode=23fe0ad0-2b6d-4b28-bc6b-c9cb84a8becb, cacheOrGroup=data_point_new, topology=AffinityTopologyVersion [topVer=18, minorTopVer=0], time=92658 ms] 2019-01-18 09:28:15:628 [sys-#46%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionDemander:478 - Completed rebalance future: RebalanceFuture [grp=CacheGroupContext [grp=data_point_new], topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], rebalanceId=1] 2019-01-18 09:28:17:202 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.e.time:478 - Started exchange init [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, customEvt=CacheAffinityChangeMessage [id=fcc5eef5861-b0e299ac-bcd4-4ecf-855c-af770da317dc, topVer=AffinityTopologyVersion [topVer=18, minorTopVer=0], exchId=null, partsMsg=null, exchangeNeeded=true], allowMerge=false] 2019-01-18 09:28:17:209 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], waitTime=0ms, futInfo=NA] 2019-01-18 09:28:17:666 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finished waiting for partitions release latch: ClientLatch [coordinator=ZookeeperClusterNode [id=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, addrs=[172.17.0.1, 10.0.251.89, 0:0:0:0:0:0:0:1%lo, 127.0.0.1], order=3, loc=false, client=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=18, minorTopVer=1]]] 2019-01-18 09:28:17:666 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], waitTime=0ms, futInfo=NA] 2019-01-18 09:28:17:678 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.e.time:478 - Finished exchange init [topVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], crd=false] 2019-01-18 09:28:17:685 [sys-#49%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Received full message, will finish exchange [node=bea075f4-a7b2-409d-8c78-5ea420d4ebd4, resVer=AffinityTopologyVersion [topVer=18, minorTopVer=1]] 2019-01-18 09:28:17:686 [sys-#49%ignite-server%] INFO o.a.i.i.p.c.d.d.p.GridDhtPartitionsExchangeFuture:478 - Finish exchange future [startVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=18, minorTopVer=1], err=null] 2019-01-18 09:28:17:688 [exchange-worker-#42%ignite-server%] INFO o.a.i.i.p.c.GridCachePartitionExchangeManager:478 - Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=18, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=bea075f4-a7b2-409d-8c78-5ea420d4ebd4] 2019-01-18 09:28:19:008 [flusher-0-#50%ignite-server%] INFO c.t.i.c.s.DataPointCacheStore:43 - begin write records to database:smart_datapoint And I also reviewed the GC log, the GC became more frequent(1 time per second), but only took 10~50ms. Can anyone tell me how to decrease the stop time of ignite cluster. -- Sent from: http://apache-ignite-users.70518.x6.nabble.com/