KIbana - Elasticsearch : Request time out after 3000ms

Elastic Stack Elasticsearch
23

@Christian_Dahlqvist: The index structure and size is almost same. Please find below the details of the index in both the environments:

AWS
health status index uuid pri rep docs.count docs.deleted store.size pri.store.size
yellow open .kibana pygfcx4FQPmJc5Bcd6BlAQ 1 1 9 1 62.1kb 62.1kb
yellow open logstash-aws-index JsLke78KSrW0iC7JumrPSg 5 1 319984 0 200.8mb 200.8mb

On-premises
health status index uuid pri rep docs.count docs.deleted store.size pri.store.size
yellow open .kibana mnalWDcLT-uopXr8O-bfvg 1 1 64 1 112.5kb 112.5kb
yellow open logstash-stg-index 15lqbm0aQeisUZDmYk2X0w 5 1 105266 0 84mb 84mb

24

So you have more data and less heap on your AWS cluster, and it is still faster?

Is your on-prem cluster deployed on VMs? If so, is there any possibility that e.g. memory ballooning could be causing swap to be used behind the scenes, resulting in this performance difference? Are you sure the VM has access to all the resources you expect it to?

25

@Christian_Dahlqvist: Yes that's true. AWS cluster has more data and less heap and it is still fast as compare to On-premises setup.

Further On-premises we have dedicated machines not VMs.

The only difference on the CPU part is that on AWS we have

  • Core(s) per socket: 2
  • Socket(s): 1
    whereas on-premises has following value:
  • Core(s) per socket: 1
  • Socket(s): 2

Because the issue here seems to be with the I/O. Is any other thing we should look at for?

26

What kind of hardware and storage do you have on premise?

What does extended instates show?

Do you have anything else running on the hosts?

27

@Christian_Dahlqvist: I ran "iostat -x" when timeout parameter is set to 60sec instead of 30sec

bash-4.2$ iostat -x
Linux 3.10.0-327.22.2.el7.x86_64 04/09/2018 x86_64 (2 CPU)

avg-cpu: %user %nice %system %iowait %steal %idle
0.47 0.00 0.35 0.04 0.00 99.15

Device: rrqm/s wrqm/s r/s w/s rkB/s wkB/s avgrq-sz avgqu-sz await r_await w_await svctm %util
sda 0.00 3.08 0.01 2.42 0.10 33.28 27.46 0.00 1.16 3.74 1.16 0.34 0.08
sdb 0.00 0.91 0.00 0.54 0.02 15.75 58.50 0.00 1.13 5.83 1.12 0.31 0.02
dm-0 0.00 0.00 0.01 2.62 0.06 11.01 8.43 0.00 0.81 3.74 0.80 0.14 0.04
dm-1 0.00 0.00 0.00 0.00 0.00 0.00 9.05 0.00 15.02 0.54 16.77 0.36 0.00
dm-2 0.00 0.00 0.00 1.44 0.02 15.75 21.82 0.00 0.94 5.90 0.93 0.12 0.02
dm-3 0.00 0.00 0.00 2.89 0.03 22.27 15.45 0.00 1.02 3.76 1.02 0.16 0.05

28

@Christian_Dahlqvist: Also in the background we have GC Info/Warning in the logs

[2018-04-09T02:50:04,312][WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221132] overhead, spent [660ms] collecting in the last [1s]
[2018-04-09T02:50:05,361][INFO ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221133] overhead, spent [434ms] collecting in the last [1s]
[2018-04-09T02:54:55,445][WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221423] overhead, spent [561ms] collecting in the last [1s]
[2018-04-09T02:57:17,848][INFO ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221565] overhead, spent [624ms] collecting in the last [1.3s]
[2018-04-09T03:00:30,906][INFO ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221758] overhead, spent [430ms] collecting in the last [1s]
[2018-04-09T03:00:31,907][INFO ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][221759] overhead, spent [307ms] collecting in the last [1s]
[2018-04-09T03:10:28,349][WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][222355] overhead, spent [711ms] collecting in the last [1.2s]

29

