You are viewing a plain text version of this content. The canonical link for it is here.
Posted to user@ignite.apache.org by Justin Ji <bi...@foxmail.com> on 2019/01/18 09:49:59 UTC
Re: Failed to wait for initial partition map exchange
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/