Elasticsearch can take more than the healthcheck timeout

[joehoyle]

Elasticsearch can take more than the healthcheck timeout

[roborourke]

For clarification how many containers do you have running when this occurs and how much memory are you allowing for Docker Machine in total?

I've never seen this as a result of anything other than running out of memory personally so I'm thinking that could be reason why it's taking so long to start up.

[joehoyle]

FYI here is one typical starting log, which takes around 80 seconds

elasticsearch_1    | [2020-06-24T13:18:39,923][INFO ][o.e.n.Node               ] [] initializing ...
elasticsearch_1    | [2020-06-24T13:18:40,572][INFO ][o.e.e.NodeEnvironment    ] [33YN504] using [1] data paths, mounts [[/usr/share/elasticsearch/data (/dev/vda1)]], net usable_space [36.5gb], net total_space [58.4gb], types [ext4]
elasticsearch_1    | [2020-06-24T13:18:40,577][INFO ][o.e.e.NodeEnvironment    ] [33YN504] heap size [495.3mb], compressed ordinary object pointers [true]
elasticsearch_1    | [2020-06-24T13:18:41,083][INFO ][o.e.n.Node               ] [33YN504] node name derived from node ID [33YN504kTLWUpfmSjTU89A]; set [node.name] to override
elasticsearch_1    | [2020-06-24T13:18:41,084][INFO ][o.e.n.Node               ] [33YN504] version[6.3.1], pid[1], build[oss/tar/eb782d0/2018-06-29T21:59:26.107521Z], OS[Linux/4.19.76-linuxkit/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/1.8.0_171/25.171-b11]
elasticsearch_1    | [2020-06-24T13:18:41,084][INFO ][o.e.n.Node               ] [33YN504] JVM arguments [-Xms1g, -Xmx1g, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Djava.io.tmpdir=/usr/share/elasticsearch/tmp, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -XX:+PrintTenuringDistribution, -XX:+PrintGCApplicationStoppedTime, -Xloggc:logs/gc.log, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=32, -XX:GCLogFileSize=64m, -Des.cgroups.hierarchy.override=/, -Xms512m, -Xmx512m, -Des.path.home=/usr/share/elasticsearch, -Des.path.conf=/usr/share/elasticsearch/config, -Des.distribution.flavor=oss, -Des.distribution.type=tar]
elasticsearch_1    | [2020-06-24T13:18:50,439][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [aggs-matrix-stats]
elasticsearch_1    | [2020-06-24T13:18:50,439][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [analysis-common]
elasticsearch_1    | [2020-06-24T13:18:50,440][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [ingest-common]
elasticsearch_1    | [2020-06-24T13:18:50,441][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-expression]
elasticsearch_1    | [2020-06-24T13:18:50,441][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-mustache]
elasticsearch_1    | [2020-06-24T13:18:50,447][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-painless]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [mapper-extras]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [parent-join]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [percolator]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [rank-eval]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [reindex]
elasticsearch_1    | [2020-06-24T13:18:50,448][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [repository-url]
elasticsearch_1    | [2020-06-24T13:18:50,449][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [transport-netty4]
elasticsearch_1    | [2020-06-24T13:18:50,449][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [tribe]
elasticsearch_1    | [2020-06-24T13:18:50,451][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-icu]
elasticsearch_1    | [2020-06-24T13:18:50,453][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-kuromoji]
elasticsearch_1    | [2020-06-24T13:18:50,453][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-phonetic]
elasticsearch_1    | [2020-06-24T13:18:50,454][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-smartcn]
elasticsearch_1    | [2020-06-24T13:18:50,455][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-stempel]
elasticsearch_1    | [2020-06-24T13:18:50,455][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-ukrainian]
elasticsearch_1    | [2020-06-24T13:18:50,456][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [ingest-attachment]
elasticsearch_1    | [2020-06-24T13:18:50,457][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [ingest-user-agent]
elasticsearch_1    | [2020-06-24T13:18:50,457][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [mapper-murmur3]
elasticsearch_1    | [2020-06-24T13:18:50,458][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [mapper-size]
elasticsearch_1    | [2020-06-24T13:19:34,358][INFO ][o.e.d.DiscoveryModule    ] [33YN504] using discovery type [single-node]
elasticsearch_1    | [2020-06-24T13:19:43,517][INFO ][o.e.n.Node               ] [33YN504] initialized
elasticsearch_1    | [2020-06-24T13:19:43,521][INFO ][o.e.n.Node               ] [33YN504] starting ...
elasticsearch_1    | [2020-06-24T13:19:46,443][INFO ][o.e.t.TransportService   ] [33YN504] publish_address {172.18.0.12:9300}, bound_addresses {0.0.0.0:9300}
elasticsearch_1    | [2020-06-24T13:19:46,868][INFO ][o.e.h.n.Netty4HttpServerTransport] [33YN504] publish_address {172.18.0.12:9200}, bound_addresses {0.0.0.0:9200}
elasticsearch_1    | [2020-06-24T13:19:46,868][INFO ][o.e.n.Node               ] [33YN504] started
elasticsearch_1    | [2020-06-24T13:19:53,653][WARN ][o.e.d.i.a.ShingleTokenFilterFactory] Deprecated big difference between maxShingleSize and minShingleSize in Shingle TokenFilter,expected difference must be less than or equal to: [3]
elasticsearch_1    | [2020-06-24T13:19:56,409][INFO ][o.e.g.GatewayService     ] [33YN504] recovered [5] indices into cluster_state
elasticsearch_1    | [2020-06-24T13:19:59,970][WARN ][o.e.d.i.a.ShingleTokenFilterFactory] Deprecated big difference between maxShingleSize and minShingleSize in Shingle TokenFilter,expected difference must be less than or equal to: [3]
elasticsearch_1    | [2020-06-24T13:20:00,982][INFO ][o.e.c.r.a.AllocationService] [33YN504] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[devaltisdev-1][0]] ...]).

However, inconcistyently it can take a lot longer, no change (just ran stop & start, seems to almost alternatate), we can see it takes > 110 seconds:

elasticsearch_1    | [2020-06-24T13:29:37,514][INFO ][o.e.n.Node               ] [] initializing ...
elasticsearch_1    | [2020-06-24T13:29:39,717][INFO ][o.e.e.NodeEnvironment    ] [33YN504] using [1] data paths, mounts [[/usr/share/elasticsearch/data (/dev/vda1)]], net usable_space [36.5gb], net total_space [58.4gb], types [ext4]
elasticsearch_1    | [2020-06-24T13:29:39,725][INFO ][o.e.e.NodeEnvironment    ] [33YN504] heap size [495.3mb], compressed ordinary object pointers [true]
elasticsearch_1    | [2020-06-24T13:29:41,003][INFO ][o.e.n.Node               ] [33YN504] node name derived from node ID [33YN504kTLWUpfmSjTU89A]; set [node.name] to override
elasticsearch_1    | [2020-06-24T13:29:41,009][INFO ][o.e.n.Node               ] [33YN504] version[6.3.1], pid[1], build[oss/tar/eb782d0/2018-06-29T21:59:26.107521Z], OS[Linux/4.19.76-linuxkit/amd64], JVM[Oracle Corporation/OpenJDK 64-Bit Server VM/1.8.0_171/25.171-b11]
elasticsearch_1    | [2020-06-24T13:29:41,009][INFO ][o.e.n.Node               ] [33YN504] JVM arguments [-Xms1g, -Xmx1g, -XX:+UseConcMarkSweepGC, -XX:CMSInitiatingOccupancyFraction=75, -XX:+UseCMSInitiatingOccupancyOnly, -XX:+AlwaysPreTouch, -Xss1m, -Djava.awt.headless=true, -Dfile.encoding=UTF-8, -Djna.nosys=true, -XX:-OmitStackTraceInFastThrow, -Dio.netty.noUnsafe=true, -Dio.netty.noKeySetOptimization=true, -Dio.netty.recycler.maxCapacityPerThread=0, -Dlog4j.shutdownHookEnabled=false, -Dlog4j2.disable.jmx=true, -Djava.io.tmpdir=/usr/share/elasticsearch/tmp, -XX:+HeapDumpOnOutOfMemoryError, -XX:HeapDumpPath=data, -XX:ErrorFile=logs/hs_err_pid%p.log, -XX:+PrintGCDetails, -XX:+PrintGCDateStamps, -XX:+PrintTenuringDistribution, -XX:+PrintGCApplicationStoppedTime, -Xloggc:logs/gc.log, -XX:+UseGCLogFileRotation, -XX:NumberOfGCLogFiles=32, -XX:GCLogFileSize=64m, -Des.cgroups.hierarchy.override=/, -Xms512m, -Xmx512m, -Des.path.home=/usr/share/elasticsearch, -Des.path.conf=/usr/share/elasticsearch/config, -Des.distribution.flavor=oss, -Des.distribution.type=tar]
elasticsearch_1    | [2020-06-24T13:30:01,034][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [aggs-matrix-stats]
elasticsearch_1    | [2020-06-24T13:30:01,034][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [analysis-common]
elasticsearch_1    | [2020-06-24T13:30:01,034][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [ingest-common]
elasticsearch_1    | [2020-06-24T13:30:01,034][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-expression]
elasticsearch_1    | [2020-06-24T13:30:01,035][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-mustache]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [lang-painless]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [mapper-extras]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [parent-join]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [percolator]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [rank-eval]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [reindex]
elasticsearch_1    | [2020-06-24T13:30:01,036][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [repository-url]
elasticsearch_1    | [2020-06-24T13:30:01,037][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [transport-netty4]
elasticsearch_1    | [2020-06-24T13:30:01,037][INFO ][o.e.p.PluginsService     ] [33YN504] loaded module [tribe]
elasticsearch_1    | [2020-06-24T13:30:01,051][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-icu]
elasticsearch_1    | [2020-06-24T13:30:01,051][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-kuromoji]
elasticsearch_1    | [2020-06-24T13:30:01,052][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-phonetic]
elasticsearch_1    | [2020-06-24T13:30:01,053][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-smartcn]
elasticsearch_1    | [2020-06-24T13:30:01,110][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-stempel]
elasticsearch_1    | [2020-06-24T13:30:01,110][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [analysis-ukrainian]
elasticsearch_1    | [2020-06-24T13:30:01,111][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [ingest-attachment]
elasticsearch_1    | [2020-06-24T13:30:01,116][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [ingest-user-agent]
elasticsearch_1    | [2020-06-24T13:30:01,118][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [mapper-murmur3]
elasticsearch_1    | [2020-06-24T13:30:01,119][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [mapper-size]
elasticsearch_1    | [2020-06-24T13:31:03,345][INFO ][o.e.d.DiscoveryModule    ] [33YN504] using discovery type [single-node]
elasticsearch_1    | [2020-06-24T13:31:10,450][INFO ][o.e.n.Node               ] [33YN504] initialized
elasticsearch_1    | [2020-06-24T13:31:10,452][INFO ][o.e.n.Node               ] [33YN504] starting ...
elasticsearch_1    | [2020-06-24T13:31:11,526][INFO ][o.e.t.TransportService   ] [33YN504] publish_address {172.18.0.12:9300}, bound_addresses {0.0.0.0:9300}
elasticsearch_1    | [2020-06-24T13:31:12,667][INFO ][o.e.h.n.Netty4HttpServerTransport] [33YN504] publish_address {172.18.0.12:9200}, bound_addresses {0.0.0.0:9200}
elasticsearch_1    | [2020-06-24T13:31:12,667][INFO ][o.e.n.Node               ] [33YN504] started
elasticsearch_1    | [2020-06-24T13:31:13,538][WARN ][o.e.d.i.a.ShingleTokenFilterFactory] Deprecated big difference between maxShingleSize and minShingleSize in Shingle TokenFilter,expected difference must be less than or equal to: [3]
elasticsearch_1    | [2020-06-24T13:31:14,843][INFO ][o.e.m.j.JvmGcMonitorService] [33YN504] [gc][4] overhead, spent [435ms] collecting in the last [1.3s]
elasticsearch_1    | [2020-06-24T13:31:20,355][INFO ][o.e.g.GatewayService     ] [33YN504] recovered [5] indices into cluster_state
elasticsearch_1    | [2020-06-24T13:31:26,999][WARN ][o.e.d.i.a.ShingleTokenFilterFactory] Deprecated big difference between maxShingleSize and minShingleSize in Shingle TokenFilter,expected difference must be less than or equal to: [3]
elasticsearch_1    | [2020-06-24T13:31:28,342][INFO ][o.e.c.r.a.AllocationService] [33YN504] Cluster health status changed from [RED] to [YELLOW] (reason: [shards started [[devaltisdev-1][2], [devaltisdev-1][1], [devaltisdev-1][4]] ...]).

Consistently it seems there is a large lag of time between log entries:

elasticsearch_1    | [2020-06-24T13:30:01,119][INFO ][o.e.p.PluginsService     ] [33YN504] loaded plugin [mapper-size]
elasticsearch_1    | [2020-06-24T13:31:03,345][INFO ][o.e.d.DiscoveryModule    ] [33YN504] using discovery type [single-node]

I don't know if this is mapper-size being slow, if it loaded plugin is a post-process message. I've seen a total of 22 failures on the healthcheck (22*5 seconds = 110 seconds) so we'd need to at least lift the retries to 25 until we can speed up ES.

[roborourke]

The mapper size plugin was only recently added, after this issue was originally opened at least so I'm not sure it's definitely that but we can compare start up times with the previous version of the ES container to rule it out or in.