# Logstash elasticsearch output plugin takes extremely long time **URL:** \ **Category:** Logstash\ **Created:** [November 10, 2017, 2:13pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198 "2017-11-10T14:13:54Z")\ **Posts on this page:** 6\ **Page:** 1
**Author:** ![shaowencheng](https://avatars.discourse-cdn.com/v4/letter/s/c57346/32.png) [@shaowencheng](https://discuss.elastic.co/u/shaowencheng)\ **Post date:** [November 10, 2017, 2:13pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/1 "2017-11-10T14:13:54Z")
Could someone help identify the problem and advice? Thanks in advance. The following logstash stats are obtained from the logstash management API: curl –X GET [http://127.0.0.1/\_node/stats](http://127.0.0.1/_node/stats) Cluster configuration is as follows: 1 coordinating node, 1 master node, 2 data nodes Logstash & elasticsearch version 5.3.1 CentOS 7 host Each node runs on VMware VM, 2vCPU, 32GB RAM (16GB allocate to elasticsearch), 1TB HDD. Logstash runs on coordinating node, and elasticsearch output directs to coordinating node, too. Daily index, 5 shards, 1 replica. Input is syslog UDP from Sophos firewall. 1400 events/second. If I comment out elasticsearch output plugin, all events can be consumed. But when I put elasticsearch output plugin to work, throughput degrades to 130 events/second. We can see in the stats that elasticsearch output plugin duration is 1847441 millis, compared to second longest KV filter, which takes 38864 millis. { "host": "ELK3-163281032", "version": "5.6.3", "http\_address": "127.0.0.1:9600", "id": "...f", "name": "ELK3-163281032", "jvm": { "threads": { "count": 25, "peak\_count": 26 }, "mem": { "heap\_used\_percent": 11, "heap\_committed\_in\_bytes": 284299264, "heap\_max\_in\_bytes": 1056309248, "heap\_used\_in\_bytes": 120045568, "non\_heap\_used\_in\_bytes": 96202840, "non\_heap\_committed\_in\_bytes": 102518784, "pools": { "survivor": { "peak\_used\_in\_bytes": 17432576, "used\_in\_bytes": 14982408, "peak\_max\_in\_bytes": 17432576, "max\_in\_bytes": 17432576, "committed\_in\_bytes": 17432576 }, "old": { "peak\_used\_in\_bytes": 106202536, "used\_in\_bytes": 74550752, "peak\_max\_in\_bytes": 899284992, "max\_in\_bytes": 899284992, "committed\_in\_bytes": 127275008 }, "young": { "peak\_used\_in\_bytes": 139591680, "used\_in\_bytes": 30512408, "peak\_max\_in\_bytes": 139591680, "max\_in\_bytes": 139591680, "committed\_in\_bytes": 139591680 } } }, "gc": { "collectors": { "old": { "collection\_time\_in\_millis": 2312, "collection\_count": 25 }, "young": { "collection\_time\_in\_millis": 5762, "collection\_count": 140 } } }, "uptime\_in\_millis": 501144 }, "process": { "open\_file\_descriptors": 57, "peak\_open\_file\_descriptors": 60, "max\_file\_descriptors": 4096, "mem": { "total\_virtual\_in\_bytes": 3753644032 }, "cpu": { "total\_in\_millis": 236320, "percent": 37, "load\_average": { "1m": 0.39, "5m": 0.41, "15m": 0.53 } } }, "pipeline": { "events": { "duration\_in\_millis": 1927823, "in": 67748, "out": 67246, "filtered": 67746, "queue\_push\_duration\_in\_millis": 966360 }, "plugins": { "inputs": [ { "id": "...", "events": { "out": 67748, "queue\_push\_duration\_in\_millis": 966360 }, "name": "udp" } ], "filters": [ { "id": "...", "events": { "duration\_in\_millis": 12652, "in": 67746, "out": 67746 }, "matches": 67746, "patterns\_per\_field": { "message": 1 }, "name": "grok" }, { "id": "...", "events": { "duration\_in\_millis": 1939, "in": 67746, "out": 67746 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 0, "in": 0, "out": 0 }, "name": "drop" }, { "id": "...", "events": { "duration\_in\_millis": 0, "in": 1, "out": 1 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 2481, "in": 67746, "out": 67746 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 38864, "in": 67746, "out": 67746 }, "name": "kv" }, { "id": "...", "events": { "duration\_in\_millis": 0, "in": 27, "out": 27 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 3565, "in": 67746, "out": 67746 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 1456, "in": 67746, "out": 67746 }, "name": "ruby" }, { "id": "...", "events": { "duration\_in\_millis": 2544, "in": 67718, "out": 67718 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 6244, "in": 67746, "out": 67746 }, "name": "mutate" }, { "id": "...", "events": { "duration\_in\_millis": 2705, "in": 67746, "out": 67746 }, "matches": 67746, "name": "date" } ], "outputs": [ { "id": "...", "events": { "duration\_in\_millis": 1847441, "in": 67746, "out": 67246 }, "name": "elasticsearch" }, { "id": "...", "events": { "duration\_in\_millis": 589, "in": 67246, "out": 67246 }, "name": "stdout" } ] }, "reloads": { "last\_error": null, "successes": 0, "last\_success\_timestamp": null, "last\_failure\_timestamp": null, "failures": 0 }, "queue": { "type": "memory" }, "id": "main" }, "reloads": { "successes": 0, "failures": 0 }, "os": { "cgroup": { "cpuacct": { "usage\_nanos": 19844737287582, "control\_group": "/" }, "cpu": { "cfs\_quota\_micros": -1, "control\_group": "/", "stat": { "number\_of\_times\_throttled": 0, "time\_throttled\_nanos": 0, "number\_of\_elapsed\_periods": 0 }, "cfs\_period\_micros": 100000 } } } } ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [November 10, 2017, 2:27pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/2 "2017-11-10T14:27:38Z")
What does CPU usage, disk I/O and iowait look like on the Elasticsearch data nodes while indexing? What does CPU usage on the Logstash node look like when outputting to Elasticsearch via the coordinating node? ---
**Author:** ![shaowencheng](https://avatars.discourse-cdn.com/v4/letter/s/c57346/32.png) [@shaowencheng](https://discuss.elastic.co/u/shaowencheng)\ **Post date:** [November 10, 2017, 3:08pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/3 "2017-11-10T15:08:22Z")
Hi, Christian CPU usage on the Logstash node is around 40%. I will try to collect more stats from data node next Monday for your reference. BTW, will elasticsearch throttle logstash output while it is busy? Thanks for your kind help. ---
**Author:** ![Christian\_Dahlqvist](https://sea2.discourse-cdn.com/elastic/user_avatar/discuss.elastic.co/christian_dahlqvist/32/4617_2.png) [@Christian\_Dahlqvist](https://discuss.elastic.co/u/Christian_Dahlqvist)\ **Post date:** [November 10, 2017, 3:09pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/4 "2017-11-10T15:09:44Z")
Logstash will only output as fast as the slowest output, although it can buffer internally if you have a recent version and use persistent queues. ---
**Author:** ![shaowencheng](https://avatars.discourse-cdn.com/v4/letter/s/c57346/32.png) [@shaowencheng](https://discuss.elastic.co/u/shaowencheng)\ **Post date:** [November 13, 2017, 4:20pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/5 "2017-11-13T16:20:26Z")
Hi Christian, I use Zabbix to collect Logstash and Elasticsearch performance by management API, mainly \_nodes/stats. Sampling interval is 1 minute. log-cedu-02 and log-cedu-05 are both data nodes, while log-cedu-01 is coordinating node on which logstash is running. 2 hour logstash performance from 14:00 – 16:00 2017/11/13: ![P1](https://us1.discourse-cdn.com/elastic/original/3X/c/7/c72b9091470947a7bbae0942fc2ea767ed128e15.png) It seems that logstash may be blocked sometime (pipeline event count down to 0). 2 hour cluster summary is as follows: ![P2](https://us1.discourse-cdn.com/elastic/original/3X/b/c/bc4852f0cb65b2be84d6e8df39673dd783ce2e66.png) Average indexing latency corresponds to \_all.total.indexing.index\_time\_in\_millis. It is converted to minutely difference between two consecutive samples. Total rate corresponds to \_all.total.indexing.index\_total. . It is converted to minutely difference between two consecutive samples. Data node indexing is not continuous, it is in batched. Every time there is an ingest event, data node takes time to consume the batch. Input is blocked during this period. 12 hour performance is as follows: ![P3](https://us1.discourse-cdn.com/elastic/original/3X/7/e/7ec013b223a02f11ec3b26e0bfbb5d1909f6fa5d.png) Refresh ![P4](https://us1.discourse-cdn.com/elastic/original/3X/6/0/60581f25b641733c25ac7296c323cdc2794fd622.png) Merge ![P5](https://us1.discourse-cdn.com/elastic/original/3X/7/1/71b43c57b237008ceacf0563ff622c22d9c7293c.png) 2 hour GC/traffic/disk ![P6](https://us1.discourse-cdn.com/elastic/original/3X/e/d/ed385d718732eba131c9a63ef76aaea231b9335f.png) 12 hour GC/traffic/disk ![P7](https://us1.discourse-cdn.com/elastic/original/3X/e/d/ed7a58ac1f0b64b9ac5cb882948c84fd9466dc57.png) Please help advise where may go wrong ? Thanks, Shaowen ---
**Author:** ![system](https://us1.discourse-cdn.com/elastic/original/3X/1/a/1ac57faf039f6b580b3f104ef42a2a89e41014de.png) [@system](https://discuss.elastic.co/u/system)\ **Post date:** [December 11, 2017, 4:20pm UTC](https://discuss.elastic.co/t/logstash-elasticsearch-output-plugin-takes-extremely-long-time/107198/6 "2017-12-11T16:20:31Z")
This topic was automatically closed 28 days after the last reply. New replies are no longer allowed.