GC spending too much time on elastic injest node

Hi All,

I am running elastic 5.5 and my set up is having 3 client node, [data: false, master:false] and I am sending bulk request of 15000 from Logstash to client nodes.

I have:

3 Master
3 Client
10 Data
1 Logstash

I am getting these GC logs and then the client node is not responding and hence my cronjob is restarting the elastic process:

[2017-10-31T10:18:06,109][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][348] overhead, spent [619ms] collecting in the last [1s]
[2017-10-31T10:18:07,225][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][349] overhead, spent [877ms] collecting in the last [1.1s]
[2017-10-31T10:18:08,527][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][350] overhead, spent [1.1s] collecting in the last [1.3s]
[2017-10-31T10:18:09,577][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][351] overhead, spent [864ms] collecting in the last [1s]
[2017-10-31T10:18:10,748][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][352] overhead, spent [965ms] collecting in the last [1.1s]
[2017-10-31T10:18:11,749][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][353] overhead, spent [845ms] collecting in the last [1s]
[2017-10-31T10:18:12,750][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][354] overhead, spent [403ms] collecting in the last [1s]
[2017-10-31T10:18:20,922][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][362] overhead, spent [360ms] collecting in the last [1.1s]
[2017-10-31T10:18:22,934][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][364] overhead, spent [255ms] collecting in the last [1s]
[2017-10-31T10:18:23,935][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][365] overhead, spent [401ms] collecting in the last [1s]
[2017-10-31T10:18:24,936][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][366] overhead, spent [323ms] collecting in the last [1s]
[2017-10-31T10:18:36,107][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][old][370][4] duration [7.2s], collections [1]/[8s], total [7.2s]/[7.3s], memory [14.2gb]->[13.9gb]/[14.9gb], all_pools {[young] [25.9mb]->[5.9mb]/[399.4mb]}{[survivor] [49.8mb]->[0b]/[49.8mb]}{[old] [14.1gb]->[13.9gb]/[14.5gb]}
[2017-10-31T10:18:36,108][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][370] overhead, spent [7.2s] collecting in the last [8s]
[2017-10-31T10:18:46,756][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][old][375][6] duration [6s], collections [1]/[6.6s], total [6s]/[13.4s], memory [14.6gb]->[14.5gb]/[14.9gb], all_pools {[young] [286.8mb]->[32.7mb]/[399.4mb]}{[survivor] [49.8mb]->[0b]/[49.8mb]}{[old] [14.3gb]->[14.5gb]/[14.5gb]}
[2017-10-31T10:18:46,758][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][375] overhead, spent [6.2s] collecting in the last [6.6s]
[2017-10-31T10:18:52,991][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][old][376][7] duration [6s], collections [1]/[6.2s], total [6s]/[19.4s], memory [14.5gb]->[14.8gb]/[14.9gb], all_pools {[young] [32.7mb]->[389.4mb]/[399.4mb]}{[survivor] [0b]->[0b]/[49.8mb]}{[old] [14.5gb]->[14.5gb]/[14.5gb]}
[2017-10-31T10:18:52,991][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][376] overhead, spent [6s] collecting in the last [6.2s]
[2017-10-31T10:19:01,204][INFO ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][old][377][8] duration [8.1s], collections [1]/[8.2s], total [8.1s]/[27.6s], memory [14.8gb]->[14.9gb]/[14.9gb], all_pools {[young] [389.4mb]->[399.4mb]/[399.4mb]}{[survivor] [0b]->[44.1mb]/[49.8mb]}{[old] [14.5gb]->[14.5gb]/[14.5gb]}
[2017-10-31T10:19:01,204][WARN ][o.e.m.j.JvmGcMonitorService] [client-esinjest1] [gc][377] overhead, spent [8.1s] collecting in the last [8.2s]

Here is my heap details from jmap -heap