[2018-04-10T01:29:10,140][WARN ][o.e.h.n.Netty4HttpServerTransport] [8-emPGV] caught exception while handling client http traffic, closing connection [id: 0xaf1ae87c, L:/10.225.40.34:9200 - R:/10.48.130.140:33132]
java.lang.IllegalArgumentException: Failed to parse value [1] as only [true] or [false] are allowed.
at org.elasticsearch.common.Booleans.parseBoolean(Booleans.java:73) ~[elasticsearch-6.1.2.jar:6.1.2]
at org.elasticsearch.common.Booleans.parseBoolean(Booleans.java:84) ~[elasticsearch-6.1.2.jar:6.1.2]
at org.elasticsearch.rest.RestRequest.paramAsBoolean(RestRequest.java:298) ~[elasticsearch-6.1.2.jar:6.1.2]
at org.elasticsearch.rest.AbstractRestChannel.(AbstractRestChannel.java:56) ~[elasticsearch-6.1.2.jar:6.1.2]
at org.elasticsearch.http.netty4.Netty4HttpChannel.(Netty4HttpChannel.java:78) ~[transport-netty4-6.1.2.jar:6.1.2]
at org.elasticsearch.http.netty4.Netty4HttpRequestHandler.channelRead0(Netty4HttpRequestHandler.java:76) ~[transport-netty4-6.1.2.jar:6.1.2]
at io.netty.channel.SimpleChannelInboundHandler.channelRead(SimpleChannelInboundHandler.java:105) ~[netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at org.elasticsearch.http.netty4.pipelining.HttpPipeliningHandler.channelRead(HttpPipeliningHandler.java:68) [transport-netty4-6.1.2.jar:6.1.2]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.handler.codec.MessageToMessageDecoder.channelRead(MessageToMessageDecoder.java:102) [netty-codec-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.fireChannelRead(AbstractChannelHandlerContext.java:340) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.DefaultChannelPipeline$HeadContext.channelRead(DefaultChannelPipeline.java:1334) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:362) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.AbstractChannelHandlerContext.invokeChannelRead(AbstractChannelHandlerContext.java:348) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.DefaultChannelPipeline.fireChannelRead(DefaultChannelPipeline.java:926) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.nio.AbstractNioByteChannel$NioByteUnsafe.read(AbstractNioByteChannel.java:134) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKey(NioEventLoop.java:644) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeysPlain(NioEventLoop.java:544) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.nio.NioEventLoop.processSelectedKeys(NioEventLoop.java:498) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.channel.nio.NioEventLoop.run(NioEventLoop.java:458) [netty-transport-4.1.13.Final.jar:4.1.13.Final]
at io.netty.util.concurrent.SingleThreadEventExecutor$5.run(SingleThreadEventExecutor.java:858) [netty-common-4.1.13.Final.jar:4.1.13.Final]
at java.lang.Thread.run(Thread.java:748) [?:1.8.0_131]

30

We found couple of things when we ran this 15 aggregations:
1 Error on Kibana UI - if we check in the developer console i.e. "TypeError: Cannot read property 'key' of undefined -kibana.bundle.js?v=16363:103 Uncaught (in promise) TypeError: Cannot read property 'key' of undefined.

2 And on Elastic Search we receive following issues:
- [WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][222355] overhead, spent [711ms] collecting in the last [1.2s]
- Sometimes it also give error:[2018-04-10T01:29:10,140][WARN ][o.e.h.n.Netty4HttpServerTransport] [8-emPGV] caught exception while handling client http traffic, closing connection [id: 0xaf1ae87c, L:/10.225.40.34:9200 - R:/10.48.130.140:33132]
java.lang.IllegalArgumentException: Failed to parse value [1] as only [true] or [false] are allowed.

31

@Christian_Dahlqvist: any advice on the above

32

I don't know. Maybe someone else will see or think of something I have missed.

33

@Christian_Dahlqvist: Thanks for your time. Is there anyone with whom i can check because we are stuck with this.

34

Now we are getting GC error continuously:

[2018-04-11T13:52:08,678][ERROR][i.n.u.ResourceLeakDetector] LEAK: ByteBuf.release() was not called before it's garbage-collected. Enable advanced leak reporting to find out where the leak occurred. To enable advanced leak reporting, specify the JVM option '-Dio.netty.leakDetection.level=advanced' or call ResourceLeakDetector.setLevel() See http://netty.io/wiki/reference-counted-objects.html for more information.
[2018-04-11T13:53:22,812][WARN ][o.e.h.n.Netty4HttpServerTransport] [elasticnode] caught exception while handling client http traffic, closing connection [id: 0x13c792d7, L:/172.26.9.22:9201 - R:/125.22.193.148:10327]

[2018-04-11T13:54:08,896][INFO ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][old][630][3] duration [6s], collections [1]/[6s], total [6s]/[6.2s], memory [3.8gb]->[1.3gb]/[3.9gb], all_pools {[young] [68.8mb]->[4.1mb]/[133.1mb]}{[survivor] [16.6mb]->[0b]/[16.6mb]}{[old] [3.8gb]->[1.3gb]/[3.8gb]}

[2018-04-11T07:23:36,634][WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][1400] overhead, spent [791ms] collecting in the last [1.1s]
[2018-04-11T07:23:37,639][WARN ][o.e.m.j.JvmGcMonitorService] [8-emPGV] [gc][1401] overhead, spent [578ms] collecting in the last [1s]

35

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