Hi team,
There is a cluster with 2 server nodes and 1 client node.
It can be seen from the attached log that the two server nodes are
disconnected from about 20:18:15.
However, it is strange that the node with IP 10.97.32.53 did not shut
down due to split brain. Instead, it is split into two clusters with
only one server node.
We know that the default SegmentationPolicy value is STOP, so here comes
the question:
1.There is no split brain in the behavior of this cluster, is there a
bug here?
2.The default SegmentationPolicy does not take effect for a cluster with
two nodes. An ignite cluster must have at least three nodes before the
policy is effective?
[14:00:48,909][INFO][main][IgniteKernal]
>>> __________ ________________
>>> / _/ ___/ |/ / _/_ __/ __/
>>> _/ // (7 7 // / / / / _/
>>> /___/\___/_/|_/___/ /_/ /___/
>>>
>>> ver. 2.10.0#20210310-sha1:bc24f6ba
>>> 2021 Copyright(C) Apache Software Foundation
>>>
>>> Ignite documentation: http://ignite.apache.org
[14:00:48,910][INFO][main][IgniteKernal] Config URL: file:/data/ignite/apache-ignite-2.10.0-bin/config/ignite-config-cluster-1.xml
[14:00:48,946][INFO][main][IgniteKernal] IgniteConfiguration [igniteInstanceName=null, pubPoolSize=32, svcPoolSize=32, callbackPoolSize=32, stripedPoolSize=32, sysPoolSize=32, mgmtPoolSize=4, dataStreamerPoolSize=32, utilityCachePoolSize=32, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=32, buildIdxPoolSize=4, igniteHome=/data/ignite/apache-ignite-2.10.0-bin, igniteWorkDir=/data/ignite/apache-ignite-2.10.0-bin/node1/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@564718df, nodeId=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, marsh=BinaryMarshaller [], marshLocJobs=false, daemon=false, p2pEnabled=false, netTimeout=5000, netCompressionLevel=1, 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, soLinger=0, forceSrvMode=false, clientReconnectDisabled=false, internalLsnr=null, skipAddrsRandomization=false], segPlc=STOP, segResolveAttempts=2, waitForSegOnStart=true, allResolversPassReq=true, segChkFreq=10000, commSpi=TcpCommunicationSpi [connectGate=org.apache.ignite.spi.communication.tcp.internal.ConnectGateway@186f8716, ctxInitLatch=java.util.concurrent.CountDownLatch@1d8bd0de[Count = 1], stopping=false, clientPool=null, nioSrvWrapper=null, stateProvider=null], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@45ca843, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@3cc1435c, addrRslvr=null, encryptionSpi=org.apache.ignite.spi.encryption.noop.NoopEncryptionSpi@6bf0219d, tracingSpi=org.apache.ignite.spi.tracing.NoopTracingSpi@dd0c991, clientMode=false, rebalanceThreadPoolSize=4, rebalanceTimeout=10000, rebalanceBatchesPrefetchCnt=3, rebalanceThrottle=0, rebalanceBatchSize=524288, txCfg=TransactionConfiguration [txSerEnabled=false, dfltIsolation=REPEATABLE_READ, dfltConcurrency=PESSIMISTIC, dfltTxTimeout=0, txTimeoutOnPartitionMapExchange=0, deadlockTimeout=10000, pessimisticTxLogSize=0, pessimisticTxLogLinger=10000, tmLookupClsName=null, txManagerFactory=null, useJtaSync=false], cacheSanityCheckEnabled=true, discoStartupDelay=60000, deployMode=SHARED, p2pMissedCacheSize=100, locHost=null, timeSrvPortBase=31100, timeSrvPortRange=100, failureDetectionTimeout=10000, sysWorkerBlockedTimeout=null, clientFailureDetectionTimeout=30000, metricsLogFreq=60000, connectorCfg=ConnectorConfiguration [jettyPath=null, host=null, port=11211, noDelay=true, directBuf=false, sndBufSize=32768, rcvBufSize=32768, idleQryCurTimeout=600000, idleQryCurCheckFreq=60000, sndQueueLimit=0, selectorCnt=4, idleTimeout=7000, sslEnabled=false, sslClientAuth=false, sslCtxFactory=null, sslFactory=null, portRange=100, threadPoolSize=32, msgInterceptor=null], 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, sysRegionMaxSize=104857600, pageSize=0, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=Default_Region, maxSize=214748364800, initSize=1073741824, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=true, checkpointPageBufSize=0, lazyMemoryAllocation=true, warmUpCfg=null], dataRegions=null, storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, maxWalArchiveSize=1073741824, walSegments=10, walSegmentSize=1073741824, walPath=db/wal, walArchivePath=db/wal/archive, metricsEnabled=false, 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@7e9131d5, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false, walCompactionLevel=1, checkpointReadLockTimeout=null, walPageCompression=DISABLED, walPageCompressionLevel=null, dfltWarmUpCfg=null, encCfg=org.apache.ignite.configuration.EncryptionConfiguration@61d6015a, defragmentationThreadPoolSize=4], snapshotPath=snapshots, activeOnStart=true, activeOnStartPropSetFlag=false, autoActivation=true, autoActivationPropSetFlag=false, clusterStateOnStart=null, sqlConnCfg=null, cliConnCfg=ClientConnectorConfiguration [host=null, port=10800, portRange=100, sockSndBufSize=0, sockRcvBufSize=0, tcpNoDelay=true, maxOpenCursorsPerConn=128, threadPoolSize=32, selectorCnt=16, idleTimeout=0, handshakeTimeout=10000, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null, thinCliCfg=ThinClientConfiguration [maxActiveTxPerConn=100, maxActiveComputeTasksPerConn=0]], mvccVacuumThreadCnt=2, mvccVacuumFreq=5000, authEnabled=false, failureHnd=null, commFailureRslvr=null, sqlCfg=SqlConfiguration [longQryWarnTimeout=3000, dfltQryTimeout=0, sqlQryHistSize=1000, validationEnabled=false]]
[14:00:48,947][INFO][main][IgniteKernal] Daemon mode: off
[14:00:48,947][INFO][main][IgniteKernal] OS: Linux 3.10.0-1062.18.1.el7.x86_64 amd64
[14:00:48,947][INFO][main][IgniteKernal] OS user: root
[14:00:48,949][INFO][main][IgniteKernal] PID: 56432
[14:00:48,950][INFO][main][IgniteKernal] Language runtime: Java Platform API Specification ver. 1.8
[14:00:48,950][INFO][main][IgniteKernal] VM information: OpenJDK Runtime Environment 1.8.0_222-b10 Oracle Corporation OpenJDK 64-Bit Server VM 25.222-b10
[14:00:48,952][INFO][main][IgniteKernal] VM total memory: 30.0GB
[14:00:48,952][INFO][main][IgniteKernal] Remote Management [restart: on, REST: on, JMX (remote: off)]
[14:00:48,953][INFO][main][IgniteKernal] Logger: JavaLogger [quiet=false, config=null]
[14:00:48,953][INFO][main][IgniteKernal] IGNITE_HOME=/data/ignite/apache-ignite-2.10.0-bin
[14:00:48,954][INFO][main][IgniteKernal] VM arguments: [-XX:+AggressiveOpts, -Dfile.encoding=UTF-8, -DIGNITE_QUIET=false, -DIGNITE_SUCCESS_FILE=/data/ignite/apache-ignite-2.10.0-bin/work/ignite_success_5e39da02-f67b-4703-ae2f-8c6e0bcaf57f, -DIGNITE_HOME=/data/ignite/apache-ignite-2.10.0-bin, -DIGNITE_PROG_NAME=/data/ignite/apache-ignite-2.10.0-bin/bin/ignite.sh, -Djava.net.preferIPv4Stack=true, -XX:+UseG1GC, -XX:+AlwaysPreTouch, -XX:+ScavengeBeforeFullGC, -XX:+DisableExplicitGC, -XX:MaxDirectMemorySize=4096m, -XX:MaxGCPauseMillis=10000, -Xmx30480m, -DIGNITE_JVM_PAUSE_DETECTOR_THRESHOLD=60000]
[14:00:48,954][INFO][main][IgniteKernal] System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemRegionInitialSize property to change the setting.
[14:00:48,955][INFO][main][IgniteKernal] Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']]
[14:00:48,959][INFO][main][IgniteKernal] 3-rd party licenses can be found at: /data/ignite/apache-ignite-2.10.0-bin/libs/licenses
[14:00:49,162][INFO][main][IgnitePluginProcessor] Configured plugins:
[14:00:49,163][INFO][main][IgnitePluginProcessor] ^-- None
[14:00:49,163][INFO][main][IgnitePluginProcessor]
[14:00:49,170][INFO][main][FailureProcessor] Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0, super=AbstractFailureHandler [ignoredFailureTypes=UnmodifiableSet [SYSTEM_WORKER_BLOCKED, SYSTEM_CRITICAL_OPERATION_TIMEOUT]]]]
[14:00:49,549][INFO][main][TcpCommunicationSpi] Successfully bound communication NIO server to TCP port [port=49000, locHost=0.0.0.0/0.0.0.0, selectorsCnt=16, selectorSpins=0, pairedConn=false]
[14:00:49,549][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.
[14:00:49,570][WARNING][main][NoopCheckpointSpi] Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation)
[14:00:49,613][WARNING][main][GridCollisionManager] Collision resolution is disabled (all jobs will be activated upon arrival).
[14:00:49,615][INFO][main][IgniteKernal] Security status [authentication=off, sandbox=off, tls/ssl=off]
[14:00:49,681][INFO][main][MaintenanceProcessor] Resolved store directory for node persistent data: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/Node1
[14:00:49,721][INFO][main][CacheObjectBinaryProcessorImpl] Resolved directory for serialized binary metadata: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/binary_meta/Node1
[14:00:50,010][INFO][main][FilePageStoreManager] Resolved page store work directory: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/Node1
[14:00:50,011][INFO][main][FileWriteAheadLogManager] Resolved write ahead log work directory: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/wal/Node1
[14:00:50,011][INFO][main][FileWriteAheadLogManager] Resolved write ahead log archive directory: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/wal/archive/Node1
[14:00:55,186][INFO][main][FileWriteAheadLogManager] Reached logical end of the segment for file /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/wal/Node1/0000000000000000.wal
[14:00:55,191][INFO][main][FileHandleManagerImpl] Initialized write-ahead log manager [mode=LOG_ONLY]
[14:00:55,203][WARNING][main][GridCacheDatabaseSharedManager] DataRegionConfiguration.maxWalArchiveSize instead DataRegionConfiguration.walHistorySize would be used for removing old archive wal files
[14:00:55,247][INFO][main][GridCacheDatabaseSharedManager] Configured data regions initialized successfully [total=5]
[14:00:55,280][INFO][main][IgniteSnapshotManager] Resolved snapshot work directory: /data/ignite/apache-ignite-2.10.0-bin/node1/work/snapshots
[14:00:55,280][INFO][main][IgniteSnapshotManager] Resolved temp directory for snapshot creation: /data/ignite/apache-ignite-2.10.0-bin/node1/work/db/Node1/snp
[14:00:55,351][WARNING][main][IgniteH2Indexing] Serialization of Java objects in H2 was enabled.
[14:00:55,664][INFO][main][ClientListenerProcessor] Client connector processor has started on TCP port 10800
[14:00:55,750][INFO][main][GridTcpRestProtocol] Command protocol successfully started [name=TCP binary, host=0.0.0.0/0.0.0.0, port=11211]
[14:00:56,100][INFO][main][GridJettyRestProtocol] Command protocol successfully started [name=Jetty REST, host=/0.0.0.0, port=8080]
[14:00:56,201][INFO][main][IgniteKernal] Non-loopback local IPs: 10.97.32.53
[14:00:56,201][INFO][main][IgniteKernal] Enabled local MACs: 005056B106A3
[14:00:56,211][INFO][main][CheckpointMarkersStorage] Read checkpoint status [startMarker=null, endMarker=null]
[14:00:56,222][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24800, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB]
[14:00:56,226][INFO][main][GridCacheDatabaseSharedManager] Checking memory state [lastValidPos=WALPointer [idx=0, fileOff=0, len=0], lastMarked=WALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000]
[14:00:56,285][INFO][main][GridCacheDatabaseSharedManager] Applying lost cache updates since last checkpoint record [lastMarked=WALPointer [idx=0, fileOff=0, len=0], lastCheckpointId=00000000-0000-0000-0000-000000000000]
[14:00:56,301][INFO][main][GridCacheDatabaseSharedManager] Finished applying WAL changes [updatesApplied=0, time=14 ms]
[14:00:56,302][INFO][main][GridCacheProcessor] Restoring partition state for local groups.
[14:00:56,302][INFO][main][GridCacheProcessor] Finished restoring partition state for local groups [groupsProcessed=0, partitionsProcessed=0, time=0ms]
[14:00:56,307][INFO][main][GridEncryptionManager] Encryption keys loaded from metastore. [grps=, masterKeyName=null]
[14:00:56,346][INFO][main][ClusterProcessor] Cluster ID and tag has been read from metastorage: null
[14:00:56,355][INFO][main][IgniteClusterImpl] Shutdown policy was updated [oldVal=null, newVal=null]
[14:00:56,367][INFO][main][FilePageStoreManager] Cleanup cache stores [total=1, left=0, cleanFiles=false]
[14:00:56,397][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24800, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB]
[14:00:56,399][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24800, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB]
[14:00:56,403][INFO][main][PageMemoryImpl] Started page memory [memoryAllocated=100.0 MiB, pages=24800, tableSize=1.9 MiB, checkpointBuffer=100.0 MiB]
[14:00:56,419][INFO][main][GridCacheDatabaseSharedManager] Data Regions Started: 5
..............
[20:17:53,384][WARNING][long-qry-#92][LongRunningQueryManager] Query execution is too long [duration=24315ms, type=MAP, distributedJoin=false, enforceJoinOrder=false, lazy=false, schema=PUBLIC, sql='SELECT
__Z0.TRADEDATE __C0_0,
__Z0.SYMBOL __C0_1,
__Z0.VALUE __C0_2,
__Z0.HOLDING __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0', plan=SELECT
__Z0.TRADEDATE AS __C0_0,
__Z0.SYMBOL AS __C0_1,
__Z0.VALUE AS __C0_2,
__Z0.HOLDING AS __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0
/* ASE_BONDATTR.BONDATTR.__SCAN_ */
/* scanCount: 5942284 */, node=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629893872907, loc=true, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], reqId=3, segment=0]
[20:18:15,747][WARNING][tcp-disco-msg-worker-[accfe8fb 10.97.32.54:49500]-#2-#121][TcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, id=9098ce77b71-accfe8fb-a5e3-41f2-82da-cfc1debff104, verifierNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=accfe8fb-a5e3-41f2-82da-cfc1debff104, consistentId=Node3, addrs=ArrayList [10.97.32.54, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, /10.97.32.54:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1629871260439, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, id=9098ce77b71-accfe8fb-a5e3-41f2-82da-cfc1debff104, verifierNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=accfe8fb-a5e3-41f2-82da-cfc1debff104, order=2, addr=[10.97.32.54, 127.0.0.1], daemon=false]]]
[20:18:15,748][WARNING][tcp-disco-msg-worker-[accfe8fb 10.97.32.54:49500]-#2-#121][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'
[20:18:15,758][WARNING][disco-event-worker-#125][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=accfe8fb-a5e3-41f2-82da-cfc1debff104, consistentId=Node3, addrs=ArrayList [10.97.32.54, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, /10.97.32.54:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1629871260439, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false]
[20:18:15,760][INFO][disco-event-worker-#125][GridDiscoveryManager] Topology snapshot [ver=12, locNode=bb2aa568, servers=1, clients=1, state=ACTIVE, CPUs=32, offheap=200.0GB, heap=50.0GB]
[20:18:15,761][INFO][disco-event-worker-#125][GridDiscoveryManager] Coordinator changed [prev=TcpDiscoveryNode [id=accfe8fb-a5e3-41f2-82da-cfc1debff104, consistentId=Node3, addrs=ArrayList [10.97.32.54, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, /10.97.32.54:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1629871260439, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], cur=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629893884921, loc=true, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false]]
[20:18:15,761][INFO][disco-event-worker-#125][GridDiscoveryManager] ^-- Baseline [id=0, size=2, online=1, offline=1]
[20:18:15,775][INFO][disco-event-worker-#125][MvccProcessorImpl] Assigned mvcc coordinator [crd=MvccCoordinator [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], nodeId=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, ver=1629804134341, local=true, initialized=false]]
[20:18:15,796][INFO][exchange-worker-#127][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], crd=true, evt=NODE_FAILED, evtNode=accfe8fb-a5e3-41f2-82da-cfc1debff104, customEvt=null, allowMerge=false, exchangeFreeSwitch=true]
[20:18:15,796][INFO][sys-#1728][ExchangeLatchManager] Become new coordinator bb2aa568-9b5c-4079-bd5a-62c35e7b1ada
[20:18:15,801][INFO][sys-#1729][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CBOND_RECOMMEND_ANALYSIS, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,802][INFO][sys-#1730][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=ASE_BONDATTR, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,805][INFO][exchange-worker-#127][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CB_INDEX_WEIGHT, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,805][INFO][sys-#1733][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CBOND_ANALYSIS, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,805][INFO][sys-#1734][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=ASE_BONDFEATURE, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,815][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED]
[20:18:15,816][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange-free-replicated, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]]]
[20:18:15,817][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED]
[20:18:15,817][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange-free-partitioned, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]]]
[20:18:15,828][INFO][grid-nio-worker-tcp-comm-1-#72%TcpCommunicationSpi%][TcpCommunicationSpi] Accepted incoming communication connection [locAddr=/10.97.32.53:49000, rmtAddr=/10.97.32.54:45376]
[20:18:15,828][INFO][tcp-disco-sock-reader-[accfe8fb 10.97.32.54:59846]-#5-#124][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.97.32.54:59846, rmtPort=59846
[20:18:15,831][WARNING][grid-nio-worker-tcp-comm-1-#72%TcpCommunicationSpi%][TcpCommunicationSpi] Close incoming connection, unknown node [nodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, ses=GridSelectorNioSessionImpl [worker=DirectNioClientWorker [super=AbstractNioClientWorker [idx=1, bytesRcvd=42, bytesSent=18, bytesRcvd0=42, bytesSent0=18, select=true, super=GridWorker [name=grid-nio-worker-tcp-comm-1, igniteInstanceName=TcpCommunicationSpi, finished=false, heartbeatTs=1629893895822, hashCode=1544372059, interrupted=false, runner=grid-nio-worker-tcp-comm-1-#72%TcpCommunicationSpi%]]], writeBuf=java.nio.DirectByteBuffer[pos=0 lim=32768 cap=32768], readBuf=java.nio.DirectByteBuffer[pos=42 lim=42 cap=32768], inRecovery=null, outRecovery=null, closeSocket=true, outboundMessagesQueueSizeMetric=o.a.i.i.processors.metric.impl.LongAdderMetric@69a257d1, super=GridNioSessionImpl [locAddr=/10.97.32.53:49000, rmtAddr=/10.97.32.54:45376, createTime=1629893895822, closeTime=0, bytesSent=18, bytesRcvd=42, bytesSent0=18, bytesRcvd0=42, sndSchedTime=1629893895822, lastSndTime=1629893895822, lastRcvTime=1629893895822, readsPaused=false, filterChain=FilterChain[filters=[GridNioCodecFilter [parser=o.a.i.i.util.nio.GridDirectParser@650bc537, directMode=true], GridConnectionBytesVerifyFilter], accepted=true, markedForClose=false]]]
[20:18:15,844][INFO][exchange-worker-#127][GridCacheDatabaseSharedManager] Cache groups with earliest reserved checkpoint and a reason why a previous checkpoint was inapplicable: [[[grpId=-1149072480, grpName=ASE_BONDATTR, cp=(909bc51a-77bc-4a6b-86b6-242bbf9ac851, 08/25/2021 16:42:34)], [grpId=-1193630088, grpName=CBOND_RECOMMEND_ANALYSIS, cp=(5cac6c10-95d2-4bae-99e7-ad6d74807c51, 08/25/2021 16:14:07)], [grpId=852578677, grpName=CBOND_ANALYSIS, cp=(af35b853-4b47-41e7-a8fa-6f557f78f470, 08/25/2021 15:50:47)], [grpId=-1433191737, grpName=ASE_BONDFEATURE, cp=(0d5d421e-bc88-40ab-99ea-713b9c2f2e0e, 08/25/2021 15:26:52)], [grpId=-1698665851, grpName=CB_INDEX_WEIGHT, cp=(05e74831-6b21-4f41-93f8-1d9676af055d, 08/25/2021 14:58:57)], reason=Checkpoint was marked as inapplicable for historical rebalancing]]
[20:18:15,864][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=true]
[20:18:15,880][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], evt=NODE_FAILED, evtNode=TcpDiscoveryNode [id=accfe8fb-a5e3-41f2-82da-cfc1debff104, consistentId=Node3, addrs=ArrayList [10.97.32.54, 127.0.0.1], sockAddrs=HashSet [/127.0.0.1:49500, /10.97.32.54:49500], discPort=49500, order=2, intOrder=2, lastExchangeTime=1629871260439, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]
[20:18:15,880][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (13 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange-free-replicated]" (5 ms), stage="Wait partitions release latch [latch=exchange-free-replicated]" (1 ms), stage="Wait partitions release [latch=exchange-free-partitioned]" (0 ms), stage="Wait partitions release latch [latch=exchange-free-partitioned]" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (27 ms), stage="Finalize update counters" (11 ms), stage="Detect lost partitions" (13 ms), stage="Exchange done" (11 ms), stage="Total time" (81 ms)]
[20:18:15,880][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=ASE_BONDFEATURE]" (13 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CB_INDEX_WEIGHT]" (11 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CBOND_ANALYSIS]" (11 ms) (parent=Determine exchange type)]
[20:18:15,881][INFO][exchange-worker-#127][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], crd=true]
[20:18:15,891][INFO][exchange-worker-#127][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=12, minorTopVer=0], force=false, evt=NODE_FAILED, node=accfe8fb-a5e3-41f2-82da-cfc1debff104]
[20:18:17,742][WARNING][long-qry-#92][LongRunningQueryManager] Query execution is too long [duration=48673ms, type=MAP, distributedJoin=false, enforceJoinOrder=false, lazy=false, schema=PUBLIC, sql='SELECT
__Z0.TRADEDATE __C0_0,
__Z0.SYMBOL __C0_1,
__Z0.VALUE __C0_2,
__Z0.HOLDING __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0', plan=SELECT
__Z0.TRADEDATE AS __C0_0,
__Z0.SYMBOL AS __C0_1,
__Z0.VALUE AS __C0_2,
__Z0.HOLDING AS __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0
/* ASE_BONDATTR.BONDATTR.__SCAN_ */
/* scanCount: 11231837 */, node=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629893884921, loc=true, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], reqId=3, segment=0]
[20:18:19,423][INFO][grid-timeout-worker-#70][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=bb2aa568, uptime=06:17:03.974]
^-- Cluster [hosts=1, CPUs=32, servers=1, clients=1, topVer=12, minorTopVer=0]
^-- Network [addrs=[10.97.32.53, 127.0.0.1], discoPort=49500, commPort=49000]
^-- CPU [CPUs=32, curLoad=3.53%, avgLoad=6.08%, GC=0%]
^-- Heap [used=3053MB, free=89.98%, comm=12652MB]
^-- Off-heap memory [used=65780MB, free=67.94%, allocated=205000MB]
^-- Page memory [pages=16644670]
^-- sysMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.98%, allocRam=100MB, allocTotal=0MB]
^-- metastoreMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.91%, allocRam=0MB, allocTotal=0MB]
^-- TxLog region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=100MB, allocTotal=0MB]
^-- volatileDsMemPlc region [type=user, persistence=false, lazyAlloc=true,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=0MB]
^-- Default_Region region [type=default, persistence=true, lazyAlloc=true,
... initCfg=1024MB, maxCfg=204800MB, usedRam=65780MB, freeRam=67.88%, allocRam=204800MB, allocTotal=65018MB]
^-- Ignite persistence [used=65018MB]
^-- Outbound messages queue [size=0]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
[20:18:33,800][WARNING][tcp-disco-msg-worker-[crd]-#2-#121][TcpDiscoverySpi] Failing client node due to not receiving metrics updates from client node within 'IgniteConfiguration.clientFailureDetectionTimeout' (consider increasing configuration property) [timeout=30000, node=TcpDiscoveryNode [id=b0de752d-16da-44aa-82e2-a31f1e9edc77, consistentId=b0de752d-16da-44aa-82e2-a31f1e9edc77, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:0, /127.0.0.1:0], discPort=0, order=10, intOrder=6, lastExchangeTime=1629871260449, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=true]]
[20:18:33,801][WARNING][disco-event-worker-#125][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=b0de752d-16da-44aa-82e2-a31f1e9edc77, consistentId=b0de752d-16da-44aa-82e2-a31f1e9edc77, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:0, /127.0.0.1:0], discPort=0, order=10, intOrder=6, lastExchangeTime=1629871260449, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=true]
[20:18:33,802][INFO][disco-event-worker-#125][GridDiscoveryManager] Topology snapshot [ver=13, locNode=bb2aa568, servers=1, clients=0, state=ACTIVE, CPUs=32, offheap=200.0GB, heap=30.0GB]
[20:18:33,802][INFO][disco-event-worker-#125][GridDiscoveryManager] ^-- Baseline [id=0, size=2, online=1, offline=1]
[20:18:33,804][INFO][exchange-worker-#127][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], crd=true, evt=NODE_FAILED, evtNode=b0de752d-16da-44aa-82e2-a31f1e9edc77, customEvt=null, allowMerge=true, exchangeFreeSwitch=false]
[20:18:33,806][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=true]
[20:18:33,812][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], evt=NODE_FAILED, evtNode=TcpDiscoveryNode [id=b0de752d-16da-44aa-82e2-a31f1e9edc77, consistentId=b0de752d-16da-44aa-82e2-a31f1e9edc77, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [VKF-I03-1437.hostname.com/10.97.32.53:0, /127.0.0.1:0], discPort=0, order=10, intOrder=6, lastExchangeTime=1629871260449, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=true], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0]]
[20:18:33,812][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (1 ms), stage="Exchange done" (6 ms), stage="Total time" (7 ms)]
[20:18:33,812][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=13, minorTopVer=0]]
[20:18:33,813][INFO][exchange-worker-#127][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=13, minorTopVer=0], crd=true]
[20:18:33,816][INFO][exchange-worker-#127][GridCachePartitionExchangeManager] Skipping rebalancing (no affinity changes) [top=AffinityTopologyVersion [topVer=13, minorTopVer=0], evt=NODE_FAILED, evtNode=b0de752d-16da-44aa-82e2-a31f1e9edc77, client=false]
[20:18:34,335][INFO][db-checkpoint-thread-#163][Checkpointer] Skipping checkpoint (no pages were modified) [checkpointBeforeLockTime=14ms, checkpointLockWait=0ms, checkpointListenersExecuteTime=25ms, checkpointLockHoldTime=28ms, reason='timeout']
....................................
[20:17:53,846][WARNING][long-qry-#92][LongRunningQueryManager] Query execution is too long [duration=24770ms, type=MAP, distributedJoin=false, enforceJoinOrder=false, lazy=false, schema=PUBLIC, sql='SELECT
__Z0.TRADEDATE __C0_0,
__Z0.SYMBOL __C0_1,
__Z0.VALUE __C0_2,
__Z0.HOLDING __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0', plan=SELECT
__Z0.TRADEDATE AS __C0_0,
__Z0.SYMBOL AS __C0_1,
__Z0.VALUE AS __C0_2,
__Z0.HOLDING AS __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0
/* ASE_BONDATTR.BONDATTR.__SCAN_ */
/* scanCount: 7911990 */, node=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], reqId=3, segment=0]
[20:18:11,737][WARNING][jvm-pause-detector-worker][IgniteKernal] Possible too long JVM pause: 5359 milliseconds.
[20:18:12,211][INFO][grid-timeout-worker-#70][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=accfe8fb, uptime=1 day, 00:55:44.416]
^-- Cluster [hosts=2, CPUs=64, servers=2, clients=1, topVer=11, minorTopVer=1]
^-- Network [addrs=[10.97.32.54, 127.0.0.1], discoPort=49500, commPort=49000]
^-- CPU [CPUs=32, curLoad=74.53%, avgLoad=0.15%, GC=5.6%]
^-- Heap [used=4892MB, free=84.06%, comm=29152MB]
^-- Off-heap memory [used=66394MB, free=67.64%, allocated=205000MB]
^-- Page memory [pages=16800176]
^-- sysMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.98%, allocRam=100MB, allocTotal=0MB]
^-- metastoreMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.94%, allocRam=0MB, allocTotal=0MB]
^-- TxLog region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=100MB, allocTotal=0MB]
^-- volatileDsMemPlc region [type=user, persistence=false, lazyAlloc=true,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=0MB]
^-- Default_Region region [type=default, persistence=true, lazyAlloc=true,
... initCfg=1024MB, maxCfg=204800MB, usedRam=66394MB, freeRam=67.58%, allocRam=204800MB, allocTotal=65625MB]
^-- Ignite persistence [used=65625MB]
^-- Outbound messages queue [size=0]
^-- Public thread pool [active=0, idle=0, qSize=0]
^-- System thread pool [active=0, idle=7, qSize=0]
[20:18:15,828][INFO][tcp-disco-sock-reader-[bb2aa568 10.97.32.53:57906]-#17-#8316][TcpDiscoverySpi] Finished serving remote node connection [rmtAddr=/10.97.32.53:57906, rmtPort=57906
[20:18:15,828][WARNING][jvm-pause-detector-worker][IgniteKernal] Possible too long JVM pause: 1484 milliseconds.
[20:18:15,828][WARNING][tcp-disco-msg-worker-[bb2aa568 10.97.32.53:49500 crd]-#2-#121][TcpDiscoverySpi] Timed out waiting for message delivery receipt (most probably, the reason is in long GC pauses on remote node; consider tuning GC and increasing 'ackTimeout' configuration property). Will retry to send message with increased timeout [currentTimeout=9521, rmtAddr=/10.97.32.53:49500, rmtPort=49500]
[20:18:15,831][WARNING][tcp-disco-msg-worker-[bb2aa568 10.97.32.53:49500 crd]-#2-#121][TcpDiscoverySpi] Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=9098ce77b71-accfe8fb-a5e3-41f2-82da-cfc1debff104, verifierNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], errMsg=Failed to send message to next node [msg=TcpDiscoveryMetricsUpdateMessage [super=TcpDiscoveryAbstractMessage [sndNodeId=null, id=9098ce77b71-accfe8fb-a5e3-41f2-82da-cfc1debff104, verifierNodeId=accfe8fb-a5e3-41f2-82da-cfc1debff104, topVer=0, pendingIdx=0, failedNodes=null, isClient=false]], next=ClusterNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, order=11, addr=[10.97.32.53, 127.0.0.1], daemon=false]]]
[20:18:15,833][WARNING][tcp-disco-msg-worker-[bb2aa568 10.97.32.53:49500 crd]-#2-#121][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'
[20:18:15,836][WARNING][disco-event-worker-#125][GridDiscoveryManager] Node FAILED: TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false]
[20:18:15,837][INFO][disco-event-worker-#125][GridDiscoveryManager] Topology snapshot [ver=12, locNode=accfe8fb, servers=1, clients=1, state=ACTIVE, CPUs=64, offheap=200.0GB, heap=50.0GB]
[20:18:15,838][INFO][disco-event-worker-#125][GridDiscoveryManager] ^-- Baseline [id=0, size=2, online=1, offline=1]
[20:18:15,841][INFO][exchange-worker-#127][time] Started exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], crd=true, evt=NODE_FAILED, evtNode=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, customEvt=null, allowMerge=false, exchangeFreeSwitch=true]
[20:18:15,844][WARNING][query-#9874][IgniteH2Indexing] Long running query is finished with error: The query was cancelled while executing. [duration=46765ms, type=MAP, distributedJoin=false, enforceJoinOrder=false, lazy=false, schema=PUBLIC, sql='SELECT
__Z0.TRADEDATE __C0_0,
__Z0.SYMBOL __C0_1,
__Z0.VALUE __C0_2,
__Z0.HOLDING __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0', plan=SELECT
__Z0.TRADEDATE AS __C0_0,
__Z0.SYMBOL AS __C0_1,
__Z0.VALUE AS __C0_2,
__Z0.HOLDING AS __C0_3
FROM ASE_BONDATTR.BONDATTR __Z0
/* ASE_BONDATTR.BONDATTR.__SCAN_ */
/* scanCount: 12918527 */, node=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], reqId=3, segment=0]
[20:18:15,850][INFO][sys-#9887][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=ASE_BONDFEATURE, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,852][INFO][exchange-worker-#127][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CB_INDEX_WEIGHT, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,850][INFO][sys-#9888][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CBOND_ANALYSIS, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,852][INFO][sys-#9885][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=ASE_BONDATTR, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,850][INFO][sys-#9884][GridAffinityAssignmentCache] Local node affinity assignment distribution is not ideal [cache=CBOND_RECOMMEND_ANALYSIS, expectedPrimary=1024.00, actualPrimary=1024, expectedBackups=1024.00, actualBackups=0, warningThreshold=50.00%]
[20:18:15,852][SEVERE][query-#9874][TcpCommunicationSpi] Failed to send message to remote node [node=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], msg=GridIoMessage [plc=10, topic=TOPIC_QUERY, topicOrd=19, ordered=false, timeout=0, skipOnTimeout=false, msg=GridQueryFailResponse [qryReqId=3, errMsg=The query was cancelled while executing., failCode=1]]]
class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false]
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:420)
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1255)
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:689)
at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:453)
at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:228)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1186)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1133)
at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2101)
at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2196)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.sendError(GridMapQueryExecutor.java:756)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.onQueryRequest0(GridMapQueryExecutor.java:532)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.onQueryRequest(GridMapQueryExecutor.java:269)
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.onMessage(IgniteH2Indexing.java:2240)
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.lambda$start$20(IgniteH2Indexing.java:2185)
at org.apache.ignite.internal.managers.communication.GridIoManager$ArrayListener.onMessage(GridIoManager.java:3478)
at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1908)
at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1529)
at org.apache.ignite.internal.managers.communication.GridIoManager.access$5300(GridIoManager.java:242)
at org.apache.ignite.internal.managers.communication.GridIoManager$9.execute(GridIoManager.java:1422)
at org.apache.ignite.internal.managers.communication.TraceRunnable.run(TraceRunnable.java:55)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
[20:18:15,854][SEVERE][query-#9874][GridMapQueryExecutor] Failed to send error message.
class org.apache.ignite.internal.cluster.ClusterTopologyCheckedException: Failed to send message (node left topology): TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false]
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createNioSession(GridNioServerWrapper.java:420)
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:691)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.createTcpClient(TcpCommunicationSpi.java:1255)
at org.apache.ignite.spi.communication.tcp.internal.GridNioServerWrapper.createTcpClient(GridNioServerWrapper.java:689)
at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.createCommunicationClient(ConnectionClientPool.java:453)
at org.apache.ignite.spi.communication.tcp.internal.ConnectionClientPool.reserveClient(ConnectionClientPool.java:228)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage0(TcpCommunicationSpi.java:1186)
at org.apache.ignite.spi.communication.tcp.TcpCommunicationSpi.sendMessage(TcpCommunicationSpi.java:1133)
at org.apache.ignite.internal.managers.communication.GridIoManager.send(GridIoManager.java:2101)
at org.apache.ignite.internal.managers.communication.GridIoManager.sendToGridTopic(GridIoManager.java:2196)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.sendError(GridMapQueryExecutor.java:756)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.onQueryRequest0(GridMapQueryExecutor.java:532)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.onQueryRequest(GridMapQueryExecutor.java:269)
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.onMessage(IgniteH2Indexing.java:2240)
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.lambda$start$20(IgniteH2Indexing.java:2185)
at org.apache.ignite.internal.managers.communication.GridIoManager$ArrayListener.onMessage(GridIoManager.java:3478)
at org.apache.ignite.internal.managers.communication.GridIoManager.invokeListener(GridIoManager.java:1908)
at org.apache.ignite.internal.managers.communication.GridIoManager.processRegularMessage0(GridIoManager.java:1529)
at org.apache.ignite.internal.managers.communication.GridIoManager.access$5300(GridIoManager.java:242)
at org.apache.ignite.internal.managers.communication.GridIoManager$9.execute(GridIoManager.java:1422)
at org.apache.ignite.internal.managers.communication.TraceRunnable.run(TraceRunnable.java:55)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1149)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:624)
at java.lang.Thread.run(Thread.java:748)
Suppressed: class org.apache.ignite.cache.query.QueryCancelledException: The query was cancelled while executing.
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.executeSqlQuery(IgniteH2Indexing.java:857)
at org.apache.ignite.internal.processors.query.h2.IgniteH2Indexing.executeSqlQueryWithTimer(IgniteH2Indexing.java:949)
at org.apache.ignite.internal.processors.query.h2.twostep.GridMapQueryExecutor.onQueryRequest0(GridMapQueryExecutor.java:449)
... 12 more
[20:18:15,857][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED]
[20:18:15,858][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange-free-replicated, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]]]
[20:18:15,858][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partition release future [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], waitTime=0ms, futInfo=NA, mode=DISTRIBUTED]
[20:18:15,859][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finished waiting for partitions release latch: ServerLatch [permits=0, pendingAcks=HashSet [], super=CompletableLatch [id=CompletableLatchUid [id=exchange-free-partitioned, topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]]]
[20:18:15,880][INFO][exchange-worker-#127][GridCacheDatabaseSharedManager] Cache groups with earliest reserved checkpoint and a reason why a previous checkpoint was inapplicable: [[[grpId=-1149072480, grpName=ASE_BONDATTR, cp=(8f143b73-3838-4439-93cf-b76b7d289eaa, 08/25/2021 00:10:58)], [grpId=-1193630088, grpName=CBOND_RECOMMEND_ANALYSIS, cp=(8f143b73-3838-4439-93cf-b76b7d289eaa, 08/25/2021 00:10:58)], [grpId=852578677, grpName=CBOND_ANALYSIS, cp=(8f143b73-3838-4439-93cf-b76b7d289eaa, 08/25/2021 00:10:58)], [grpId=-1433191737, grpName=ASE_BONDFEATURE, cp=(8f143b73-3838-4439-93cf-b76b7d289eaa, 08/25/2021 00:10:58)], [grpId=-1698665851, grpName=CB_INDEX_WEIGHT, cp=(8f143b73-3838-4439-93cf-b76b7d289eaa, 08/25/2021 00:10:58)], reason=Reserved checkpoint is the oldest in history]]
[20:18:15,887][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Finish exchange future [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], err=null, rebalanced=true, wasRebalanced=true]
[20:18:15,897][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Completed partition exchange [localNode=accfe8fb-a5e3-41f2-82da-cfc1debff104, exchange=GridDhtPartitionsExchangeFuture [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], evt=NODE_FAILED, evtNode=TcpDiscoveryNode [id=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada, consistentId=Node1, addrs=ArrayList [10.97.32.53, 127.0.0.1], sockAddrs=HashSet [/10.97.32.53:49500, /127.0.0.1:49500], discPort=49500, order=11, intOrder=7, lastExchangeTime=1629871260358, loc=false, ver=2.10.0#20210310-sha1:bc24f6ba, isClient=false], rebalanced=true, done=true, newCrdFut=null], topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0]]
[20:18:15,897][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange timings [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], stage="Waiting in exchange queue" (0 ms), stage="Exchange parameters initialization" (0 ms), stage="Determine exchange type" (15 ms), stage="Preloading notification" (0 ms), stage="Wait partitions release [latch=exchange-free-replicated]" (0 ms), stage="Wait partitions release latch [latch=exchange-free-replicated]" (0 ms), stage="Wait partitions release [latch=exchange-free-partitioned]" (0 ms), stage="Wait partitions release latch [latch=exchange-free-partitioned]" (0 ms), stage="After states restored callback" (0 ms), stage="WAL history reservation" (21 ms), stage="Finalize update counters" (3 ms), stage="Detect lost partitions" (5 ms), stage="Exchange done" (6 ms), stage="Total time" (50 ms)]
[20:18:15,897][INFO][exchange-worker-#127][GridDhtPartitionsExchangeFuture] Exchange longest local stages [startVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CB_INDEX_WEIGHT]" (14 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=CBOND_RECOMMEND_ANALYSIS]" (14 ms) (parent=Determine exchange type), stage="Affinity initialization (exchange-free switch on fully-rebalanced topology) [grp=ASE_BONDATTR]" (14 ms) (parent=Determine exchange type)]
[20:18:15,898][INFO][exchange-worker-#127][time] Finished exchange init [topVer=AffinityTopologyVersion [topVer=12, minorTopVer=0], crd=true]
[20:18:15,908][INFO][exchange-worker-#127][GridCachePartitionExchangeManager] Skipping rebalancing (nothing scheduled) [top=AffinityTopologyVersion [topVer=12, minorTopVer=0], force=false, evt=NODE_FAILED, node=bb2aa568-9b5c-4079-bd5a-62c35e7b1ada]
[20:18:39,221][INFO][db-checkpoint-thread-#143][Checkpointer] Skipping checkpoint (no pages were modified) [checkpointBeforeLockTime=18ms, checkpointLockWait=0ms, checkpointListenersExecuteTime=25ms, checkpointLockHoldTime=28ms, reason='timeout']
[20:19:12,216][INFO][grid-timeout-worker-#70][IgniteKernal]
Metrics for local node (to disable set 'metricsLogFrequency' to 0)
^-- Node [id=accfe8fb, uptime=1 day, 00:56:44.424]
^-- Cluster [hosts=2, CPUs=64, servers=1, clients=1, topVer=12, minorTopVer=0]
^-- Network [addrs=[10.97.32.54, 127.0.0.1], discoPort=49500, commPort=49000]
^-- CPU [CPUs=32, curLoad=0.03%, avgLoad=0.15%, GC=0%]
^-- Heap [used=4941MB, free=83.9%, comm=29152MB]
^-- Off-heap memory [used=66394MB, free=67.64%, allocated=205000MB]
^-- Page memory [pages=16800176]
^-- sysMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.98%, allocRam=100MB, allocTotal=0MB]
^-- metastoreMemPlc region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=99.94%, allocRam=0MB, allocTotal=0MB]
^-- TxLog region [type=internal, persistence=true, lazyAlloc=false,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=100MB, allocTotal=0MB]
^-- volatileDsMemPlc region [type=user, persistence=false, lazyAlloc=true,
... initCfg=40MB, maxCfg=100MB, usedRam=0MB, freeRam=100%, allocRam=0MB]
^-- Default_Region region [type=default, persistence=true, lazyAlloc=true,
... initCfg=1024MB, maxCfg=204800MB, usedRam=66394MB, freeRam=67.58%, allocRam=204800MB, allocTotal=65625MB]
^-- Ignite persistence [used=65625MB]
^-- Outbound messages queue [size=0]
^-- Public thread pool [active=0, idle=2, qSize=0]
^-- System thread pool [active=0, idle=32, qSize=0]
..........................
