attaching log of the tow nodes crashing everytime, I have 4 nodes but the other two nodes ver rarely crashed. All nodes(VM) are 4CPU/16GB RAm/200GB HDD(Shared Storage)
node 3: [16:35:21,938][INFO][main][IgniteKernal] >>> __________ ________________ >>> / _/ ___/ |/ / _/_ __/ __/ >>> _/ // (7 7 // / / / / _/ >>> /___/\___/_/|_/___/ /_/ /___/ >>> >>> ver. 2.6.0#20180710-sha1:669feacc >>> 2018 Copyright(C) Apache Software Foundation >>> >>> Ignite documentation: http://ignite.apache.org [16:35:21,946][INFO][main][IgniteKernal] Config URL: file:/data/ignitedata/apache-ignite-fabric-2.6.0-bin/config/default-config.xml [16:35:21,954][INFO][main][IgniteKernal] IgniteConfiguration [igniteInstanceName=null, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=8, mgmtPoolSize=4, igfsPoolSize=4, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=8, igniteHome=/data/ignitedata/apache-ignite-fabric-2.6.0-bin, igniteWorkDir=/data/ignitedata/apache-ignite-fabric-2.6.0-bin/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@6f94fa3e, nodeId=df202ccb-356f-426a-8131-e2cc0b9bf98f, marsh=org.apache.ignite.internal.binary.BinaryMarshaller@3023df74, marshLocJobs=false, daemon=false, p2pEnabled=false, netTimeout=5000, sndRetryDelay=1000, sndRetryCnt=3, metricsHistSize=10000, metricsUpdateFreq=2000, metricsExpTime=9223372036854775807, discoSpi=TcpDiscoverySpi [addrRslvr=null, sockTimeout=0, ackTimeout=0, marsh=null, reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null], 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@6302bbb1, locAddr=null, locHost=null, locPort=47100, locPortRange=100, shmemPort=-1, directBuf=true, directSndBuf=false, idleConnTimeout=600000, connTimeout=5000, maxConnTimeout=600000, reconCnt=10, sockSndBuf=32768, sockRcvBuf=32768, msgQueueLimit=0, slowClientQueueLimit=1000, 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@31304f14[Count = 1], stopping=false, metricsLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationMetricsListener@34a3d150], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@2a4fb17b, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [lsnr=null], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@7cc0cdad, addrRslvr=null, clientMode=false, rebalanceThreadPoolSize=1, txCfg=org.apache.ignite.configuration.TransactionConfiguration@7c7b252e, 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@4d5d943d, 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=10737418240, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=true, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=true, checkpointPageBufSize=0], storagePath=/data/ignitedata/data, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, walSegments=10, walSegmentSize=67108864, walPath=/root/ignite/wal, walArchivePath=db/wal/archive, metricsEnabled=true, walMode=LOG_ONLY, walTlbSize=131072, walBuffSize=0, walFlushFreq=2000, walFsyncDelay=1000, walRecordIterBuffSize=67108864, alwaysWriteFullPages=false, fileIOFactory=org.apache.ignite.internal.processors.cache.persistence.file.AsyncFileIOFactory@4c583ecf, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false], activeOnStart=true, autoActivation=true, longQryWarnTimeout=500, 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=true, failureHnd=null, commFailureRslvr=null] [16:35:21,954][INFO][main][IgniteKernal] Daemon mode: off [16:35:21,954][INFO][main][IgniteKernal] OS: Linux 3.10.0-862.3.2.el7.x86_64 amd64 [16:35:21,955][INFO][main][IgniteKernal] OS user: root [16:35:21,955][INFO][main][IgniteKernal] PID: 9038 [16:35:21,955][INFO][main][IgniteKernal] Language runtime: Java Platform API Specification ver. 1.8 [16:35:21,955][INFO][main][IgniteKernal] VM information: Java(TM) SE Runtime Environment 1.8.0_171-b11 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.171-b11 [16:35:21,957][INFO][main][IgniteKernal] VM total memory: 1.0GB [16:35:21,957][INFO][main][IgniteKernal] Remote Management [restart: on, REST: on, JMX (remote: on, port: 49163, auth: off, ssl: off)] [16:35:21,957][INFO][main][IgniteKernal] Logger: JavaLogger [quiet=true, config=null] [16:35:21,957][INFO][main][IgniteKernal] IGNITE_HOME=/data/ignitedata/apache-ignite-fabric-2.6.0-bin [16:35:21,957][INFO][main][IgniteKernal] VM arguments: [-Xms1g, -Xmx1g, -XX:+AggressiveOpts, -XX:MaxMetaspaceSize=256m, -XX:+UseG1GC, -DIGNITE_QUIET=true, -DIGNITE_SUCCESS_FILE=/data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/ignite_success_41e927d2-f522-4b8e-aec5-dbe288f53bae, -Dcom.sun.management.jmxremote, -Dcom.sun.management.jmxremote.port=49163, -Dcom.sun.management.jmxremote.authenticate=false, -Dcom.sun.management.jmxremote.ssl=false, -DIGNITE_HOME=/data/ignitedata/apache-ignite-fabric-2.6.0-bin, -DIGNITE_PROG_NAME=bin/ignite.sh] [16:35:21,958][INFO][main][IgniteKernal] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemCacheMemorySize property to change the setting. [16:35:21,967][INFO][main][IgniteKernal] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']] [16:35:21,970][INFO][main][IgniteKernal] 3-rd party licenses can be found at: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/libs/licenses [16:35:22,023][INFO][main][IgnitePluginProcessor] Configured plugins: [16:35:22,023][INFO][main][IgnitePluginProcessor] ^-- None [16:35:22,023][INFO][main][IgnitePluginProcessor] [16:35:22,024][INFO][main][FailureProcessor] Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0]] [16:35:22,094][INFO][main][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=47100, locHost=0.0.0.0/0.0.0.0, selectorsCnt=4, selectorSpins=0, pairedConn=false] [16:35:22,127][WARNING][main][TcpCommunicationSpi] Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides. [16:35:22,145][WARNING][main][NoopCheckpointSpi] Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation) [16:35:22,171][WARNING][main][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival). [16:35:22,172][INFO][main][IgniteKernal] Security status [authentication=off, tls/ssl=off] [16:35:22,223][INFO][main][TcpDiscoverySpi] Successfully bound to TCP port [port=47500, localHost=0.0.0.0/0.0.0.0, locNodeId=df202ccb-356f-426a-8131-e2cc0b9bf98f] [16:35:22,390][INFO][main][PdsFoldersResolver] Successfully created new persistent storage folder [/data/ignitedata/data/node00-84153e73-2d96-49b3-b593-bef18c8218f9] [16:35:22,391][INFO][main][PdsFoldersResolver] Consistent ID used for local node is [84153e73-2d96-49b3-b593-bef18c8218f9] according to persistence data storage folders [16:35:22,397][INFO][main][CacheObjectBinaryProcessorImpl] Resolved directory for serialized binary metadata: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/binary_meta/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:22,596][INFO][main][FilePageStoreManager] Resolved page store work directory: /data/ignitedata/data/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:22,598][INFO][main][FileWriteAheadLogManager] Resolved write ahead log work directory: /root/ignite/wal/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:22,655][INFO][main][FileWriteAheadLogManager] Resolved write ahead log archive directory: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/db/wal/archive/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:22,673][INFO][main][FileWriteAheadLogManager] Started write-ahead log manager [mode=LOG_ONLY] [16:35:22,714][INFO][main][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:22,739][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:22,740][INFO][main][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=FileWALPointer [idx=0, fileOff=0, len=0], lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:22,755][INFO][main][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:22,756][INFO][main][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=0ms] [16:35:22,838][INFO][main][ClientListenerProcessor] Client connector processor has started on TCP port 10800 [16:35:22,883][INFO][main][GridTcpRestProtocol] Command protocol successfully started [name=TCP binary, host=0.0.0.0/0.0.0.0, port=11211] [16:35:22,932][INFO][main][IgniteKernal] Non-loopback local IPs: 64.101.22.98, fe80:0:0:0:f816:3eff:fe3c:aad6%eth0 [16:35:22,932][INFO][main][IgniteKernal] Enabled local MACs: FA163E3CAAD6 [16:35:24,227][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/64.101.22.96, rmtPort=39781] [16:35:24,237][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/64.101.22.96, rmtPort=39781] [16:35:24,238][INFO][tcp-disco-sock-reader-#5][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/64.101.22.96:39781, rmtPort=39781] [16:35:24,327][WARNING][main][IgniteKernal] 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=13412MB, available=15885MB] [16:35:24,391][INFO][main][IgniteKernal] Performance suggestions for grid (fix if possible) [16:35:24,392][INFO][main][IgniteKernal] To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true [16:35:24,392][INFO][main][IgniteKernal] ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options) [16:35:24,392][INFO][main][IgniteKernal] ^-- Disable processing of calls to System.gc() (add '-XX:+DisableExplicitGC' to JVM options) [16:35:24,392][INFO][main][IgniteKernal] ^-- Speed up flushing of dirty pages by OS (alter vm.dirty_expire_centisecs parameter by setting to 500) [16:35:24,392][INFO][main][IgniteKernal] ^-- Reduce pages swapping ratio (set vm.swappiness=10) [16:35:24,392][INFO][main][IgniteKernal] Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning [16:35:24,393][INFO][main][IgniteKernal] [16:35:24,393][INFO][main][IgniteKernal] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat} [16:35:24,393][INFO][main][IgniteKernal] [16:35:24,394][INFO][main][IgniteKernal] >>> +----------------------------------------------------------------------+ >>> Ignite ver. 2.6.0#20180710-sha1:669feacc5d3a4e60efcdd300dc8de99780f38eed >>> +----------------------------------------------------------------------+ >>> OS name: Linux 3.10.0-862.3.2.el7.x86_64 amd64 >>> CPU(s): 4 >>> Heap: 1.0GB >>> VM name: 9038@ccrc_spark_analytic_4 >>> Local node [ID=DF202CCB-356F-426A-8131-E2CC0B9BF98F, order=3, >>> clientMode=false] >>> Local node addresses: [64.101.22.98/0:0:0:0:0:0:0:1%lo, /127.0.0.1, >>> /64.101.22.98] >>> Local ports: TCP:10800 TCP:11211 TCP:47100 UDP:47400 TCP:47500 [16:35:24,394][INFO][main][IgniteKernal] >>> Ignite cluster is not active (limited functionality available). Use control.(sh|bat) script or IgniteCluster interface to activate. [16:35:24,396][INFO][main][GridDiscoveryManager] Topology snapshot [ver=3, servers=3, clients=0, CPUs=12, offheap=30.0GB, heap=3.0GB] [16:35:24,396][INFO][main][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=INACTIVE] [16:35:24,396][INFO][main][GridDiscoveryManager] Data Regions Configured: [16:35:24,396][INFO][main][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:35:25,812][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=4, intOrder=4, lastExchangeTime=1533832525697, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false] [16:35:25,814][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=4, servers=4, clients=0, CPUs=16, offheap=40.0GB, heap=4.0GB] [16:35:25,814][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=INACTIVE] [16:35:25,814][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:35:25,814][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:35:34,340][INFO][ignite-update-notifier-timer][GridUpdateNotifier] Your version is up to date. [16:35:40,648][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Received activate request with BaselineTopology[id=0] [16:35:40,652][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Started state transition: true [16:35:40,667][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=9eb5b437-977b-4a27-874d-2f554f11b3b1, customEvt=ChangeGlobalStateMessage [id=a48da8f1561-17023b74-7b2a-4808-acff-c836ff2bfc3b, reqId=393b2bd6-1a39-41a3-b889-6bcb348c0b7f, initiatingNodeId=9eb5b437-977b-4a27-874d-2f554f11b3b1, activate=true, baselineTopology=BaselineTopology [id=0, branchingHash=-3794941467, branchingType='New BaselineTopology', baselineNodes=[ed7c9512-9c83-4c0f-a13c-0ee2016f31a3, 5ddaed11-e882-450d-bc91-f14704edfffc, 66183021-00d7-4afa-bef4-dca67652cd67, 84153e73-2d96-49b3-b593-bef18c8218f9]], forceChangeBaselineTopology=false, timestamp=1533832540592], allowMerge=false] [16:35:40,668][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Start activation process [nodeId=df202ccb-356f-426a-8131-e2cc0b9bf98f, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:40,668][INFO][exchange-worker-#43][FilePageStoreManager] Resolved page store work directory: /data/ignitedata/data/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:40,669][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resolved write ahead log work directory: /root/ignite/wal/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:40,669][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resolved write ahead log archive directory: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/db/wal/archive/node00-84153e73-2d96-49b3-b593-bef18c8218f9 [16:35:40,669][INFO][exchange-worker-#43][FileWriteAheadLogManager] Started write-ahead log manager [mode=LOG_ONLY] [16:35:40,679][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:40,733][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=10.0 GiB, pages=2541052, tableSize=197.7 MiB, checkpointBuffer=2.0 GiB] [16:35:40,735][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:40,782][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:40,783][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=FileWALPointer [idx=0, fileOff=0, len=0], lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:40,784][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resuming logging to WAL segment [file=/root/ignite/wal/node00-84153e73-2d96-49b3-b593-bef18c8218f9/0000000000000000.wal, offset=0, ver=2] [16:35:40,865][INFO][exchange-worker-#43][GridClusterStateProcessor] Writing BaselineTopology[id=0] [16:35:41,193][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647] [16:35:41,199][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Successfully activated caches [nodeId=df202ccb-356f-426a-8131-e2cc0b9bf98f, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:41,211][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:35:41,231][INFO][grid-nio-worker-tcp-comm-0-#25][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/64.101.22.98:35468, rmtAddr=/64.101.22.95:47100] [16:35:41,324][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832524246, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]]] [16:35:41,324][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:35:41,325][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:41,325][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:41,406][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=81ms] [16:35:41,489][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=09382c71-988c-40e1-a1a9-896559b1fc5a, startPtr=FileWALPointer [idx=0, fileOff=261363, len=47], checkpointLockWait=0ms, checkpointLockHoldTime=2ms, walCpRecordFsyncDuration=65ms, pages=27, reason='node started'] [16:35:41,491][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], crd=false] [16:35:41,650][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Received state change finish message: true [16:35:41,656][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:41,659][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], err=null] [16:35:41,682][INFO][grid-nio-worker-tcp-comm-1-#26][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/64.101.22.98:58728, rmtAddr=ccrc_spark_analytic_2.cisco.com/64.101.22.96:47100] [16:35:41,687][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=4, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=9eb5b437-977b-4a27-874d-2f554f11b3b1] [16:35:41,690][INFO][sys-#53][GridClusterStateProcessor] Successfully performed final activation steps [nodeId=df202ccb-356f-426a-8131-e2cc0b9bf98f, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:41,703][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=09382c71-988c-40e1-a1a9-896559b1fc5a, pages=27, markPos=FileWALPointer [idx=0, fileOff=261363, len=47], walSegmentsCleared=0, markDuration=83ms, pagesWrite=11ms, fsync=200ms, total=295ms] [16:36:16,567][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/64.101.22.98, rmtPort=48566] [16:36:16,567][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/64.101.22.98, rmtPort=48566] [16:36:16,567][INFO][tcp-disco-sock-reader-#7][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/64.101.22.98:48566, rmtPort=48566] [16:36:16,669][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=855d5f8d-57d0-49f0-830e-da51908019d2, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.98], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.98:0], discPort=0, order=5, intOrder=5, lastExchangeTime=1533832576626, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:16,670][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=5, servers=4, clients=1, CPUs=16, offheap=50.0GB, heap=8.4GB] [16:36:16,671][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:16,671][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:16,671][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:16,671][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:16,673][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=null, allowMerge=true] [16:36:16,674][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], err=null] [16:36:16,674][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], crd=false] [16:36:16,675][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=5, minorTopVer=0], evt=NODE_JOINED, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:36:17,445][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=DynamicCacheChangeBatch [id=612bb8f1561-de578bea-fbc7-4fe6-8d49-95906395021b, reqs=[DynamicCacheChangeRequest [cacheName=SQL_PUBLIC_QHDR, hasCfg=true, nodeId=855d5f8d-57d0-49f0-830e-da51908019d2, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[SQL_PUBLIC_QHDR], stopCaches=null, startGrps=[SQL_PUBLIC_QHDR], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false] [16:36:17,603][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=SQL_PUBLIC_QHDR, id=-2066276374, memoryPolicyName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1] [16:36:17,615][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:36:17,625][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832524246, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1]]] [16:36:17,626][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:36:17,693][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], crd=false] [16:36:17,724][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=5, minorTopVer=1]] [16:36:17,728][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], err=null] [16:36:17,744][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=5, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:36:17,765][INFO][pub-#59][GridCacheDatabaseSharedManager] Finished indexes rebuilding for cache [name=SQL_PUBLIC_QHDR, grpName=null] [16:36:24,394][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:01:00.001] ^-- H/N/C [hosts=4, nodes=5, CPUs=16] ^-- CPU [cur=0.27%, avg=1.78%, GC=0%] ^-- PageMemory [pages=37] ^-- Heap [used=64MB, free=93.72%, comm=1024MB] ^-- Non heap [used=51MB, free=93.11%, comm=52MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=1, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] [16:36:32,304][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=6036816f-cbb9-43b3-94ff-ec55f233155d, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.96], sockAddrs=[ccrc_spark_analytic_2.cisco.com/64.101.22.96:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1533832592256, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,305][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=6, servers=4, clients=2, CPUs=16, offheap=60.0GB, heap=12.0GB] [16:36:32,305][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:32,306][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,306][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,306][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,307][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=6036816f-cbb9-43b3-94ff-ec55f233155d, customEvt=null, allowMerge=true] [16:36:32,307][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], err=null] [16:36:32,307][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], crd=false] [16:36:32,311][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=6, minorTopVer=0], evt=NODE_JOINED, node=6036816f-cbb9-43b3-94ff-ec55f233155d] [16:36:32,321][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=4cd15597-95eb-4870-b683-e23f4bea674b, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.98], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.98:0], discPort=0, order=7, intOrder=7, lastExchangeTime=1533832592267, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,322][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=7, servers=4, clients=3, CPUs=16, offheap=70.0GB, heap=16.0GB] [16:36:32,322][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:32,322][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,322][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,323][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,323][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=4cd15597-95eb-4870-b683-e23f4bea674b, customEvt=null, allowMerge=true] [16:36:32,324][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], err=null] [16:36:32,324][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], crd=false] [16:36:32,328][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=7, minorTopVer=0], evt=NODE_JOINED, node=4cd15597-95eb-4870-b683-e23f4bea674b] [16:36:32,482][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.95:0], discPort=0, order=8, intOrder=8, lastExchangeTime=1533832592439, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,483][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=8, servers=4, clients=4, CPUs=16, offheap=80.0GB, heap=19.0GB] [16:36:32,483][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:32,483][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,483][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,484][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,487][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58, customEvt=null, allowMerge=true] [16:36:32,488][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], err=null] [16:36:32,488][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], crd=false] [16:36:32,494][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=8, minorTopVer=0], evt=NODE_JOINED, node=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58] [16:36:32,914][INFO][grid-nio-worker-tcp-comm-2-#27][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.98:47100, rmtAddr=/64.101.22.96:45300] [16:36:33,131][INFO][grid-nio-worker-tcp-comm-3-#28][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:47100, rmtAddr=/127.0.0.1:60546] [16:36:33,455][INFO][grid-nio-worker-tcp-comm-0-#25][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.98:47100, rmtAddr=/64.101.22.95:36782] [16:36:35,872][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/64.101.22.97, rmtPort=41060] [16:36:35,872][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/64.101.22.97, rmtPort=41060] [16:36:35,873][INFO][tcp-disco-sock-reader-#9][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/64.101.22.97:41060, rmtPort=41060] [16:36:36,085][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=e55be418-9131-4abd-8f9c-d3616a0cb508, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=9, intOrder=9, lastExchangeTime=1533832595986, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:36,086][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=9, servers=4, clients=5, CPUs=16, offheap=90.0GB, heap=23.0GB] [16:36:36,086][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:36,086][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:36,086][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:36,086][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:36,091][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=e55be418-9131-4abd-8f9c-d3616a0cb508, customEvt=null, allowMerge=true] [16:36:36,092][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], err=null] [16:36:36,092][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], crd=false] [16:36:36,095][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=9, minorTopVer=0], evt=NODE_JOINED, node=e55be418-9131-4abd-8f9c-d3616a0cb508] [16:36:36,105][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=e780e47b-9117-4382-8b4d-d4de92c69b46, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=10, intOrder=10, lastExchangeTime=1533832596025, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:36,106][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=10, servers=4, clients=6, CPUs=16, offheap=100.0GB, heap=26.0GB] [16:36:36,106][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:36:36,106][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:36,106][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:36,106][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:36,110][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=e780e47b-9117-4382-8b4d-d4de92c69b46, customEvt=null, allowMerge=true] [16:36:36,110][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], err=null] [16:36:36,111][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], crd=false] [16:36:36,114][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=10, minorTopVer=0], evt=NODE_JOINED, node=e780e47b-9117-4382-8b4d-d4de92c69b46] [16:36:37,018][INFO][grid-nio-worker-tcp-comm-1-#26][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.98:47100, rmtAddr=/64.101.22.97:50666] [16:36:37,145][INFO][grid-nio-worker-tcp-comm-2-#27][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.98:47100, rmtAddr=/64.101.22.97:50668] [16:37:24,392][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:02:00.004] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=36.1%, avg=14.65%, GC=0.33%] ^-- PageMemory [pages=251780] ^-- Heap [used=453MB, free=55.75%, comm=1024MB] ^-- Non heap [used=60MB, free=91.92%, comm=64MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:38:24,399][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:03:00.008] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=5.17%, avg=19.52%, GC=0%] ^-- PageMemory [pages=501357] ^-- Heap [used=121MB, free=88.1%, comm=1024MB] ^-- Non heap [used=61MB, free=91.69%, comm=65MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:38:43,106][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=539d8365-1bcd-4816-95ed-003980a879dc, startPtr=FileWALPointer [idx=54, fileOff=52068068, len=11795], checkpointLockWait=1ms, checkpointLockHoldTime=43ms, walCpRecordFsyncDuration=453ms, pages=566123, reason='timeout'] [16:39:19,141][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=539d8365-1bcd-4816-95ed-003980a879dc, pages=566123, markPos=FileWALPointer [idx=54, fileOff=52068068, len=11795], walSegmentsCleared=0, markDuration=1696ms, pagesWrite=22171ms, fsync=13864ms, total=37732ms] [16:39:24,402][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:04:00.017] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=15.5%, avg=24.94%, GC=0.2%] ^-- PageMemory [pages=688740] ^-- Heap [used=507MB, free=50.4%, comm=1024MB] ^-- Non heap [used=64MB, free=91.36%, comm=65MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:40:24,411][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:05:00.020] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=25.57%, avg=24.47%, GC=0.43%] ^-- PageMemory [pages=887105] ^-- Heap [used=400MB, free=60.93%, comm=1024MB] ^-- Non heap [used=63MB, free=91.51%, comm=65MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:40:32,570][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=DynamicCacheChangeBatch [id=de7bb8f1561-de578bea-fbc7-4fe6-8d49-95906395021b, reqs=[DynamicCacheChangeRequest [cacheName=SQL_PUBLIC_QMAJOR, hasCfg=true, nodeId=855d5f8d-57d0-49f0-830e-da51908019d2, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[SQL_PUBLIC_QMAJOR], stopCaches=null, startGrps=[SQL_PUBLIC_QMAJOR], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false] [16:40:32,686][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=SQL_PUBLIC_QMAJOR, id=-1412181587, memoryPolicyName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1] [16:40:32,690][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:40:32,697][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832524246, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1]]] [16:40:32,698][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:40:32,754][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], crd=false] [16:40:32,785][INFO][sys-#89][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=10, minorTopVer=1]] [16:40:32,788][INFO][sys-#89][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], err=null] [16:40:32,830][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=10, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:40:32,836][INFO][pub-#90][GridCacheDatabaseSharedManager] Finished indexes rebuilding for cache [name=SQL_PUBLIC_QMAJOR, grpName=null] [16:41:24,410][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:06:00.020] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=28.1%, avg=24.96%, GC=1.07%] ^-- PageMemory [pages=1085678] ^-- Heap [used=694MB, free=32.16%, comm=1024MB] ^-- Non heap [used=63MB, free=91.41%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=1, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] [16:41:43,675][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=14b0b9a5-620b-4da5-8e16-7294526d9e41, startPtr=FileWALPointer [idx=123, fileOff=54166553, len=21643], checkpointLockWait=0ms, checkpointLockHoldTime=97ms, walCpRecordFsyncDuration=959ms, pages=693814, reason='timeout'] [16:42:24,415][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:07:00.029] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=4.43%, avg=27.47%, GC=0%] ^-- PageMemory [pages=1294400] ^-- Heap [used=546MB, free=46.62%, comm=1024MB] ^-- Non heap [used=63MB, free=91.41%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:43:24,423][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:08:00.031] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=4.23%, avg=24.6%, GC=0%] ^-- PageMemory [pages=1324326] ^-- Heap [used=731MB, free=28.55%, comm=1024MB] ^-- Non heap [used=63MB, free=91.44%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:44:24,425][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:09:00.038] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=38.27%, avg=22.81%, GC=0.97%] ^-- PageMemory [pages=1390283] ^-- Heap [used=850MB, free=16.93%, comm=1024MB] ^-- Non heap [used=63MB, free=91.43%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:44:26,331][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=14b0b9a5-620b-4da5-8e16-7294526d9e41, pages=693814, markPos=FileWALPointer [idx=123, fileOff=54166553, len=21643], walSegmentsCleared=0, markDuration=2270ms, pagesWrite=135670ms, fsync=26986ms, total=164926ms] [16:44:41,707][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=63315d75-2838-47af-8b24-8316c1cc0152, startPtr=FileWALPointer [idx=150, fileOff=32790119, len=21643], checkpointLockWait=0ms, checkpointLockHoldTime=25ms, walCpRecordFsyncDuration=141ms, pages=268343, reason='timeout'] [16:45:12,994][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=63315d75-2838-47af-8b24-8316c1cc0152, pages=268343, markPos=FileWALPointer [idx=150, fileOff=32790119, len=21643], walSegmentsCleared=0, markDuration=297ms, pagesWrite=5199ms, fsync=26088ms, total=31585ms] [16:45:24,432][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:10:00.045] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=13.33%, avg=22.66%, GC=0.37%] ^-- PageMemory [pages=1480461] ^-- Heap [used=588MB, free=42.51%, comm=1024MB] ^-- Non heap [used=63MB, free=91.43%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:46:24,440][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:11:00.048] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=36.83%, avg=23.93%, GC=1.13%] ^-- PageMemory [pages=1718609] ^-- Heap [used=552MB, free=46.03%, comm=1024MB] ^-- Non heap [used=63MB, free=91.47%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:47:24,435][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:12:00.050] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=52.5%, avg=24.93%, GC=1.6%] ^-- PageMemory [pages=1961029] ^-- Heap [used=369MB, free=63.94%, comm=1024MB] ^-- Non heap [used=63MB, free=91.49%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:47:44,338][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=fe7fefc1-550a-4847-980e-2afbbc185e89, startPtr=FileWALPointer [idx=223, fileOff=47554540, len=21643], checkpointLockWait=1ms, checkpointLockHoldTime=32ms, walCpRecordFsyncDuration=1833ms, pages=699616, reason='timeout'] [16:48:24,436][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:13:00.050] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=59.33%, avg=26.26%, GC=1.13%] ^-- PageMemory [pages=2120598] ^-- Heap [used=448MB, free=56.23%, comm=1024MB] ^-- Non heap [used=63MB, free=91.48%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:48:46,011][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=fe7fefc1-550a-4847-980e-2afbbc185e89, pages=699616, markPos=FileWALPointer [idx=223, fileOff=47554540, len=21643], walSegmentsCleared=0, markDuration=2912ms, pagesWrite=40636ms, fsync=21037ms, total=64586ms] [16:49:24,443][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:14:00.056] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=0.27%, avg=25.34%, GC=0%] ^-- PageMemory [pages=2207591] ^-- Heap [used=884MB, free=13.57%, comm=1024MB] ^-- Non heap [used=63MB, free=91.48%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:50:24,450][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:15:00.065] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=1.33%, avg=23.76%, GC=0%] ^-- PageMemory [pages=2229194] ^-- Heap [used=572MB, free=44.09%, comm=1024MB] ^-- Non heap [used=63MB, free=91.48%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:50:42,853][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=e6af1260-5082-473a-b7c7-d90c846e5d28, startPtr=FileWALPointer [idx=256, fileOff=4285480, len=21643], checkpointLockWait=392ms, checkpointLockHoldTime=29ms, walCpRecordFsyncDuration=108ms, pages=317292, reason='timeout'] [16:51:24,460][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:16:00.074] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=0.33%, avg=23.37%, GC=0%] ^-- PageMemory [pages=2296945] ^-- Heap [used=363MB, free=64.49%, comm=1024MB] ^-- Non heap [used=63MB, free=91.49%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:52:13,369][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=e6af1260-5082-473a-b7c7-d90c846e5d28, pages=317292, markPos=FileWALPointer [idx=256, fileOff=4285480, len=21643], walSegmentsCleared=0, markDuration=1039ms, pagesWrite=49074ms, fsync=41442ms, total=91947ms] [16:52:24,473][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:17:00.087] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=0.73%, avg=22.73%, GC=0%] ^-- PageMemory [pages=2377713] ^-- Heap [used=705MB, free=31.08%, comm=1024MB] ^-- Non heap [used=63MB, free=91.48%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:53:16,106][WARNING][jvm-pause-detector-worker][] Possible too long JVM pause: 886 milliseconds. [16:53:17,343][INFO][grid-nio-worker-tcp-comm-3-#28][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:47100, rmtAddr=/127.0.0.1:60678] [16:53:17,410][WARNING][tcp-disco-msg-worker-#3][TcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=9eb5b437-977b-4a27-874d-2f554f11b3b1, id=9b5e98f1561-6aba33d0-311a-4bbb-bc09-0959a62eddd6, verifierNodeId=6aba33d0-311a-4bbb-bc09-0959a62eddd6, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=4, intOrder=4, lastExchangeTime=1533832525697, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=9eb5b437-977b-4a27-874d-2f554f11b3b1, id=9b5e98f1561-6aba33d0-311a-4bbb-bc09-0959a62eddd6, verifierNodeId=6aba33d0-311a-4bbb-bc09-0959a62eddd6, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, order=4, addr=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], daemon=false]]] [16:53:17,433][WARNING][tcp-disco-msg-worker-#3][TcpDiscoverySpi] Local node has detected failed nodes and started cluster-wide procedure. To speed up failure detection please see 'Failure Detection' section under javadoc for 'TcpDiscoverySpi' [16:53:17,546][INFO][grid-nio-worker-tcp-comm-0-#25][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:47100, rmtAddr=/127.0.0.1:60680] [16:53:17,555][WARNING][disco-event-worker-#41][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:47500, /0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500], discPort=47500, order=4, intOrder=4, lastExchangeTime=1533832525697, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false] [16:53:17,556][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=11, servers=3, clients=6, CPUs=16, offheap=90.0GB, heap=25.0GB] [16:53:17,556][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=DF202CCB-356F-426A-8131-E2CC0B9BF98F, clusterState=ACTIVE] [16:53:17,556][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=3, offline=1] [16:53:17,556][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:53:17,557][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:53:17,580][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], crd=false, evt=NODE_FAILED, evtNode=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, customEvt=null, allowMerge=true] [16:53:19,049][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], waitTime=1472ms, futInfo=NA] [16:53:19,051][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832524246, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0]]] [16:53:19,052][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], waitTime=0ms, futInfo=NA] [16:53:19,062][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], crd=false] [16:53:19,117][INFO][sys-#161][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=11, minorTopVer=0]] [16:53:19,155][INFO][sys-#161][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=11, minorTopVer=0], err=null] [16:53:19,197][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=11, minorTopVer=0], evt=NODE_FAILED, node=3e90fa61-10ae-4f29-bc07-1a5ee34870a2] [16:53:24,482][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:18:00.096] ^-- H/N/C [hosts=4, nodes=9, CPUs=16] ^-- CPU [cur=37.67%, avg=22.41%, GC=1.1%] ^-- PageMemory [pages=2488681] ^-- Heap [used=743MB, free=27.42%, comm=1024MB] ^-- Non heap [used=64MB, free=91.36%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=2, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] [16:53:39,729][WARNING][data-streamer-stripe-4-#13][PageMemoryImpl] Page replacements started, pages will be rotated with disk, this will affect storage performance (consider increasing DataRegionConfiguration#setMaxSize). [16:53:45,331][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=e5ee9e24-e543-4bf0-a115-b84cc1fa24a2, startPtr=FileWALPointer [idx=287, fileOff=4295697, len=21643], checkpointLockWait=1860ms, checkpointLockHoldTime=211ms, walCpRecordFsyncDuration=414ms, pages=319384, reason='timeout'] [16:54:00,663][WARNING][jvm-pause-detector-worker][] Possible too long JVM pause: 821 milliseconds. [16:54:03,167][WARNING][jvm-pause-detector-worker][] Possible too long JVM pause: 1448 milliseconds. [16:54:26,496][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=df202ccb, uptime=00:19:01.762] ^-- H/N/C [hosts=4, nodes=9, CPUs=16] ^-- CPU [cur=2.83%, avg=22.34%, GC=0%] ^-- PageMemory [pages=2532127] ^-- Heap [used=388MB, free=62.04%, comm=1024MB] ^-- Non heap [used=65MB, free=91.24%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=5, qSize=0] [16:54:45,250][WARNING][jvm-pause-detector-worker][] Possible too long JVM pause: 1359 milliseconds. [16:54:57,741][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=e5ee9e24-e543-4bf0-a115-b84cc1fa24a2, pages=319384, markPos=FileWALPointer [idx=287, fileOff=4295697, len=21643], walSegmentsCleared=0, markDuration=1656ms, pagesWrite=71182ms, fsync=1211ms, total=75909ms] Node 4: [16:35:23,395][INFO][main][IgniteKernal] >>> __________ ________________ >>> / _/ ___/ |/ / _/_ __/ __/ >>> _/ // (7 7 // / / / / _/ >>> /___/\___/_/|_/___/ /_/ /___/ >>> >>> ver. 2.6.0#20180710-sha1:669feacc >>> 2018 Copyright(C) Apache Software Foundation >>> >>> Ignite documentation: http://ignite.apache.org [16:35:23,404][INFO][main][IgniteKernal] Config URL: file:/data/ignitedata/apache-ignite-fabric-2.6.0-bin/config/default-config.xml [16:35:23,413][INFO][main][IgniteKernal] IgniteConfiguration [igniteInstanceName=null, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=8, mgmtPoolSize=4, igfsPoolSize=4, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=8, igniteHome=/data/ignitedata/apache-ignite-fabric-2.6.0-bin, igniteWorkDir=/data/ignitedata/apache-ignite-fabric-2.6.0-bin/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@6f94fa3e, nodeId=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, marsh=org.apache.ignite.internal.binary.BinaryMarshaller@3023df74, marshLocJobs=false, daemon=false, p2pEnabled=false, netTimeout=5000, sndRetryDelay=1000, sndRetryCnt=3, metricsHistSize=10000, metricsUpdateFreq=2000, metricsExpTime=9223372036854775807, discoSpi=TcpDiscoverySpi [addrRslvr=null, sockTimeout=0, ackTimeout=0, marsh=null, reconCnt=10, reconDelay=2000, maxAckTimeout=600000, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null], 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@6302bbb1, locAddr=null, locHost=null, locPort=47100, locPortRange=100, shmemPort=-1, directBuf=true, directSndBuf=false, idleConnTimeout=600000, connTimeout=5000, maxConnTimeout=600000, reconCnt=10, sockSndBuf=32768, sockRcvBuf=32768, msgQueueLimit=0, slowClientQueueLimit=1000, 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@31304f14[Count = 1], stopping=false, metricsLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationMetricsListener@34a3d150], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@2a4fb17b, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [lsnr=null], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@7cc0cdad, addrRslvr=null, clientMode=false, rebalanceThreadPoolSize=1, txCfg=org.apache.ignite.configuration.TransactionConfiguration@7c7b252e, 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@4d5d943d, 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=10737418240, initSize=268435456, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=true, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=true, checkpointPageBufSize=0], storagePath=/data/ignitedata/data, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, walSegments=10, walSegmentSize=67108864, walPath=/root/ignite/wal, walArchivePath=db/wal/archive, metricsEnabled=true, walMode=LOG_ONLY, walTlbSize=131072, walBuffSize=0, walFlushFreq=2000, walFsyncDelay=1000, walRecordIterBuffSize=67108864, alwaysWriteFullPages=false, fileIOFactory=org.apache.ignite.internal.processors.cache.persistence.file.AsyncFileIOFactory@4c583ecf, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false], activeOnStart=true, autoActivation=true, longQryWarnTimeout=500, 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=true, failureHnd=null, commFailureRslvr=null] [16:35:23,413][INFO][main][IgniteKernal] Daemon mode: off [16:35:23,414][INFO][main][IgniteKernal] OS: Linux 3.10.0-862.3.2.el7.x86_64 amd64 [16:35:23,414][INFO][main][IgniteKernal] OS user: root [16:35:23,414][INFO][main][IgniteKernal] PID: 19878 [16:35:23,414][INFO][main][IgniteKernal] Language runtime: Java Platform API Specification ver. 1.8 [16:35:23,415][INFO][main][IgniteKernal] VM information: Java(TM) SE Runtime Environment 1.8.0_171-b11 Oracle Corporation Java HotSpot(TM) 64-Bit Server VM 25.171-b11 [16:35:23,416][INFO][main][IgniteKernal] VM total memory: 1.0GB [16:35:23,416][INFO][main][IgniteKernal] Remote Management [restart: on, REST: on, JMX (remote: on, port: 49165, auth: off, ssl: off)] [16:35:23,416][INFO][main][IgniteKernal] Logger: JavaLogger [quiet=true, config=null] [16:35:23,416][INFO][main][IgniteKernal] IGNITE_HOME=/data/ignitedata/apache-ignite-fabric-2.6.0-bin [16:35:23,416][INFO][main][IgniteKernal] VM arguments: [-Xms1g, -Xmx1g, -XX:+AggressiveOpts, -XX:MaxMetaspaceSize=256m, -XX:+UseG1GC, -DIGNITE_QUIET=true, -DIGNITE_SUCCESS_FILE=/data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/ignite_success_6072bc65-662b-4157-8748-518151f0fdb4, -Dcom.sun.management.jmxremote, -Dcom.sun.management.jmxremote.port=49165, -Dcom.sun.management.jmxremote.authenticate=false, -Dcom.sun.management.jmxremote.ssl=false, -DIGNITE_HOME=/data/ignitedata/apache-ignite-fabric-2.6.0-bin, -DIGNITE_PROG_NAME=bin/ignite.sh] [16:35:23,416][INFO][main][IgniteKernal] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemCacheMemorySize property to change the setting. [16:35:23,424][INFO][main][IgniteKernal] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']] [16:35:23,428][INFO][main][IgniteKernal] 3-rd party licenses can be found at: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/libs/licenses [16:35:23,483][INFO][main][IgnitePluginProcessor] Configured plugins: [16:35:23,483][INFO][main][IgnitePluginProcessor] ^-- None [16:35:23,484][INFO][main][IgnitePluginProcessor] [16:35:23,485][INFO][main][FailureProcessor] Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0]] [16:35:23,532][INFO][main][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=47100, locHost=0.0.0.0/0.0.0.0, selectorsCnt=4, selectorSpins=0, pairedConn=false] [16:35:23,566][WARNING][main][TcpCommunicationSpi] Message queue limit is set to 0 which may lead to potential OOMEs when running cache operations in FULL_ASYNC or PRIMARY_SYNC modes due to message queues growth on sender and receiver sides. [16:35:23,587][WARNING][main][NoopCheckpointSpi] Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation) [16:35:23,616][WARNING][main][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival). [16:35:23,618][INFO][main][IgniteKernal] Security status [authentication=off, tls/ssl=off] [16:35:23,660][INFO][main][TcpDiscoverySpi] Successfully bound to TCP port [port=47500, localHost=0.0.0.0/0.0.0.0, locNodeId=3e90fa61-10ae-4f29-bc07-1a5ee34870a2] [16:35:23,874][INFO][main][PdsFoldersResolver] Successfully created new persistent storage folder [/data/ignitedata/data/node00-66183021-00d7-4afa-bef4-dca67652cd67] [16:35:23,876][INFO][main][PdsFoldersResolver] Consistent ID used for local node is [66183021-00d7-4afa-bef4-dca67652cd67] according to persistence data storage folders [16:35:23,881][INFO][main][CacheObjectBinaryProcessorImpl] Resolved directory for serialized binary metadata: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/binary_meta/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:24,087][INFO][main][FilePageStoreManager] Resolved page store work directory: /data/ignitedata/data/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:24,099][INFO][main][FileWriteAheadLogManager] Resolved write ahead log work directory: /root/ignite/wal/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:24,120][INFO][main][FileWriteAheadLogManager] Resolved write ahead log archive directory: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/db/wal/archive/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:24,138][INFO][main][FileWriteAheadLogManager] Started write-ahead log manager [mode=LOG_ONLY] [16:35:24,163][INFO][main][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:24,201][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:24,202][INFO][main][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=FileWALPointer [idx=0, fileOff=0, len=0], lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:24,215][INFO][main][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:24,216][INFO][main][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=0ms] [16:35:24,304][INFO][main][ClientListenerProcessor] Client connector processor has started on TCP port 10800 [16:35:24,351][INFO][main][GridTcpRestProtocol] Command protocol successfully started [name=TCP binary, host=0.0.0.0/0.0.0.0, port=11211] [16:35:24,396][INFO][main][IgniteKernal] Non-loopback local IPs: 64.101.22.97, fe80:0:0:0:f816:3eff:feb0:851%eth0 [16:35:24,397][INFO][main][IgniteKernal] Enabled local MACs: FA163EB00851 [16:35:25,712][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/64.101.22.98, rmtPort=41636] [16:35:25,724][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/64.101.22.98, rmtPort=41636] [16:35:25,724][INFO][tcp-disco-sock-reader-#5][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/64.101.22.98:41636, rmtPort=41636] [16:35:25,819][WARNING][main][IgniteKernal] 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=13412MB, available=15885MB] [16:35:25,902][INFO][main][IgniteKernal] Performance suggestions for grid (fix if possible) [16:35:25,903][INFO][main][IgniteKernal] To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true [16:35:25,903][INFO][main][IgniteKernal] ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options) [16:35:25,903][INFO][main][IgniteKernal] ^-- Disable processing of calls to System.gc() (add '-XX:+DisableExplicitGC' to JVM options) [16:35:25,904][INFO][main][IgniteKernal] ^-- Speed up flushing of dirty pages by OS (alter vm.dirty_expire_centisecs parameter by setting to 500) [16:35:25,904][INFO][main][IgniteKernal] ^-- Reduce pages swapping ratio (set vm.swappiness=10) [16:35:25,904][INFO][main][IgniteKernal] Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning [16:35:25,904][INFO][main][IgniteKernal] [16:35:25,905][INFO][main][IgniteKernal] To start Console Management & Monitoring run ignitevisorcmd.{sh|bat} [16:35:25,905][INFO][main][IgniteKernal] [16:35:25,906][INFO][main][IgniteKernal] >>> +----------------------------------------------------------------------+ >>> Ignite ver. 2.6.0#20180710-sha1:669feacc5d3a4e60efcdd300dc8de99780f38eed >>> +----------------------------------------------------------------------+ >>> OS name: Linux 3.10.0-862.3.2.el7.x86_64 amd64 >>> CPU(s): 4 >>> Heap: 1.0GB >>> VM name: 19878@ccrc_spark_analytic_3 >>> Local node [ID=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, order=4, >>> clientMode=false] >>> Local node addresses: [64.101.22.97/0:0:0:0:0:0:0:1%lo, /127.0.0.1, >>> /64.101.22.97] >>> Local ports: TCP:10800 TCP:11211 TCP:47100 UDP:47400 TCP:47500 [16:35:25,906][INFO][main][IgniteKernal] >>> Ignite cluster is not active (limited functionality available). Use control.(sh|bat) script or IgniteCluster interface to activate. [16:35:25,910][INFO][main][GridDiscoveryManager] Topology snapshot [ver=4, servers=4, clients=0, CPUs=16, offheap=40.0GB, heap=4.0GB] [16:35:25,910][INFO][main][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=INACTIVE] [16:35:25,910][INFO][main][GridDiscoveryManager] Data Regions Configured: [16:35:25,910][INFO][main][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:35:35,846][INFO][ignite-update-notifier-timer][GridUpdateNotifier] Your version is up to date. [16:35:40,665][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Received activate request with BaselineTopology[id=0] [16:35:40,668][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Started state transition: true [16:35:40,688][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=9eb5b437-977b-4a27-874d-2f554f11b3b1, customEvt=ChangeGlobalStateMessage [id=a48da8f1561-17023b74-7b2a-4808-acff-c836ff2bfc3b, reqId=393b2bd6-1a39-41a3-b889-6bcb348c0b7f, initiatingNodeId=9eb5b437-977b-4a27-874d-2f554f11b3b1, activate=true, baselineTopology=BaselineTopology [id=0, branchingHash=-3794941467, branchingType='New BaselineTopology', baselineNodes=[ed7c9512-9c83-4c0f-a13c-0ee2016f31a3, 5ddaed11-e882-450d-bc91-f14704edfffc, 66183021-00d7-4afa-bef4-dca67652cd67, 84153e73-2d96-49b3-b593-bef18c8218f9]], forceChangeBaselineTopology=false, timestamp=1533832540592], allowMerge=false] [16:35:40,689][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Start activation process [nodeId=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:40,689][INFO][exchange-worker-#43][FilePageStoreManager] Resolved page store work directory: /data/ignitedata/data/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:40,689][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resolved write ahead log work directory: /root/ignite/wal/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:40,690][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resolved write ahead log archive directory: /data/ignitedata/apache-ignite-fabric-2.6.0-bin/work/db/wal/archive/node00-66183021-00d7-4afa-bef4-dca67652cd67 [16:35:40,690][INFO][exchange-worker-#43][FileWriteAheadLogManager] Started write-ahead log manager [mode=LOG_ONLY] [16:35:40,702][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:40,758][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=10.0 GiB, pages=2541052, tableSize=197.7 MiB, checkpointBuffer=2.0 GiB] [16:35:40,761][INFO][exchange-worker-#43][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24812, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB] [16:35:40,782][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:40,783][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=FileWALPointer [idx=0, fileOff=0, len=0], lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:40,784][INFO][exchange-worker-#43][FileWriteAheadLogManager] Resuming logging to WAL segment [file=/root/ignite/wal/node00-66183021-00d7-4afa-bef4-dca67652cd67/0000000000000000.wal, offset=0, ver=2] [16:35:40,825][INFO][exchange-worker-#43][GridClusterStateProcessor] Writing BaselineTopology[id=0] [16:35:41,123][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647] [16:35:41,129][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Successfully activated caches [nodeId=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:41,143][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:35:41,171][INFO][grid-nio-worker-tcp-comm-0-#25][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/64.101.22.97:53872, rmtAddr=/64.101.22.95:47100] [16:35:41,323][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832525728, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]]] [16:35:41,324][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:35:41,324][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Read checkpoint status [startMarker=null, endMarker=null] [16:35:41,324][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=FileWALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000] [16:35:41,405][INFO][exchange-worker-#43][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=81ms] [16:35:41,440][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], crd=false] [16:35:41,462][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=d00e7fdc-dffb-4d11-9bd5-55592dd328af, startPtr=FileWALPointer [idx=0, fileOff=261363, len=47], checkpointLockWait=0ms, checkpointLockHoldTime=3ms, walCpRecordFsyncDuration=37ms, pages=27, reason='node started'] [16:35:41,508][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=d00e7fdc-dffb-4d11-9bd5-55592dd328af, pages=27, markPos=FileWALPointer [idx=0, fileOff=261363, len=47], walSegmentsCleared=0, markDuration=56ms, pagesWrite=8ms, fsync=36ms, total=100ms] [16:35:41,653][INFO][tcp-disco-msg-worker-#3][GridClusterStateProcessor] Received state change finish message: true [16:35:41,659][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:35:41,662][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=4, minorTopVer=1], err=null] [16:35:41,687][INFO][grid-nio-worker-tcp-comm-1-#26][TcpCommunicationSpi] Established outgoing communication connection [locAddr=/64.101.22.97:39700, rmtAddr=ccrc_spark_analytic_2.cisco.com/64.101.22.96:47100] [16:35:41,695][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=4, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=9eb5b437-977b-4a27-874d-2f554f11b3b1] [16:35:41,706][INFO][sys-#53][GridClusterStateProcessor] Successfully performed final activation steps [nodeId=3e90fa61-10ae-4f29-bc07-1a5ee34870a2, client=false, topVer=AffinityTopologyVersion [topVer=4, minorTopVer=1]] [16:36:16,673][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=855d5f8d-57d0-49f0-830e-da51908019d2, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.98], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.98:0], discPort=0, order=5, intOrder=5, lastExchangeTime=1533832576646, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:16,675][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=5, servers=4, clients=1, CPUs=16, offheap=50.0GB, heap=8.4GB] [16:36:16,675][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:16,676][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:16,676][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:16,676][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:16,678][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=null, allowMerge=true] [16:36:16,679][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], err=null] [16:36:16,679][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=0], crd=false] [16:36:16,681][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=5, minorTopVer=0], evt=NODE_JOINED, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:36:17,457][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=DynamicCacheChangeBatch [id=612bb8f1561-de578bea-fbc7-4fe6-8d49-95906395021b, reqs=[DynamicCacheChangeRequest [cacheName=SQL_PUBLIC_QHDR, hasCfg=true, nodeId=855d5f8d-57d0-49f0-830e-da51908019d2, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[SQL_PUBLIC_QHDR], stopCaches=null, startGrps=[SQL_PUBLIC_QHDR], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false] [16:36:17,595][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=SQL_PUBLIC_QHDR, id=-2066276374, memoryPolicyName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1] [16:36:17,605][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:36:17,626][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832525728, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1]]] [16:36:17,626][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:36:17,686][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], crd=false] [16:36:17,727][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=5, minorTopVer=1]] [16:36:17,733][INFO][sys-#51][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=5, minorTopVer=1], err=null] [16:36:17,738][INFO][pub-#59][GridCacheDatabaseSharedManager] Finished indexes rebuilding for cache [name=SQL_PUBLIC_QHDR, grpName=null] [16:36:17,741][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=5, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:36:25,909][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:01:00.006] ^-- H/N/C [hosts=4, nodes=5, CPUs=16] ^-- CPU [cur=0.5%, avg=1.44%, GC=0%] ^-- PageMemory [pages=37] ^-- Heap [used=60MB, free=94.14%, comm=1024MB] ^-- Non heap [used=50MB, free=93.15%, comm=51MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=1, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] [16:36:32,315][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=6036816f-cbb9-43b3-94ff-ec55f233155d, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.96], sockAddrs=[ccrc_spark_analytic_2.cisco.com/64.101.22.96:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=6, intOrder=6, lastExchangeTime=1533832592274, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,317][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=6, servers=4, clients=2, CPUs=16, offheap=60.0GB, heap=12.0GB] [16:36:32,317][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:32,317][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,317][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,317][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,318][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=6036816f-cbb9-43b3-94ff-ec55f233155d, customEvt=null, allowMerge=true] [16:36:32,318][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], err=null] [16:36:32,319][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=6, minorTopVer=0], crd=false] [16:36:32,322][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=6, minorTopVer=0], evt=NODE_JOINED, node=6036816f-cbb9-43b3-94ff-ec55f233155d] [16:36:32,335][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery accepted incoming connection [rmtAddr=/64.101.22.95, rmtPort=39396] [16:36:32,335][INFO][tcp-disco-srvr-#2][TcpDiscoverySpi] TCP discovery spawning a new thread for connection [rmtAddr=/64.101.22.95, rmtPort=39396] [16:36:32,343][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=4cd15597-95eb-4870-b683-e23f4bea674b, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.98], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.98:0], discPort=0, order=7, intOrder=7, lastExchangeTime=1533832592291, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,344][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=7, servers=4, clients=3, CPUs=16, offheap=70.0GB, heap=16.0GB] [16:36:32,345][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:32,345][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,345][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,345][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,346][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=4cd15597-95eb-4870-b683-e23f4bea674b, customEvt=null, allowMerge=true] [16:36:32,356][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], err=null] [16:36:32,357][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=7, minorTopVer=0], crd=false] [16:36:32,360][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=7, minorTopVer=0], evt=NODE_JOINED, node=4cd15597-95eb-4870-b683-e23f4bea674b] [16:36:32,362][INFO][tcp-disco-sock-reader-#7][TcpDiscoverySpi] Started serving remote node connection [rmtAddr=/64.101.22.95:39396, rmtPort=39396] [16:36:32,515][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0, /64.101.22.95:0], discPort=0, order=8, intOrder=8, lastExchangeTime=1533832592447, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:32,516][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=8, servers=4, clients=4, CPUs=16, offheap=80.0GB, heap=19.0GB] [16:36:32,516][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:32,516][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:32,517][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:32,517][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:32,517][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58, customEvt=null, allowMerge=true] [16:36:32,518][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], err=null] [16:36:32,518][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=8, minorTopVer=0], crd=false] [16:36:32,521][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=8, minorTopVer=0], evt=NODE_JOINED, node=2ba16c0b-e88d-4fb1-b0ff-f3ac43dc8b58] [16:36:33,312][INFO][grid-nio-worker-tcp-comm-2-#27][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.97:47100, rmtAddr=/64.101.22.95:36338] [16:36:36,095][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=e55be418-9131-4abd-8f9c-d3616a0cb508, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=9, intOrder=9, lastExchangeTime=1533832595997, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:36,096][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=9, servers=4, clients=5, CPUs=16, offheap=90.0GB, heap=23.0GB] [16:36:36,096][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:36,096][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:36,096][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:36,096][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:36,097][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=e55be418-9131-4abd-8f9c-d3616a0cb508, customEvt=null, allowMerge=true] [16:36:36,097][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], err=null] [16:36:36,097][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=9, minorTopVer=0], crd=false] [16:36:36,100][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=9, minorTopVer=0], evt=NODE_JOINED, node=e55be418-9131-4abd-8f9c-d3616a0cb508] [16:36:36,120][INFO][disco-event-worker-#41][GridDiscoveryManager] Added new node to topology: TcpDiscoveryNode [id=e780e47b-9117-4382-8b4d-d4de92c69b46, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.97], sockAddrs=[/64.101.22.97:0, /0:0:0:0:0:0:0:1%lo:0, /127.0.0.1:0], discPort=0, order=10, intOrder=10, lastExchangeTime=1533832596044, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=true] [16:36:36,122][INFO][disco-event-worker-#41][GridDiscoveryManager] Topology snapshot [ver=10, servers=4, clients=6, CPUs=16, offheap=100.0GB, heap=26.0GB] [16:36:36,122][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Node [id=3E90FA61-10AE-4F29-BC07-1A5EE34870A2, clusterState=ACTIVE] [16:36:36,122][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- Baseline [id=0, size=4, online=4, offline=0] [16:36:36,122][INFO][disco-event-worker-#41][GridDiscoveryManager] Data Regions Configured: [16:36:36,122][INFO][disco-event-worker-#41][GridDiscoveryManager] ^-- default [initSize=256.0 MiB, maxSize=10.0 GiB, persistenceEnabled=true] [16:36:36,123][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=e780e47b-9117-4382-8b4d-d4de92c69b46, customEvt=null, allowMerge=true] [16:36:36,124][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], err=null] [16:36:36,124][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=0], crd=false] [16:36:36,127][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=10, minorTopVer=0], evt=NODE_JOINED, node=e780e47b-9117-4382-8b4d-d4de92c69b46] [16:36:37,144][INFO][grid-nio-worker-tcp-comm-3-#28][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.97:47100, rmtAddr=/64.101.22.96:47328] [16:36:37,965][INFO][grid-nio-worker-tcp-comm-0-#25][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/64.101.22.97:47100, rmtAddr=/64.101.22.98:41826] [16:36:47,125][INFO][grid-nio-worker-tcp-comm-1-#26][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:47100, rmtAddr=/127.0.0.1:50908] [16:36:49,915][INFO][grid-nio-worker-tcp-comm-2-#27][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/127.0.0.1:47100, rmtAddr=/127.0.0.1:50910] [16:37:25,911][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:02:00.014] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=25.5%, avg=11.21%, GC=0.6%] ^-- PageMemory [pages=240343] ^-- Heap [used=325MB, free=68.26%, comm=1024MB] ^-- Non heap [used=61MB, free=91.74%, comm=62MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:38:25,920][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:03:00.022] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=13.4%, avg=16.22%, GC=0%] ^-- PageMemory [pages=483399] ^-- Heap [used=507MB, free=50.47%, comm=1024MB] ^-- Non heap [used=60MB, free=91.85%, comm=63MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:38:43,496][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=a4e541e7-5fc7-4b7d-945f-56e75917278e, startPtr=FileWALPointer [idx=51, fileOff=62100019, len=11282], checkpointLockWait=0ms, checkpointLockHoldTime=76ms, walCpRecordFsyncDuration=290ms, pages=536455, reason='timeout'] [16:39:11,926][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=a4e541e7-5fc7-4b7d-945f-56e75917278e, pages=536455, markPos=FileWALPointer [idx=51, fileOff=62100019, len=11282], walSegmentsCleared=0, markDuration=2090ms, pagesWrite=22345ms, fsync=6084ms, total=30519ms] [16:39:25,924][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:04:00.022] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=19.67%, avg=21.51%, GC=0.6%] ^-- PageMemory [pages=659362] ^-- Heap [used=580MB, free=43.36%, comm=1024MB] ^-- Non heap [used=63MB, free=91.51%, comm=64MB] ^-- Outbound messages queue [size=1] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:40:25,924][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:05:00.028] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=21.07%, avg=21.58%, GC=0.33%] ^-- PageMemory [pages=846121] ^-- Heap [used=627MB, free=38.72%, comm=1024MB] ^-- Non heap [used=61MB, free=91.68%, comm=64MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:40:32,565][INFO][exchange-worker-#43][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], crd=false, evt=DISCOVERY_CUSTOM_EVT, evtNode=855d5f8d-57d0-49f0-830e-da51908019d2, customEvt=DynamicCacheChangeBatch [id=de7bb8f1561-de578bea-fbc7-4fe6-8d49-95906395021b, reqs=[DynamicCacheChangeRequest [cacheName=SQL_PUBLIC_QMAJOR, hasCfg=true, nodeId=855d5f8d-57d0-49f0-830e-da51908019d2, clientStartOnly=false, stop=false, destroy=false, disabledAfterStartfalse]], exchangeActions=ExchangeActions [startCaches=[SQL_PUBLIC_QMAJOR], stopCaches=null, startGrps=[SQL_PUBLIC_QMAJOR], stopGrps=[], resetParts=null, stateChangeRequest=null], startCaches=false], allowMerge=false] [16:40:32,638][INFO][exchange-worker-#43][GridCacheProcessor] Started cache [name=SQL_PUBLIC_QMAJOR, id=-1412181587, memoryPolicyName=default, mode=PARTITIONED, atomicity=ATOMIC, backups=1] [16:40:32,644][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:40:32,693][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ClientLatch [coordinator=TcpDiscoveryNode [id=6aba33d0-311a-4bbb-bc09-0959a62eddd6, addrs=[0:0:0:0:0:0:0:1%lo, 127.0.0.1, 64.101.22.95], sockAddrs=[/0:0:0:0:0:0:0:1%lo:47500, /127.0.0.1:47500, /64.101.22.95:47500], discPort=47500, order=1, intOrder=1, lastExchangeTime=1533832525728, loc=false, ver=2.6.0#20180710-sha1:669feacc, isClient=false], ackSent=true, super=CompletableLatch [id=exchange, topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1]]] [16:40:32,694][INFO][exchange-worker-#43][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], waitTime=0ms, futInfo=NA] [16:40:32,749][INFO][exchange-worker-#43][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], crd=false] [16:40:32,785][INFO][sys-#84][GridDhtPartitionsExchangeFuture] Received full message, will finish exchange [node=6aba33d0-311a-4bbb-bc09-0959a62eddd6, resVer=AffinityTopologyVersion [topVer=10, minorTopVer=1]] [16:40:32,789][INFO][sys-#84][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], resVer=AffinityTopologyVersion [topVer=10, minorTopVer=1], err=null] [16:40:32,799][INFO][exchange-worker-#43][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=10, minorTopVer=1], evt=DISCOVERY_CUSTOM_EVT, node=855d5f8d-57d0-49f0-830e-da51908019d2] [16:40:32,800][INFO][pub-#85][GridCacheDatabaseSharedManager] Finished indexes rebuilding for cache [name=SQL_PUBLIC_QMAJOR, grpName=null] [16:41:25,933][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:06:00.037] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=23.43%, avg=22.47%, GC=0.7%] ^-- PageMemory [pages=1045037] ^-- Heap [used=599MB, free=41.5%, comm=1024MB] ^-- Non heap [used=63MB, free=91.41%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=1, qSize=0] ^-- System thread pool [active=0, idle=8, qSize=0] [16:41:42,871][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=49a7ce4f-ea12-40d9-9311-4bf97bded048, startPtr=FileWALPointer [idx=118, fileOff=9710039, len=20617], checkpointLockWait=0ms, checkpointLockHoldTime=52ms, walCpRecordFsyncDuration=198ms, pages=661927, reason='timeout'] [16:42:25,940][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:07:00.042] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=15.67%, avg=24.3%, GC=0.17%] ^-- PageMemory [pages=1221710] ^-- Heap [used=387MB, free=62.19%, comm=1024MB] ^-- Non heap [used=63MB, free=91.49%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:43:25,947][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:08:00.049] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=4.5%, avg=21.68%, GC=0%] ^-- PageMemory [pages=1225810] ^-- Heap [used=636MB, free=37.85%, comm=1024MB] ^-- Non heap [used=63MB, free=91.46%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:44:23,844][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=49a7ce4f-ea12-40d9-9311-4bf97bded048, pages=661927, markPos=FileWALPointer [idx=118, fileOff=9710039, len=20617], walSegmentsCleared=0, markDuration=1456ms, pagesWrite=139159ms, fsync=21813ms, total=162428ms] [16:44:25,956][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:09:00.055] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=6.4%, avg=20.37%, GC=0.2%] ^-- PageMemory [pages=1266931] ^-- Heap [used=426MB, free=58.33%, comm=1024MB] ^-- Non heap [used=63MB, free=91.45%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:44:41,874][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=17ee184e-e37f-4b1e-b1a6-950597585b86, startPtr=FileWALPointer [idx=138, fileOff=11618977, len=20617], checkpointLockWait=0ms, checkpointLockHoldTime=23ms, walCpRecordFsyncDuration=189ms, pages=208080, reason='timeout'] [16:45:07,153][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=17ee184e-e37f-4b1e-b1a6-950597585b86, pages=208080, markPos=FileWALPointer [idx=138, fileOff=11618977, len=20617], walSegmentsCleared=0, markDuration=456ms, pagesWrite=4310ms, fsync=20968ms, total=25734ms] [16:45:25,990][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:10:00.092] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=34.4%, avg=21.33%, GC=0.83%] ^-- PageMemory [pages=1422412] ^-- Heap [used=377MB, free=63.09%, comm=1024MB] ^-- Non heap [used=63MB, free=91.48%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:46:25,998][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:11:00.098] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=38.17%, avg=22.63%, GC=2.47%] ^-- PageMemory [pages=1661176] ^-- Heap [used=637MB, free=37.74%, comm=1024MB] ^-- Non heap [used=63MB, free=91.51%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:47:26,002][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:12:00.105] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=28.4%, avg=23.82%, GC=1.5%] ^-- PageMemory [pages=1895385] ^-- Heap [used=288MB, free=71.85%, comm=1024MB] ^-- Non heap [used=62MB, free=91.56%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:47:42,690][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=f4dbe4f2-8510-4428-b8d9-40dd2fbf9bea, startPtr=FileWALPointer [idx=212, fileOff=52611399, len=20617], checkpointLockWait=1ms, checkpointLockHoldTime=28ms, walCpRecordFsyncDuration=338ms, pages=725316, reason='timeout'] [16:48:26,010][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:13:00.106] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=64.9%, avg=24.71%, GC=1%] ^-- PageMemory [pages=2045788] ^-- Heap [used=589MB, free=42.4%, comm=1024MB] ^-- Non heap [used=63MB, free=91.53%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:48:44,775][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=f4dbe4f2-8510-4428-b8d9-40dd2fbf9bea, pages=725316, markPos=FileWALPointer [idx=212, fileOff=52611399, len=20617], walSegmentsCleared=0, markDuration=1273ms, pagesWrite=57165ms, fsync=4920ms, total=63359ms] [16:49:26,003][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:14:00.106] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=0.17%, avg=24.09%, GC=0%] ^-- PageMemory [pages=2113002] ^-- Heap [used=835MB, free=18.45%, comm=1024MB] ^-- Non heap [used=63MB, free=91.52%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:50:26,012][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:15:00.115] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=44%, avg=22.73%, GC=1.7%] ^-- PageMemory [pages=2164851] ^-- Heap [used=729MB, free=28.74%, comm=1024MB] ^-- Non heap [used=63MB, free=91.52%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:50:41,879][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint started [checkpointId=da3d20a5-c2ce-4bfb-b446-3d7b9cbdf7fa, startPtr=FileWALPointer [idx=243, fileOff=54767645, len=20617], checkpointLockWait=0ms, checkpointLockHoldTime=26ms, walCpRecordFsyncDuration=256ms, pages=309780, reason='timeout'] [16:51:26,017][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:16:00.119] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=0.57%, avg=22.42%, GC=0%] ^-- PageMemory [pages=2220223] ^-- Heap [used=415MB, free=59.44%, comm=1024MB] ^-- Non heap [used=63MB, free=91.51%, comm=66MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] [16:51:47,120][INFO][db-checkpoint-thread-#46][GridCacheDatabaseSharedManager] Checkpoint finished [cpId=da3d20a5-c2ce-4bfb-b446-3d7b9cbdf7fa, pages=309780, markPos=FileWALPointer [idx=243, fileOff=54767645, len=20617], walSegmentsCleared=0, markDuration=454ms, pagesWrite=47535ms, fsync=17706ms, total=65695ms] [16:52:26,024][INFO][grid-timeout-worker-#23][IgniteKernal] Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=3e90fa61, uptime=00:17:00.122] ^-- H/N/C [hosts=4, nodes=10, CPUs=16] ^-- CPU [cur=6.83%, avg=22.13%, GC=0.4%] ^-- PageMemory [pages=2342159] ^-- Heap [used=790MB, free=22.77%, comm=1024MB] ^-- Non heap [used=63MB, free=91.51%, comm=67MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=6, qSize=0] Thanks -- Sent from: http://apache-ignite-users.70518.x6.nabble.com/
