With timeouts you've recommended we are still observing sudden latency spike on client -> server communication leading to timeouts and restart after just 2 minutes running *with no production load on service*, literally just health checks running
Here are logs from client pod: ``` $ kubectl logs -f -n buildcache buildcache-3 --previous 2018-09-28T05:23:31.231Z [main]/I: Starting the server... 2018-09-28T05:23:31.381Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=10, freeMemoryMb=4085) Sep 28, 2018 5:23:31 AM java.util.logging.LogManager$RootLogger log SEVERE: Failed to resolve default logging config file: config/java.util.logging.properties Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: >>> __________ ________________ >>> / _/ ___/ |/ / _/_ __/ __/ >>> _/ // (7 7 // / / / / _/ >>> /___/\___/_/|_/___/ /_/ /___/ >>> >>> ver. 2.6.0#20180710-sha1:669feacc >>> 2018 Copyright(C) Apache Software Foundation >>> >>> Ignite documentation: http://ignite.apache.org Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Config URL: n/a Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: IgniteConfiguration [igniteInstanceName=null, pubPoolSize=8, svcPoolSize=8, callbackPoolSize=8, stripedPoolSize=8, sysPoolSize=8, mgmtPoolSize=4, igfsPoolSize=8, dataStreamerPoolSize=8, utilityCachePoolSize=8, utilityCacheKeepAliveTime=60000, p2pPoolSize=2, qryPoolSize=8, igniteHome=null, igniteWorkDir=/tmp/ignite/work, mbeanSrv=com.sun.jmx.mbeanserver.JmxMBeanServer@363ee3a2, nodeId=395941f3-a9fd-41c9-8035-06b2fac1b55e, marsh=org.apache.ignite.internal.binary.BinaryMarshaller@2898ac89, 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@6a2b953e, locAddr=null, locHost=null, locPort=47100, locPortRange=0, shmemPort=-1, directBuf=true, directSndBuf=false, idleConnTimeout=600000, connTimeout=5000, maxConnTimeout=600000, reconCnt=10, sockSndBuf=32768, sockRcvBuf=32768, msgQueueLimit=512, slowClientQueueLimit=0, nioSrvr=null, shmemSrv=null, usePairedConnections=false, connectionsPerNode=1, tcpNoDelay=true, filterReachableAddresses=false, ackSndThreshold=32, unackedMsgsBufSize=0, sockWriteTimeout=2000, lsnr=null, boundTcpPort=-1, boundTcpShmemPort=-1, selectorsCnt=4, selectorSpins=0, addrRslvr=null, ctxInitLatch=java.util.concurrent.CountDownLatch@313b2ea6[Count = 1], stopping=false, metricsLsnr=org.apache.ignite.spi.communication.tcp.TcpCommunicationMetricsListener@2f465398], evtSpi=org.apache.ignite.spi.eventstorage.NoopEventStorageSpi@548e6d58, colSpi=NoopCollisionSpi [], deploySpi=LocalDeploymentSpi [lsnr=null], indexingSpi=org.apache.ignite.spi.indexing.noop.NoopIndexingSpi@610f7aa, addrRslvr=null, clientMode=true, rebalanceThreadPoolSize=1, txCfg=org.apache.ignite.configuration.TransactionConfiguration@6a03bcb1, cacheSanityCheckEnabled=true, discoStartupDelay=60000, deployMode=SHARED, p2pMissedCacheSize=100, locHost=null, timeSrvPortBase=31100, timeSrvPortRange=100, failureDetectionTimeout=60000, clientFailureDetectionTimeout=30000, metricsLogFreq=60000, hadoopCfg=null, connectorCfg=org.apache.ignite.configuration.ConnectorConfiguration@21b2e768, 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=8192, concLvl=0, dfltDataRegConf=DataRegionConfiguration [name=Default_Region, maxSize=52428800, initSize=52428800, swapPath=null, pageEvictionMode=DISABLED, evictionThreshold=0.9, emptyPagesPoolSize=100, metricsEnabled=false, metricsSubIntervalCount=5, metricsRateTimeInterval=60000, persistenceEnabled=false, checkpointPageBufSize=0], storagePath=null, checkpointFreq=180000, lockWaitTime=10000, checkpointThreads=4, checkpointWriteOrder=SEQUENTIAL, walHistSize=20, walSegments=10, walSegmentSize=67108864, 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@5609159b, metricsSubIntervalCnt=5, metricsRateTimeInterval=60000, walAutoArchiveAfterInactivity=-1, writeThrottlingEnabled=false, walCompactionEnabled=false], activeOnStart=true, autoActivation=true, longQryWarnTimeout=3000, sqlConnCfg=null, cliConnCfg=ClientConnectorConfiguration [host=null, port=10800, portRange=100, sockSndBufSize=0, sockRcvBufSize=0, tcpNoDelay=true, maxOpenCursorsPerConn=128, threadPoolSize=8, idleTimeout=0, jdbcEnabled=true, odbcEnabled=true, thinCliEnabled=true, sslEnabled=false, useIgniteSslCtxFactory=true, sslClientAuth=false, sslCtxFactory=null], authEnabled=false, failureHnd=null, commFailureRslvr=null] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Daemon mode: off Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: OS: Linux 4.17.17-200.fc28.x86_64 amd64 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: OS user: root Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: PID: 1 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Language runtime: Java Platform API Specification ver. 1.8 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: VM information: OpenJDK Runtime Environment 1.8.0_171-b11 Oracle Corporation OpenJDK 64-Bit Server VM 25.171-b11 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: VM total memory: 4.0GB Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Remote Management [restart: off, REST: off, JMX (remote: off)] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Logger: JavaLogger [quiet=false, config=null] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: IGNITE_HOME=null Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: VM arguments: [-Xms4096M, -Xmx4096M, -XX:+PrintGC, -XX:+PrintGCDateStamps, -XX:+UseG1GC, -XX:+AlwaysPreTouch, -XX:+ScavengeBeforeFullGC, -XX:+DisableExplicitGC, -XX:MaxGCPauseMillis=30, -XX:+UnlockExperimentalVMOptions, -XX:G1NewSizePercent=20, -DIGNITE_QUIET=false, -Djava.net.preferIPv4Stack=true] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: System cache's DataRegion size is configured to 40 MB. Use DataStorageConfiguration.systemCacheMemorySize property to change the setting. Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Configured caches [in 'sysMemPlc' dataRegion: ['ignite-sys-cache']] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Configured plugins: Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: ^-- None Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Configured failure handler: [hnd=StopNodeOrHaltFailureHandler [tryStop=false, timeout=0]] 2018-09-28T05:23:32.156+0000: [GC pause (Metadata GC Threshold) (young) (initial-mark) 55M->11M(4096M), 0.0205314 secs] 2018-09-28T05:23:32.177+0000: [GC concurrent-root-region-scan-start] 2018-09-28T05:23:32.183+0000: [GC concurrent-root-region-scan-end, 0.0065217 secs] 2018-09-28T05:23:32.183+0000: [GC concurrent-mark-start] 2018-09-28T05:23:32.185+0000: [GC concurrent-mark-end, 0.0018376 secs] 2018-09-28T05:23:32.186+0000: [GC remark, 0.0040225 secs] 2018-09-28T05:23:32.190+0000: [GC cleanup 13M->13M(4096M), 0.0022399 secs] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: 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] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger warning WARNING: Checkpoints are disabled (to enable configure any GridCheckpointSpi implementation) Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger warning WARNING: Collision resolution is disabled (all jobs will be activated upon arrival). Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Security status [authentication=off, tls/ssl=off] Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Client connector processor has started on TCP port 10800 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: REST protocols do not start on client node. To start the protocols on client node set '-DIGNITE_REST_START_ON_CLIENT=true' system property. Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Non-loopback local IPs: 10.42.32.36 Sep 28, 2018 5:23:32 AM org.apache.ignite.logger.java.JavaLogger info INFO: Enabled local MACs: 0A094ED0320C Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Started exchange init [topVer=AffinityTopologyVersion [topVer=632, minorTopVer=0], crd=false, evt=NODE_JOINED, evtNode=395941f3-a9fd-41c9-8035-06b2fac1b55e, customEvt=null, allowMerge=true] 2018-09-28T05:23:33.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=107, freeMemoryMb=3988) 2018-09-28T05:23:33.488+0000: [GC pause (Metadata GC Threshold) (young) (initial-mark) 114M->37M(4096M), 0.0533984 secs] 2018-09-28T05:23:33.541+0000: [GC concurrent-root-region-scan-start] 2018-09-28T05:23:33.571+0000: [GC concurrent-root-region-scan-end, 0.0297871 secs] 2018-09-28T05:23:33.571+0000: [GC concurrent-mark-start] 2018-09-28T05:23:33.573+0000: [GC concurrent-mark-end, 0.0020858 secs] 2018-09-28T05:23:33.574+0000: [GC remark, 0.0129509 secs] 2018-09-28T05:23:33.587+0000: [GC cleanup 42M->42M(4096M), 0.0034809 secs] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Started cache [name=ignite-sys-cache, id=-2100569601, memoryPolicyName=sysMemPlc, mode=REPLICATED, atomicity=TRANSACTIONAL, backups=2147483647] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:42504, rmtAddr=ignite-0.ignite.buildcache.svc.cluster.local/10.42.40.84:47100] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Finished exchange init [topVer=AffinityTopologyVersion [topVer=632, minorTopVer=0], crd=false] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Received full message, will finish exchange [node=f47de522-5e60-49c8-9f2b-5a55254ffeba, resVer=AffinityTopologyVersion [topVer=632, minorTopVer=0]] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Finish exchange future [startVer=AffinityTopologyVersion [topVer=632, minorTopVer=0], resVer=AffinityTopologyVersion [topVer=632, minorTopVer=0], err=null] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Performance suggestions for grid (fix if possible) Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: To disable, set -DIGNITE_PERFORMANCE_SUGGESTIONS_DISABLED=true Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: ^-- Set max direct memory size if getting 'OOME: Direct buffer memory' (add '-XX:MaxDirectMemorySize=<size>[g|G|m|M|k|K]' to JVM options) Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Refer to this page for more performance suggestions: https://apacheignite.readme.io/docs/jvm-and-system-tuning Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: To start Console Management & Monitoring run ignitevisorcmd.{sh|bat} Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: >>> +----------------------------------------------------------------------+ >>> Ignite ver. 2.6.0#20180710-sha1:669feacc5d3a4e60efcdd300dc8de99780f38eed >>> +----------------------------------------------------------------------+ >>> OS name: Linux 4.17.17-200.fc28.x86_64 amd64 >>> CPU(s): 8 >>> Heap: 4.0GB >>> VM name: 1...@buildcache-3.buildcache-service.buildcache.svc.cluster.local >>> Local node [ID=395941F3-A9FD-41C9-8035-06B2FAC1B55E, order=632, >>> clientMode=true] >>> Local node addresses: >>> [buildcache-3.buildcache-service.buildcache.svc.cluster.local/10.42.32.36, >>> /127.0.0.1] >>> Local ports: TCP:10800 TCP:47100 Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Topology snapshot [ver=632, servers=12, clients=4, CPUs=128, offheap=290.0GB, heap=64.0GB] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: ^-- Node [id=395941F3-A9FD-41C9-8035-06B2FAC1B55E, clusterState=ACTIVE] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Data Regions Configured: Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: ^-- Default_Region [initSize=50.0 MiB, maxSize=50.0 MiB, persistenceEnabled=false] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger warning WARNING: Cache write synchronization mode is set to FULL_ASYNC. All single-key 'put' and 'remove' operations will return 'null', all 'putx' and 'removex' operations will return 'true' [cacheName=buildcache] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Started cache [name=buildcache, id=-467288620, memoryPolicyName=Default_Region, mode=PARTITIONED, atomicity=ATOMIC, backups=0] Sep 28, 2018 5:23:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:43284, rmtAddr=ignite-11.ignite.buildcache.svc.cluster.local/10.42.20.184:47100] 2018-09-28 05:23:33.921:INFO::main: Logging initialized @4865ms to org.eclipse.jetty.util.log.StdErrLog 2018-09-28 05:23:33.978:INFO:oejs.Server:main: jetty-9.4.z-SNAPSHOT; built: 2018-06-05T18:24:03.829Z; git: d5fc0523cfa96bfebfbda19606cad384d772f04c; jvm 1.8.0_171-b11 2018-09-28 05:23:34.301:INFO:oejs.AbstractConnector:main: Started ServerConnector@113bebca{HTTP/1.1,[http/1.1]}{0.0.0.0:8080} 2018-09-28 05:23:34.302:INFO:oejs.Server:main: Started @5245ms 2018-09-28T05:23:34.302Z [main]/I: Server has started in 3074 ms and is ready to handle requests on port 8080. 2018-09-28T05:23:35.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=79, freeMemoryMb=4016) 2018-09-28T05:23:37.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=82, freeMemoryMb=4013) 2018-09-28T05:23:38.188Z [RxComputationThreadPool-4]/VERBOSE: ---> req 0 GET /health Sep 28, 2018 5:23:38 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:50798, rmtAddr=ignite-5.ignite.buildcache.svc.cluster.local/10.42.25.137:47100] 2018-09-28T05:23:38.254Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 29 ms 2018-09-28T05:23:38.263Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 0 200 GET /health , took 94.56 ms 2018-09-28T05:23:39.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=102, freeMemoryMb=3993) 2018-09-28T05:23:41.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=102, freeMemoryMb=3993) 2018-09-28T05:23:43.068Z [RxComputationThreadPool-2]/VERBOSE: ---> req 1 GET /health 2018-09-28T05:23:43.161Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 75 ms 2018-09-28T05:23:43.162Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 1 200 GET /health , took 94.16 ms Sep 28, 2018 5:23:43 AM org.apache.ignite.logger.java.JavaLogger info INFO: Your version is up to date. 2018-09-28T05:23:43.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=105, freeMemoryMb=3990) 2018-09-28T05:23:45.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=106, freeMemoryMb=3989) 2018-09-28T05:23:47.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=106, freeMemoryMb=3989) 2018-09-28T05:23:48.068Z [RxComputationThreadPool-8]/VERBOSE: ---> req 2 GET /health Sep 28, 2018 5:23:48 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:53006, rmtAddr=ignite-6.ignite.buildcache.svc.cluster.local/10.42.39.9:47100] 2018-09-28T05:23:48.100Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 5 ms 2018-09-28T05:23:48.100Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 2 200 GET /health , took 32.90 ms 2018-09-28T05:23:49.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=108, freeMemoryMb=3987) 2018-09-28T05:23:50.090Z [RxComputationThreadPool-6]/VERBOSE: ---> req 3 GET /health Sep 28, 2018 5:23:50 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:49148, rmtAddr=ignite-7.ignite.buildcache.svc.cluster.local/10.42.34.115:47100] 2018-09-28T05:23:50.109Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 4 ms 2018-09-28T05:23:50.110Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 3 200 GET /health , took 20.23 ms 2018-09-28T05:23:51.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=110, freeMemoryMb=3985) 2018-09-28T05:23:52.090Z [RxComputationThreadPool-4]/VERBOSE: ---> req 4 GET /health Sep 28, 2018 5:23:52 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:46304, rmtAddr=ignite-9.ignite.buildcache.svc.cluster.local/10.42.60.171:47100] 2018-09-28T05:23:52.119Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 4 ms 2018-09-28T05:23:52.120Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 4 200 GET /health , took 30.09 ms 2018-09-28T05:23:53.068Z [RxComputationThreadPool-1]/VERBOSE: ---> req 5 GET /health Sep 28, 2018 5:23:53 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:35318, rmtAddr=ignite-10.ignite.buildcache.svc.cluster.local/10.42.46.110:47100] 2018-09-28T05:23:53.078Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 3 ms 2018-09-28T05:23:53.079Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 5 200 GET /health , took 11.45 ms 2018-09-28T05:23:53.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=113, freeMemoryMb=3982) 2018-09-28T05:23:54.089Z [RxComputationThreadPool-7]/VERBOSE: ---> req 6 GET /health Sep 28, 2018 5:23:54 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:54638, rmtAddr=ignite-2.ignite.buildcache.svc.cluster.local/10.42.64.23:47100] 2018-09-28T05:23:54.099Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 4 ms 2018-09-28T05:23:54.100Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 6 200 GET /health , took 10.43 ms 2018-09-28T05:23:55.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=115, freeMemoryMb=3980) 2018-09-28T05:23:56.089Z [RxComputationThreadPool-4]/VERBOSE: ---> req 7 GET /health 2018-09-28T05:23:56.107Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:23:56.108Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 7 200 GET /health , took 18.79 ms 2018-09-28T05:23:57.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=116, freeMemoryMb=3979) 2018-09-28T05:23:58.067Z [RxComputationThreadPool-2]/VERBOSE: ---> req 8 GET /health Sep 28, 2018 5:23:58 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:46570, rmtAddr=ignite-3.ignite.buildcache.svc.cluster.local/10.42.40.12:47100] 2018-09-28T05:23:58.161Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 76 ms 2018-09-28T05:23:58.161Z [RxComputationThreadPool-8]/VERBOSE: ---> req 9 GET /health 2018-09-28T05:23:58.162Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 8 200 GET /health , took 94.79 ms 2018-09-28T05:23:58.177Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:23:58.178Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 9 200 GET /health , took 88.32 ms 2018-09-28T05:23:59.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=118, freeMemoryMb=3977) 2018-09-28T05:24:00.089Z [RxComputationThreadPool-6]/VERBOSE: ---> req 10 GET /health 2018-09-28T05:24:00.097Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:00.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 10 200 GET /health , took 8.14 ms 2018-09-28T05:24:01.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=119, freeMemoryMb=3976) 2018-09-28T05:24:02.089Z [RxComputationThreadPool-4]/VERBOSE: ---> req 11 GET /health Sep 28, 2018 5:24:02 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:49956, rmtAddr=ignite-8.ignite.buildcache.svc.cluster.local/10.42.20.199:47100] 2018-09-28T05:24:02.109Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 4 ms 2018-09-28T05:24:02.110Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 11 200 GET /health , took 20.98 ms 2018-09-28T05:24:03.067Z [RxComputationThreadPool-2]/VERBOSE: ---> req 12 GET /health 2018-09-28T05:24:03.097Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:03.098Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 12 200 GET /health , took 30.65 ms 2018-09-28T05:24:03.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=120, freeMemoryMb=3975) 2018-09-28T05:24:04.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 13 GET /health 2018-09-28T05:24:04.117Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:04.118Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 13 200 GET /health , took 28.51 ms 2018-09-28T05:24:05.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=121, freeMemoryMb=3974) 2018-09-28T05:24:06.089Z [RxComputationThreadPool-6]/VERBOSE: ---> req 14 GET /health 2018-09-28T05:24:06.097Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:06.098Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 14 200 GET /health , took 8.78 ms 2018-09-28T05:24:07.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=121, freeMemoryMb=3974) 2018-09-28T05:24:08.067Z [RxComputationThreadPool-4]/VERBOSE: ---> req 15 GET /health 2018-09-28T05:24:08.077Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:08.078Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 15 200 GET /health , took 10.93 ms 2018-09-28T05:24:08.089Z [RxComputationThreadPool-2]/VERBOSE: ---> req 16 GET /health 2018-09-28T05:24:08.162Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:08.162Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 16 200 GET /health , took 73.58 ms 2018-09-28T05:24:09.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=123, freeMemoryMb=3972) 2018-09-28T05:24:10.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 17 GET /health 2018-09-28T05:24:10.117Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:10.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 17 200 GET /health , took 28.24 ms 2018-09-28T05:24:11.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=124, freeMemoryMb=3971) 2018-09-28T05:24:12.089Z [RxComputationThreadPool-6]/VERBOSE: ---> req 18 GET /health 2018-09-28T05:24:12.097Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:12.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 18 200 GET /health , took 8.15 ms 2018-09-28T05:24:13.068Z [RxComputationThreadPool-4]/VERBOSE: ---> req 19 GET /health 2018-09-28T05:24:13.087Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:13.088Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 19 200 GET /health , took 20.41 ms 2018-09-28T05:24:13.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=125, freeMemoryMb=3970) 2018-09-28T05:24:14.089Z [RxComputationThreadPool-1]/VERBOSE: ---> req 20 GET /health Sep 28, 2018 5:24:14 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:36994, rmtAddr=ignite-1.ignite.buildcache.svc.cluster.local/10.42.43.251:47100] 2018-09-28T05:24:14.109Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 4 ms 2018-09-28T05:24:14.109Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 20 200 GET /health , took 20.27 ms 2018-09-28T05:24:15.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=125, freeMemoryMb=3970) 2018-09-28T05:24:16.089Z [RxComputationThreadPool-7]/VERBOSE: ---> req 21 GET /health 2018-09-28T05:24:16.117Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:16.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 21 200 GET /health , took 28.43 ms 2018-09-28T05:24:17.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=126, freeMemoryMb=3969) 2018-09-28T05:24:18.067Z [RxComputationThreadPool-5]/VERBOSE: ---> req 22 GET /health 2018-09-28T05:24:18.089Z [RxComputationThreadPool-1]/VERBOSE: ---> req 23 GET /health Sep 28, 2018 5:24:18 AM org.apache.ignite.logger.java.JavaLogger info INFO: Established outgoing communication connection [locAddr=/10.42.32.36:54172, rmtAddr=ignite-4.ignite.buildcache.svc.cluster.local/10.42.58.57:47100] 2018-09-28T05:24:18.099Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 2, size: "0 B" } was processed, took 4 ms 2018-09-28T05:24:18.160Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 22 200 GET /health , took 93.56 ms 2018-09-28T05:24:18.161Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 23 200 GET /health , took 71.56 ms 2018-09-28T05:24:19.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=129, freeMemoryMb=3966) 2018-09-28T05:24:20.089Z [RxComputationThreadPool-7]/VERBOSE: ---> req 24 GET /health 2018-09-28T05:24:20.107Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:20.107Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 24 200 GET /health , took 18.26 ms 2018-09-28T05:24:21.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=129, freeMemoryMb=3966) 2018-09-28T05:24:22.089Z [RxComputationThreadPool-5]/VERBOSE: ---> req 25 GET /health 2018-09-28T05:24:22.116Z [RxComputationThreadPool-1]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:22.117Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 25 200 GET /health , took 27.76 ms 2018-09-28T05:24:23.067Z [RxComputationThreadPool-3]/VERBOSE: ---> req 26 GET /health 2018-09-28T05:24:23.077Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:23.077Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 26 200 GET /health , took 10.46 ms 2018-09-28T05:24:23.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=130, freeMemoryMb=3965) 2018-09-28T05:24:24.089Z [RxComputationThreadPool-1]/VERBOSE: ---> req 27 GET /health 2018-09-28T05:24:24.096Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:24.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 27 200 GET /health , took 7.97 ms 2018-09-28T05:24:25.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=131, freeMemoryMb=3964) 2018-09-28T05:24:26.089Z [RxComputationThreadPool-7]/VERBOSE: ---> req 28 GET /health 2018-09-28T05:24:26.107Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:26.108Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 28 200 GET /health , took 18.74 ms 2018-09-28T05:24:27.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=132, freeMemoryMb=3963) 2018-09-28T05:24:28.067Z [RxComputationThreadPool-5]/VERBOSE: ---> req 29 GET /health 2018-09-28T05:24:28.087Z [RxComputationThreadPool-1]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:28.087Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 29 200 GET /health , took 20.37 ms 2018-09-28T05:24:28.089Z [RxComputationThreadPool-3]/VERBOSE: ---> req 30 GET /health 2018-09-28T05:24:28.117Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:28.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 30 200 GET /health , took 28.07 ms 2018-09-28T05:24:29.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=135, freeMemoryMb=3960) 2018-09-28T05:24:30.100Z [RxComputationThreadPool-1]/VERBOSE: ---> req 31 GET /health 2018-09-28T05:24:30.127Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:30.128Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 31 200 GET /health , took 28.49 ms 2018-09-28T05:24:31.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=135, freeMemoryMb=3960) 2018-09-28T05:24:32.089Z [RxComputationThreadPool-6]/VERBOSE: ---> req 32 GET /health 2018-09-28T05:24:32.107Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:32.107Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 32 200 GET /health , took 18.28 ms 2018-09-28T05:24:33.067Z [RxComputationThreadPool-4]/VERBOSE: ---> req 33 GET /health 2018-09-28T05:24:33.096Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:33.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 33 200 GET /health , took 29.97 ms 2018-09-28T05:24:33.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=138, freeMemoryMb=3957) Sep 28, 2018 5:24:33 AM org.apache.ignite.logger.java.JavaLogger info INFO: Metrics for local node (to disable set 'metricsLogFrequency' to 0) ^-- Node [id=395941f3, uptime=00:01:00.004] ^-- H/N/C [hosts=16, nodes=16, CPUs=128] ^-- CPU [cur=0.1%, avg=0.34%, GC=0%] ^-- PageMemory [pages=0] ^-- Heap [used=138MB, free=96.63%, comm=4096MB] ^-- Non heap [used=55MB, free=-1%, comm=56MB] ^-- Outbound messages queue [size=0] ^-- Public thread pool [active=0, idle=0, qSize=0] ^-- System thread pool [active=0, idle=0, qSize=0] 2018-09-28T05:24:34.089Z [RxComputationThreadPool-2]/VERBOSE: ---> req 34 GET /health 2018-09-28T05:24:34.117Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:34.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 34 200 GET /health , took 28.38 ms 2018-09-28T05:24:35.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=139, freeMemoryMb=3956) 2018-09-28T05:24:36.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 35 GET /health 2018-09-28T05:24:36.097Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:36.098Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 35 200 GET /health , took 8.54 ms 2018-09-28T05:24:37.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=140, freeMemoryMb=3955) 2018-09-28T05:24:38.067Z [RxComputationThreadPool-6]/VERBOSE: ---> req 36 GET /health 2018-09-28T05:24:38.077Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:38.078Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 36 200 GET /health , took 10.66 ms 2018-09-28T05:24:38.089Z [RxComputationThreadPool-4]/VERBOSE: ---> req 37 GET /health 2018-09-28T05:24:38.106Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:38.106Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 37 200 GET /health , took 17.52 ms 2018-09-28T05:24:39.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=141, freeMemoryMb=3954) 2018-09-28T05:24:40.089Z [RxComputationThreadPool-2]/VERBOSE: ---> req 38 GET /health 2018-09-28T05:24:40.116Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:40.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 38 200 GET /health , took 27.90 ms 2018-09-28T05:24:41.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=142, freeMemoryMb=3953) 2018-09-28T05:24:42.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 39 GET /health 2018-09-28T05:24:42.097Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:42.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 39 200 GET /health , took 8.19 ms 2018-09-28T05:24:43.067Z [RxComputationThreadPool-5]/VERBOSE: ---> req 40 GET /health 2018-09-28T05:24:43.087Z [RxComputationThreadPool-1]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:43.087Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 40 200 GET /health , took 20.41 ms 2018-09-28T05:24:43.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=143, freeMemoryMb=3952) 2018-09-28T05:24:44.089Z [RxComputationThreadPool-3]/VERBOSE: ---> req 41 GET /health 2018-09-28T05:24:44.106Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:44.107Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 41 200 GET /health , took 17.91 ms 2018-09-28T05:24:45.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=144, freeMemoryMb=3951) 2018-09-28T05:24:46.089Z [RxComputationThreadPool-1]/VERBOSE: ---> req 42 GET /health 2018-09-28T05:24:46.117Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:46.117Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 42 200 GET /health , took 28.13 ms 2018-09-28T05:24:47.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=144, freeMemoryMb=3951) 2018-09-28T05:24:48.067Z [RxComputationThreadPool-7]/VERBOSE: ---> req 43 GET /health 2018-09-28T05:24:48.089Z [RxComputationThreadPool-3]/VERBOSE: ---> req 44 GET /health 2018-09-28T05:24:48.097Z [RxComputationThreadPool-7]/VERBOSE: Get: batch { keys: 2, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:48.097Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 43 200 GET /health , took 30.42 ms 2018-09-28T05:24:48.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 44 200 GET /health , took 8.52 ms 2018-09-28T05:24:49.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=146, freeMemoryMb=3949) 2018-09-28T05:24:50.089Z [RxComputationThreadPool-1]/VERBOSE: ---> req 45 GET /health 2018-09-28T05:24:50.106Z [RxComputationThreadPool-5]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:50.107Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 45 200 GET /health , took 17.49 ms 2018-09-28T05:24:51.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=146, freeMemoryMb=3949) 2018-09-28T05:24:52.143Z [RxComputationThreadPool-7]/VERBOSE: ---> req 46 GET /health 2018-09-28T05:24:52.147Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:52.160Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 46 200 GET /health , took 18.20 ms 2018-09-28T05:24:53.067Z [RxComputationThreadPool-5]/VERBOSE: ---> req 47 GET /health 2018-09-28T05:24:53.076Z [RxComputationThreadPool-1]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:53.077Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 47 200 GET /health , took 9.92 ms 2018-09-28T05:24:53.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=147, freeMemoryMb=3948) 2018-09-28T05:24:54.090Z [RxComputationThreadPool-3]/VERBOSE: ---> req 48 GET /health 2018-09-28T05:24:54.097Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:54.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 48 200 GET /health , took 7.70 ms 2018-09-28T05:24:55.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=148, freeMemoryMb=3947) 2018-09-28T05:24:56.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 49 GET /health 2018-09-28T05:24:56.107Z [RxComputationThreadPool-4]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:56.107Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 49 200 GET /health , took 18.35 ms 2018-09-28T05:24:57.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=149, freeMemoryMb=3946) 2018-09-28T05:24:58.067Z [RxComputationThreadPool-6]/VERBOSE: ---> req 50 GET /health 2018-09-28T05:24:58.086Z [RxComputationThreadPool-2]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:24:58.087Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 50 200 GET /health , took 19.76 ms 2018-09-28T05:24:58.160Z [RxComputationThreadPool-4]/VERBOSE: ---> req 51 GET /health 2018-09-28T05:24:58.177Z [RxComputationThreadPool-8]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 2 ms 2018-09-28T05:24:58.177Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 51 200 GET /health , took 88.30 ms 2018-09-28T05:24:59.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=150, freeMemoryMb=3945) 2018-09-28T05:25:00.089Z [RxComputationThreadPool-2]/VERBOSE: ---> req 52 GET /health 2018-09-28T05:25:00.096Z [RxComputationThreadPool-6]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:25:00.097Z [RxCachedThreadScheduler-1]/VERBOSE: <--- res 52 200 GET /health , took 7.91 ms 2018-09-28T05:25:01.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=151, freeMemoryMb=3944) 2018-09-28T05:25:02.089Z [RxComputationThreadPool-8]/VERBOSE: ---> req 53 GET /health 2018-09-28T05:25:02.106Z [RxComputationThreadPool-3]/VERBOSE: Get: batch { keys: 1, size: "0 B" } was processed, took 1 ms 2018-09-28T05:25:02.107Z [RxCachedThreadScheduler-2]/VERBOSE: <--- res 53 200 GET /health , took 18.04 ms 2018-09-28T05:25:03.067Z [RxComputationThreadPool-5]/VERBOSE: ---> req 54 GET /health 2018-09-28T05:25:03.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=152, freeMemoryMb=3943) 2018-09-28T05:25:03.598Z [RxComputationThreadPool-1]/W: Get: batch { keys: 1 } failed, retrying. java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:04.090Z [RxComputationThreadPool-5]/VERBOSE: ---> req 55 GET /health 2018-09-28T05:25:04.099Z [RxComputationThreadPool-3]/W: Get: batch { keys: 1 } failed, retrying. java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:04.601Z [RxComputationThreadPool-1]/E: Get: batch { keys: 1 } failed, took 1506 ms. java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:04.602Z [RxComputationThreadPool-1]/W: Cache is not healthy java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:04.615Z [RxCachedThreadScheduler-2]/W: <--- res 54 500 GET /health Not OK, took 1547.83 ms 2018-09-28T05:25:04.661Z [RxComputationThreadPool-3]/W: Get: batch { keys: 1 } failed, retrying. java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:05.162Z [RxComputationThreadPool-5]/W: Get: batch { keys: 1 } failed, retrying. java.util.concurrent.TimeoutException at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutSubscriber.onTimeout(FlowableTimeoutTimed.java:137) at io.reactivex.internal.operators.flowable.FlowableTimeoutTimed$TimeoutTask.run(FlowableTimeoutTimed.java:169) at io.reactivex.internal.schedulers.ScheduledRunnable.run(ScheduledRunnable.java:66) at io.reactivex.internal.schedulers.ScheduledRunnable.call(ScheduledRunnable.java:57) at java.util.concurrent.FutureTask.run(FutureTask.java:266) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$201(ScheduledThreadPoolExecutor.java:180) at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:293) 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) 2018-09-28T05:25:05.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=155, freeMemoryMb=3940) 2018-09-28T05:25:05.420Z [Thread-12]/I: Shutting down the server... 2018-09-28 05:25:05.462:INFO:oejs.AbstractConnector:RxCachedThreadScheduler-2: Stopped ServerConnector@113bebca{HTTP/1.1,[http/1.1]}{0.0.0.0:8080} 2018-09-28T05:25:07.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:09.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:11.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:13.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:15.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:17.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:19.367Z [RxComputationThreadPool-1]/I: JvmState = JvmState(totalMemoryMb=4096, usedMemoryMb=158, freeMemoryMb=3937) 2018-09-28T05:25:20.569Z [Thread-12]/I: Successfully shut down the server in 15149 ms ``` I doubt there is network throttling or anything like that, CPU is free, gigs of heap are free, GC is clearly not active at this moment. I believe it's a bug in Ignite, I'm out of ideas other than that -- Sent from: http://apache-ignite-users.70518.x6.nabble.com/