Heap Configuration:
   MinHeapFreeRatio         = 40
   MaxHeapFreeRatio         = 70
   MaxHeapSize              = 16106127360 (15360.0MB)
   NewSize                  = 523436032 (499.1875MB)
   MaxNewSize               = 523436032 (499.1875MB)
   OldSize                  = 15582691328 (14860.8125MB)
   NewRatio                 = 2
   SurvivorRatio            = 8
   MetaspaceSize            = 21807104 (20.796875MB)
   CompressedClassSpaceSize = 1073741824 (1024.0MB)
   MaxMetaspaceSize         = 17592186044415 MB
   G1HeapRegionSize         = 0 (0.0MB)

Heap Usage:
New Generation (Eden + 1 Survivor Space):
   capacity = 471138304 (449.3125MB)
   used     = 355704016 (339.2257843017578MB)
   free     = 115434288 (110.08671569824219MB)
   75.49885309261545% used
Eden Space:
   capacity = 418840576 (399.4375MB)
   used     = 303406288 (289.3507843017578MB)
   free     = 115434288 (110.08671569824219MB)
   72.43956421261345% used
From Space:
   capacity = 52297728 (49.875MB)
   used     = 52297728 (49.875MB)
   free     = 0 (0.0MB)
   100.0% used
To Space:
   capacity = 52297728 (49.875MB)
   used     = 0 (0.0MB)
   free     = 52297728 (49.875MB)
   0.0% used
concurrent mark-sweep generation:
   capacity = 15582691328 (14860.8125MB)
   used     = 9416535272 (8980.307838439941MB)
   free     = 6166156056 (5880.504661560059MB)
   60.4294538972209% used

16820 interned Strings occupying 2487936 bytes.

Heap Histogram:

 num     #instances         #bytes  class name
----------------------------------------------
   1:       1778028     9096304592  [B
   2:        631785       72002248  [I
   3:       1263904       59104952  [Ljava.lang.Object;
   4:       1338437       58393192  [C
   5:        837308       46889248  org.elasticsearch.search.aggregations.bucket.terms.StringTerms$Bucket
   6:       1833157       43995768  java.util.ArrayList
   7:       1282186       30772464  java.lang.String
   8:       1226539       29436936  org.apache.lucene.util.BytesRef
   9:        531366       25505568  java.nio.HeapByteBuffer
  10:        318411       25472880  org.elasticsearch.search.aggregations.bucket.terms.StringTerms
  11:        518632       24894336  org.elasticsearch.search.aggregations.metrics.cardinality.HyperLogLogPlusPlus
  12:        521897       20875880  org.elasticsearch.common.util.BigArrays$ByteArrayWrapper
  13:        518632       20745280  org.elasticsearch.common.util.BigArrays$IntArrayWrapper
  14:        518632       20745280  org.elasticsearch.search.aggregations.metrics.cardinality.HyperLogLogPlusPlus$Hashset
  15:        841696       20200704  org.elasticsearch.search.aggregations.InternalAggregations
  16:       1088436       17414976  java.util.concurrent.atomic.AtomicBoolean
  17:        518634       16596288  org.apache.lucene.util.LongBitSet
  18:        518632       16596224  org.elasticsearch.search.aggregations.metrics.cardinality.InternalCardinality
  19:        557155       13371720  java.util.LinkedList$Node
  20:        526560       12683344  [J
  21:        279160        8933120  java.util.LinkedList
  22:        518632        8298112  org.elasticsearch.search.aggregations.metrics.cardinality.HyperLogLogPlusPlus$OpenBitSet
  23:        247598        7923136  java.util.HashMap$Node
  24:        141651        5666040  java.util.TreeMap$Entry
  25:        103954        4989792  org.joda.time.format.DateTimeFormatter
  26:         59324        4749648  [S
  27:         50486        4574960  [Ljava.util.HashMap$Node;
  28:        278461        4455376  org.elasticsearch.search.aggregations.bucket.terms.InternalOrder$CompoundOrder
  29:         78943        2595280  [Lorg.elasticsearch.search.aggregations.bucket.terms.StringTerms$Bucket;
  30:        104786        2514864  java.util.Arrays$ArrayList
  31:         43240        2075520  java.util.HashMap
  32:         29531        1653736  java.util.stream.ReferencePipeline$Head
  33:         20432        1307648  java.util.concurrent.ConcurrentHashMap
  34:         25624        1229952  java.util.TreeMap
  35:         18490        1183360  java.util.regex.Matcher
  36:         10713        1176256  java.lang.Class
  37:         45591        1094184  org.apache.lucene.util.SetOnce
  38:         26678        1067120  java.util.TreeMap$KeySpliterator
  39:         16556        1059584  java.util.stream.ReferencePipeline$2
  40:         32884        1052288  java.util.TreeMap$EntryIterator
  41:         15610         999040  java.util.stream.ReferencePipeline$5
  42:         28286         905152  java.util.concurrent.ConcurrentHashMap$Node
  43:          4882         898288  com.fasterxml.jackson.core.json.UTF8StreamJsonParser
  44:         21561         862440  java.util.HashMap$KeyIterator
  45:         21011         840440  java.util.HashMap$ValueIterator
  46:         25952         830464  org.elasticsearch.common.joda.FormatDateTimeFormatter
  47:         33898         813552  java.util.Collections$SetFromMap
  48:         23398         748736  java.util.AbstractList$Itr
  49:         15073         723504  com.fasterxml.jackson.core.json.JsonReadContext
  50:          8920         713600  io.netty.buffer.PooledHeapByteBuf
  51:         12380         693280  com.carrotsearch.hppc.ObjectObjectHashMap
  52:         20721         663072  java.util.Collections$UnmodifiableSortedMap
  53:         20263         648416  org.elasticsearch.common.settings.Settings
  54:         26707         643080  [Lorg.joda.time.format.InternalParser;
  55:         15610         624400  org.elasticsearch.common.settings.Settings$FilteredMap
  56:         15495         619800  io.netty.buffer.UnpooledSlicedByteBuf
  57:         18928         605696  org.elasticsearch.transport.netty4.ByteBufBytesReference
  58:          6650         585200  java.lang.reflect.Method
  59:          4824         578880  org.elasticsearch.action.index.IndexRequest
  60:         17824         570368  org.joda.time.format.DateTimeFormatterBuilder$Composite
  61:         19586         566256  [Ljava.lang.String;
  62:         13672         546880  java.util.IdentityHashMap
  63:         12915         516600  io.netty.buffer.UnpooledDuplicatedByteBuf
  64:         15610         499520  java.util.stream.ReduceOps$8
  65:         15610         499520  java.util.stream.ReduceOps$8ReducingSink
  66:         15610         499520  org.elasticsearch.common.settings.Settings$FilteredMap$1$1
  67:         30675         490800  java.util.Collections$UnmodifiableMap$UnmodifiableEntrySet$UnmodifiableEntry
  68:         20276         486624  java.util.concurrent.ConcurrentHashMap$KeySetView
  69:         19658         471792  java.lang.Long
  70:         14291         457312  io.netty.handler.codec.CodecOutputList
  71:          7847         439432  com.carrotsearch.hppc.IntObjectHashMap
  72:         17874         428976  java.util.Collections$UnmodifiableMap$UnmodifiableEntrySet$1
  73:         17786         428768  [Lorg.joda.time.format.InternalPrinter;
  74:         12906         412992  org.elasticsearch.transport.netty4.ByteBufStreamInput
  75:          5678         408816  java.util.regex.Pattern
  76:          3924         408096  org.elasticsearch.cluster.metadata.IndexMetaData
  77:            47         407536  [D
  78:         12581         402592  org.apache.lucene.search.FieldDoc
  79:         16556         397344  java.util.stream.ReferencePipeline$2$1
  80:         15610         374640  java.util.stream.ReferencePipeline$5$1
  81:         15610         374640  org.elasticsearch.common.settings.Settings$FilteredMap$1
  82:          9312         372480  java.util.HashMap$EntryIterator
  83:         11583         370656  java.lang.NumberFormatException
  84:          6490         363440  java.lang.invoke.MemberName
  85:         14823         360936

This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.