Cluster resource usage

shift · January 23, 2013, 7:13pm

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents, 33GB
(66GB replicated) in an hour during the peak load. Any suggestions on how
I can optimize the cluster? Or, do I simply need to add more nodes to the
cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57, 12.50,
9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

polyfractal · January 23, 2013, 9:14pm

Really hope some of the seasoned vets pop in and give feedback. I'm
curious what the more knowledgeable folks think.

Some thoughts (but no experience with clusters at that size):

Adding more nodes is obviously going to help performance because of
more memory/CPU, but it also has the benefit of shrinking shard size. The
larger the shard, the slower the insert (and more CPU spent merging
segments, etc). So by adding nodes, you also shrink each individual shard
size and speed up indexing.
You may consider adding a Routing-only node that is only responsible
for routing inserts to the appropriate node, so that routing to other nodes
isn't queued up behind local node performance problems. That is one of the
things that Rafał Kuć mentioned in his presentation on massive clustershttp://www.elasticsearch.org/videos/2012/06/05/scaling-massive-elasticsearch-clusters.html
If you don't need the original _source, consider disabling it. Same
thing with the _all field.
Perhaps buffer inserts in something like memcached and do bulk inserts
every few seconds?

-Zach

On Wednesday, January 23, 2013 2:13:21 PM UTC-5, shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents, 33GB
(66GB replicated) in an hour during the peak load. Any suggestions on how
I can optimize the cluster? Or, do I simply need to add more nodes to the
cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57, 12.50,
9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

drewr · January 23, 2013, 11:02pm

shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents, 33GB
(66GB replicated) in an hour during the peak load. Any suggestions on how
I can optimize the cluster? Or, do I simply need to add more nodes to the
cluster?

[...]

    "index.cache.field.type" : "soft",
    "index.refresh_interval" : "5s",
    "index.store.compress.stored" : "true",
    "index.routing.allocation.total_shards_per_node" : 3

Any particular reason for these settings? That's a very eager
refresh interval. I would also remove the allocation and soft cache,
but those may have less of an impact on indexing performance.

-Drew

--

otisg · January 24, 2013, 4:55am

Hi,

This machine seems to be chilling. It's clearly write-heavy, but there are
no disk IO waits and the CPUs are mostly idle.
I suspect something on Logastash side is the bottleneck, not ES.
Increase the number of indexers sending docs from Logstash to ES. Use bulk
indexing.
I see a bit of swap. Probably not an issue here, but consider setting
swapiness to 0.

Nothing super spectacular in here yet, but may want to keep an eye on it:
https://github.com/jordansissel/experiments/tree/master/elasticsearch/perf

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Wednesday, January 23, 2013 2:13:21 PM UTC-5, shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents, 33GB
(66GB replicated) in an hour during the peak load. Any suggestions on how
I can optimize the cluster? Or, do I simply need to add more nodes to the
cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57, 12.50,
9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

shift · January 24, 2013, 3:27pm

Is a refresh_interval of 5s too high? The default is 1s, I read in the
guide that setting this value higher can improve indexing speed.

The routing.allocation.total_shards_per_node setting of 3 is to prevent 1
node in the cluster from having too many shards (actively being written
to). I have noticed even when a node has 3 shards, the system load spikes
up to 15 and the CPU usage is at 1000%. Each shard grows to about 8GB in
an hour.

On Wednesday, January 23, 2013 6:02:31 PM UTC-5, Drew Raines wrote:

shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7
days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents,
33GB
(66GB replicated) in an hour during the peak load. Any suggestions on
how
I can optimize the cluster? Or, do I simply need to add more nodes to
the
cluster?

[...]
    "index.cache.field.type" : "soft", 
    "index.refresh_interval" : "5s", 
    "index.store.compress.stored" : "true", 
    "index.routing.allocation.total_shards_per_node" : 3 
Any particular reason for these settings? That's a very eager
refresh interval. I would also remove the allocation and soft cache,
but those may have less of an impact on indexing performance.

-Drew

--

shift · January 24, 2013, 4:18pm

I have monitored I/O on the ES cluster nodes, the disk service times and
utilization are good.

I have 30 logstash indexers writing to ES, when I have an indexer write to
stdout() (rather than the ES cluster), it processes the incoming messages
real-time. This leads me to believe the bottleneck is ES.

On Wednesday, January 23, 2013 11:55:28 PM UTC-5, Otis Gospodnetic wrote:

Hi,

This machine seems to be chilling. It's clearly write-heavy, but there
are no disk IO waits and the CPUs are mostly idle.
I suspect something on Logastash side is the bottleneck, not ES.
Increase the number of indexers sending docs from Logstash to ES. Use
bulk indexing.
I see a bit of swap. Probably not an issue here, but consider setting
swapiness to 0.

Nothing super spectacular in here yet, but may want to keep an eye on it:

https://github.com/jordansissel/experiments/tree/master/elasticsearch/perf

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Wednesday, January 23, 2013 2:13:21 PM UTC-5, shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents,
33GB (66GB replicated) in an hour during the peak load. Any suggestions on
how I can optimize the cluster? Or, do I simply need to add more nodes to
the cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57, 12.50,
9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

drewr · January 24, 2013, 4:36pm

shift wrote:

Is a refresh_interval of 5s too high? The default is 1s, I read in
the guide that setting this value higher can improve indexing
speed.

No, way too low for high performance. Experiment with values more in
the minute(s) range. I forgot the default was 1s!

The routing.allocation.total_shards_per_node setting of 3 is to
prevent 1 node in the cluster from having too many shards (actively
being written to). I have noticed even when a node has 3 shards,
the system load spikes up to 15 and the CPU usage is at 1000%.
Each shard grows to about 8GB in an hour.

This is with replicas on, right? If you turn off replicas you should
get a fairly even distribution of primary shards and alleviate this
problem.

If you don't mind, I'd like to see the output of es shards using
es2unix[1]. It would help us visualize the topology.

-Drew

Footnotes:
[1] GitHub - elastic/es2unix: Command-line ES

--

otisg · January 24, 2013, 6:09pm

Hi,

You have 4 * 24 = 96 cores total in your ES cluster?
And 30 single-threaded Logstash indexers?

If you write to stdout you are not going over the network.

If ES is the bottleneck:

turn off replicas
increase refresh interval
allow async writes
use bulk indexing

BUT, again:
If you write to stdout you are not going over the network.

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Thursday, January 24, 2013 11:18:00 AM UTC-5, shift wrote:

I have monitored I/O on the ES cluster nodes, the disk service times and
utilization are good.

I have 30 logstash indexers writing to ES, when I have an indexer write to
stdout() (rather than the ES cluster), it processes the incoming messages
real-time. This leads me to believe the bottleneck is ES.

On Wednesday, January 23, 2013 11:55:28 PM UTC-5, Otis Gospodnetic wrote:

Hi,

This machine seems to be chilling. It's clearly write-heavy, but there
are no disk IO waits and the CPUs are mostly idle.
I suspect something on Logastash side is the bottleneck, not ES.
Increase the number of indexers sending docs from Logstash to ES. Use
bulk indexing.
I see a bit of swap. Probably not an issue here, but consider setting
swapiness to 0.

Nothing super spectacular in here yet, but may want to keep an eye on it:

https://github.com/jordansissel/experiments/tree/master/elasticsearch/perf

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Wednesday, January 23, 2013 2:13:21 PM UTC-5, shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling behind
30+ minutes during peak load. There are about 69,308,904 documents,
33GB (66GB replicated) in an hour during the peak load. Any suggestions on
how I can optimize the cluster? Or, do I simply need to add more nodes to
the cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57, 12.50,
9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

jprante · January 24, 2013, 6:39pm

I would prefer measuring instead of believing

From the data you gave, ES is not the bottleneck. Server is busy, but not
overloaded.

Just to be sure, your challenge is that your indexed log files are lagging
30min behind?

How busy are the 30 logstash indexers, can you measure network traffic?

How do you take the time of a document getting visible after being
persisted in the index? By firing up queries regularly? Or by percolator?

I agree with all the tips given.

Stat your checking at the slowest part of the system, the disks. Many
factors contribute to disk speed, disk interface, setup, RAID mode,
filesystem, journal writing mode, OS VM, caching... etc etc

With bulk indexing, you can generate huge workloads and squeeze the most
indexing performance out of Elasticsearch (you can even overwhelm a cluster
if not doing it right).

Then, if you want better indexing throughput, but slower search while
indexing, you can also tune the segment
merging Elasticsearch Platform — Find real-time answers at scale | Elastic

And an advanced setting is to minimize fsync() on the translog with the
parameter index.gateway.local.sync (you can even switch it off with -1
while large bulk indexing and let the OS decide when to persist data to
disk)

Best regards,

Jörg

On Thursday, January 24, 2013 5:18:00 PM UTC+1, shift wrote:

I have monitored I/O on the ES cluster nodes, the disk service times and
utilization are good.

I have 30 logstash indexers writing to ES, when I have an indexer write to
stdout() (rather than the ES cluster), it processes the incoming messages
real-time. This leads me to believe the bottleneck is ES.

--

shift · January 24, 2013, 6:46pm

Turning off replication is not really an option, I need the redundancy. I
will try setting the replication parameter to async.

I have increased the refresh interval to 180s.

How do I allow async writes?

I'm not sure that logstash supports bulk indexing.

On Thursday, January 24, 2013 1:09:14 PM UTC-5, Otis Gospodnetic wrote:

Hi,

You have 4 * 24 = 96 cores total in your ES cluster?
And 30 single-threaded Logstash indexers?

If you write to stdout you are not going over the network.

If ES is the bottleneck:

turn off replicas

increase refresh interval

allow async writes

use bulk indexing

BUT, again:
If you write to stdout you are not going over the network.

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Thursday, January 24, 2013 11:18:00 AM UTC-5, shift wrote:

I have monitored I/O on the ES cluster nodes, the disk service times and
utilization are good.

I have 30 logstash indexers writing to ES, when I have an indexer write
to stdout() (rather than the ES cluster), it processes the incoming
messages real-time. This leads me to believe the bottleneck is ES.

On Wednesday, January 23, 2013 11:55:28 PM UTC-5, Otis Gospodnetic wrote:

Hi,

This machine seems to be chilling. It's clearly write-heavy, but there
are no disk IO waits and the CPUs are mostly idle.
I suspect something on Logastash side is the bottleneck, not ES.
Increase the number of indexers sending docs from Logstash to ES. Use
bulk indexing.
I see a bit of swap. Probably not an issue here, but consider setting
swapiness to 0.

Nothing super spectacular in here yet, but may want to keep an eye on it:

https://github.com/jordansissel/experiments/tree/master/elasticsearch/perf

Otis

ELASTICSEARCH Performance Monitoring -
Sematext Monitoring | Infrastructure Monitoring Service

On Wednesday, January 23, 2013 2:13:21 PM UTC-5, shift wrote:

I am indexing about 520GB of log files to elasticsearch a day. At this
phase I am only keeping 24 hours of data (eventually the goal is 7 days).

The incoming data is not being processed real-time, it is falling
behind 30+ minutes during peak load. There are about 69,308,904 documents,
33GB (66GB replicated) in an hour during the peak load. Any suggestions on
how I can optimize the cluster? Or, do I simply need to add more nodes to
the cluster?

Hardware:
4 node cluster, 24 CPU cores, 24GB of memory

Config:
16GB heap size, 4 shards, 1 replica

Here is the template I uses:
"template" : "logstash*",
"settings" : {
"number_of_shards" : 4,
"number_of_replicas" : 1,
"index.cache.field.type" : "soft",
"index.refresh_interval" : "5s",
"index.store.compress.stored" : "true",
"index.routing.allocation.total_shards_per_node" : 3
}

i.e. - Here is the resource usage of a node in the cluster

Very high run queue:

procs -------------------memory------------------ ---swap-- -----io----
--system-- -----cpu-------
r b swpd free buff cache si so bi bo
in cs us sy id wa st
0 0 29296 857568 115180 4170680 0 0 0 18536
2064 19307 5 0 94 0 0
16 0 29296 981432 115460 4045384 0 0 2 91284
26435 195012 32 6 61 1 0
25 0 29296 940864 115604 4086892 0 0 2 6410
19264 148894 24 4 72 0 0
26 0 29296 937804 115740 4089044 0 0 0 7610
20409 152666 24 4 72 0 0
13 0 29296 921072 115864 4108016 0 0 0 29050
19789 151698 23 4 72 0 0
10 0 29296 899636 116060 4128760 0 0 0 8922
22611 178752 29 5 66 0 0
27 0 29296 803672 116272 4223260 0 0 1300 21616
9254 59491 14 2 84 0 0
12 0 29296 703440 116476 4324696 0 0 1260 8730
21620 164412 34 5 61 0 0
2 0 29296 723592 116756 4303752 0 0 394 46396
20529 149679 27 5 68 0 0
1 0 29296 812524 117040 4215268 0 0 6 89006
30665 224822 35 7 57 1 0
23 0 29296 811320 117248 4215140 0 0 0 16118
16144 129557 20 3 76 0 0
5 3 29296 793556 117440 4230480 0 0 92 13534
17697 130477 21 3 75 0 0
18 0 29296 791652 117664 4234996 0 0 0 25726
15064 105674 16 3 81 0 0
0 0 29296 767412 117864 4257892 0 0 2 7026
23563 185956 29 5 66 0 0
32 0 29296 698344 118092 4325644 0 0 0 24436
18761 135696 26 4 70 0 0
25 0 29296 688636 118484 4333708 0 0 0 19960
21589 169049 28 5 67 0 0
16 0 29296 641116 118756 4381596 0 0 2 28256
19404 151200 27 4 68 0 0
16 0 29296 598248 118960 4425428 0 0 0 24886
20111 154420 26 4 70 0 0
0 0 29296 684804 119228 4336856 0 0 2 51210
19501 145059 23 4 72 0 0
3 0 29296 657820 119436 4351960 0 0 24 29936
21593 160447 27 5 68 0 0
10 0 29296 649772 119680 4368648 0 0 2 8284
20268 149946 23 5 72 0 0
24 0 29296 575948 119888 4443508 0 0 2 8762
19982 156834 31 5 64 0 0
12 0 29296 528372 120108 4490592 0 0 0 29946
15819 104973 19 3 77 1 0
23 0 29296 525860 120308 4495436 0 0 0 15698
21515 163041 27 5 69 0 0

i.e. - High load and CPU usage by the elasticsearch java process

top - 07:15:34 up 124 days, 13:04, 1 user, load average: 14.57,
12.50, 9.80
Tasks: 929 total, 1 running, 928 sleeping, 0 stopped, 0 zombie
Cpu0 : 36.3%us, 4.0%sy, 0.0%ni, 59.1%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu1 : 32.5%us, 7.3%sy, 0.0%ni, 54.3%id, 6.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu2 : 33.0%us, 3.6%sy, 0.0%ni, 63.4%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu3 : 34.8%us, 5.9%sy, 0.0%ni, 55.1%id, 3.9%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu4 : 36.6%us, 4.3%sy, 0.0%ni, 59.1%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu5 : 32.9%us, 5.6%sy, 0.0%ni, 59.9%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu6 : 32.7%us, 5.3%sy, 0.0%ni, 60.1%id, 1.7%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu7 : 24.0%us, 22.7%sy, 0.0%ni, 51.6%id, 1.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu8 : 33.8%us, 5.6%sy, 0.0%ni, 59.9%id, 0.7%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu9 : 36.2%us, 10.5%sy, 0.0%ni, 45.7%id, 6.2%wa, 0.0%hi, 1.3%si,
0.0%st
Cpu10 : 47.2%us, 5.0%sy, 0.0%ni, 47.5%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu11 : 33.4%us, 15.6%sy, 0.0%ni, 48.3%id, 2.0%wa, 0.0%hi, 0.7%si,
0.0%st
Cpu12 : 37.4%us, 5.3%sy, 0.0%ni, 57.3%id, 0.0%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu13 : 34.5%us, 7.9%sy, 0.0%ni, 54.3%id, 3.0%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu14 : 64.7%us, 4.6%sy, 0.0%ni, 30.4%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu15 : 30.1%us, 15.9%sy, 0.0%ni, 50.7%id, 3.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu16 : 38.7%us, 5.0%sy, 0.0%ni, 56.0%id, 0.3%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu17 : 54.5%us, 4.6%sy, 0.0%ni, 36.3%id, 4.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu18 : 39.8%us, 4.9%sy, 0.0%ni, 54.6%id, 0.3%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu19 : 34.1%us, 7.9%sy, 0.0%ni, 55.0%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu20 : 35.7%us, 11.8%sy, 0.0%ni, 49.5%id, 2.6%wa, 0.0%hi, 0.3%si,
0.0%st
Cpu21 : 45.4%us, 10.2%sy, 0.0%ni, 34.5%id, 5.3%wa, 1.0%hi, 3.6%si,
0.0%st
Cpu22 : 38.9%us, 5.6%sy, 0.0%ni, 52.8%id, 2.6%wa, 0.0%hi, 0.0%si,
0.0%st
Cpu23 : 28.9%us, 10.5%sy, 0.0%ni, 33.9%id, 0.0%wa, 3.3%hi, 23.4%si,
0.0%st
Mem: 24675936k total, 24601936k used, 74000k free, 19960k buffers
Swap: 4192880k total, 29296k used, 4163584k free, 5052000k cached

PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
17248 user 17 0 18.9g 17g 10m S 1089.8 74.3 2850:30 java

--

shift · January 24, 2013, 7:21pm

I need the logs available for searching real-time.

The indexers are busy. The Send-Q on the syslog-ng relay connections to
each logstash port are pegged at 8308860, the Recv-Q on each logstash
indexer is 7631452.

Each log message has a timestamp, I compare that to the time it was indexed.

I need the ability to search quickly while indexing.

On Thursday, January 24, 2013 1:39:36 PM UTC-5, Jörg Prante wrote:

I would prefer measuring instead of believing

From the data you gave, ES is not the bottleneck. Server is busy, but not
overloaded.

Just to be sure, your challenge is that your indexed log files are lagging
30min behind?

How busy are the 30 logstash indexers, can you measure network traffic?

How do you take the time of a document getting visible after being
persisted in the index? By firing up queries regularly? Or by percolator?

I agree with all the tips given.

Stat your checking at the slowest part of the system, the disks. Many
factors contribute to disk speed, disk interface, setup, RAID mode,
filesystem, journal writing mode, OS VM, caching... etc etc

With bulk indexing, you can generate huge workloads and squeeze the most
indexing performance out of Elasticsearch (you can even overwhelm a cluster
if not doing it right).

Then, if you want better indexing throughput, but slower search while
indexing, you can also tune the segment merging
Elasticsearch Platform — Find real-time answers at scale | Elastic

And an advanced setting is to minimize fsync() on the translog with the
parameter index.gateway.local.sync (you can even switch it off with -1
while large bulk indexing and let the OS decide when to persist data to
disk)

Best regards,

Jörg

--

otisg · January 24, 2013, 8:16pm

Hi,

Not sure what those *-Q values represent.
Check your network. I'm look at the NICs or switches or whatever you can
measure and see if they are saturated.

You are right, no bulk in Logstash ES
output: https://github.com/logstash/logstash/blob/v1.1.5/lib/logstash/outputs/elasticsearch.rb#L114
Pull for Logstash?

Another thing to look at are ES's HTTP connection counts and threads.
If you are using SPM for Elasticsearch look for the "Connections" tab.
This is where all this stuff is graphed. Compare what you see there with
your max limits in the config.

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Thursday, January 24, 2013 2:21:07 PM UTC-5, shift wrote:

I need the logs available for searching real-time.

The indexers are busy. The Send-Q on the syslog-ng relay connections to
each logstash port are pegged at 8308860, the Recv-Q on each logstash
indexer is 7631452.

Each log message has a timestamp, I compare that to the time it was
indexed.

I need the ability to search quickly while indexing.

On Thursday, January 24, 2013 1:39:36 PM UTC-5, Jörg Prante wrote:

I would prefer measuring instead of believing

From the data you gave, ES is not the bottleneck. Server is busy, but not
overloaded.

Just to be sure, your challenge is that your indexed log files are
lagging 30min behind?

How busy are the 30 logstash indexers, can you measure network traffic?

How do you take the time of a document getting visible after being
persisted in the index? By firing up queries regularly? Or by percolator?

I agree with all the tips given.

Stat your checking at the slowest part of the system, the disks. Many
factors contribute to disk speed, disk interface, setup, RAID mode,
filesystem, journal writing mode, OS VM, caching... etc etc

With bulk indexing, you can generate huge workloads and squeeze the most
indexing performance out of Elasticsearch (you can even overwhelm a cluster
if not doing it right).

Then, if you want better indexing throughput, but slower search while
indexing, you can also tune the segment merging
Elasticsearch Platform — Find real-time answers at scale | Elastic

And an advanced setting is to minimize fsync() on the translog with the
parameter index.gateway.local.sync (you can even switch it off with -1
while large bulk indexing and let the OS decide when to persist data to
disk)

Best regards,

Jörg

--

shift · January 24, 2013, 8:56pm

There is bandwidth available on the NICs. The Send-Q in this case is data
which syslog-ng has given to the transport, but has yet to be acknowledged
by the receiving end. The Recv-Q is data which has yet to be pulled from
the socket buffer by logstash.

What parameter sets the connection limit for transport.tcp.port? I see
exactly 369 connections to each node in the ES cluster on port 9700.

On Thursday, January 24, 2013 3:16:00 PM UTC-5, Otis Gospodnetic wrote:

Hi,

Not sure what those *-Q values represent.
Check your network. I'm look at the NICs or switches or whatever you can
measure and see if they are saturated.

You are right, no bulk in Logstash ES output:
https://github.com/logstash/logstash/blob/v1.1.5/lib/logstash/outputs/elasticsearch.rb#L114
Pull for Logstash?

Another thing to look at are ES's HTTP connection counts and threads.
If you are using SPM for Elasticsearch look for the "Connections" tab.
This is where all this stuff is graphed. Compare what you see there with
your max limits in the config.

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Thursday, January 24, 2013 2:21:07 PM UTC-5, shift wrote:

I need the logs available for searching real-time.

The indexers are busy. The Send-Q on the syslog-ng relay connections to
each logstash port are pegged at 8308860, the Recv-Q on each logstash
indexer is 7631452.

Each log message has a timestamp, I compare that to the time it was
indexed.

I need the ability to search quickly while indexing.

On Thursday, January 24, 2013 1:39:36 PM UTC-5, Jörg Prante wrote:

I would prefer measuring instead of believing

From the data you gave, ES is not the bottleneck. Server is busy, but
not overloaded.

Just to be sure, your challenge is that your indexed log files are
lagging 30min behind?

How busy are the 30 logstash indexers, can you measure network traffic?

How do you take the time of a document getting visible after being
persisted in the index? By firing up queries regularly? Or by percolator?

I agree with all the tips given.

Stat your checking at the slowest part of the system, the disks. Many
factors contribute to disk speed, disk interface, setup, RAID mode,
filesystem, journal writing mode, OS VM, caching... etc etc

With bulk indexing, you can generate huge workloads and squeeze the most
indexing performance out of Elasticsearch (you can even overwhelm a cluster
if not doing it right).

Then, if you want better indexing throughput, but slower search while
indexing, you can also tune the segment merging
Elasticsearch Platform — Find real-time answers at scale | Elastic

And an advanced setting is to minimize fsync() on the translog with the
parameter index.gateway.local.sync (you can even switch it off with -1
while large bulk indexing and let the OS decide when to persist data to
disk)

Best regards,

Jörg

--

radu_gheorghe · January 26, 2013, 10:21am

Hello,

AFAIK, the "elasticsearch" output of Logstash doesn't use the bulk API.
That means there's a lot of transport overhead - which might explain why
there's not a huge amount of load on ES, but on the other hand, writing on
files doesn't fall behind.

I'd suggest you try the elasticsearch_http output and play with the
flush_size, which is 100 by default.

Best regards,
Radu

http://sematext.com/ -- Elasticsearch -- Solr -- Lucene

On Thu, Jan 24, 2013 at 10:56 PM, shift brian.malia@etrade.com wrote:

There is bandwidth available on the NICs. The Send-Q in this case is data
which syslog-ng has given to the transport, but has yet to be acknowledged
by the receiving end. The Recv-Q is data which has yet to be pulled from
the socket buffer by logstash.

What parameter sets the connection limit for transport.tcp.port? I see
exactly 369 connections to each node in the ES cluster on port 9700.

On Thursday, January 24, 2013 3:16:00 PM UTC-5, Otis Gospodnetic wrote:

Hi,

Not sure what those *-Q values represent.
Check your network. I'm look at the NICs or switches or whatever you can
measure and see if they are saturated.

You are right, no bulk in Logstash ES output:
https://github.com/logstash/logstash/blob/v1.1.5/lib/logstash/outputs/elasticsearch.rb#L114
Pull for Logstash?

Another thing to look at are ES's HTTP connection counts and threads.
If you are using SPM for Elasticsearch look for the "Connections" tab.
This is where all this stuff is graphed. Compare what you see there with
your max limits in the config.

Otis

ELASTICSEARCH Performance Monitoring - Sematext Monitoring | Infrastructure Monitoring Service

On Thursday, January 24, 2013 2:21:07 PM UTC-5, shift wrote:

I need the logs available for searching real-time.

The indexers are busy. The Send-Q on the syslog-ng relay connections to
each logstash port are pegged at 8308860, the Recv-Q on each logstash
indexer is 7631452.

Each log message has a timestamp, I compare that to the time it was
indexed.

I need the ability to search quickly while indexing.

On Thursday, January 24, 2013 1:39:36 PM UTC-5, Jörg Prante wrote:

I would prefer measuring instead of believing

From the data you gave, ES is not the bottleneck. Server is busy, but
not overloaded.

Just to be sure, your challenge is that your indexed log files are
lagging 30min behind?

How busy are the 30 logstash indexers, can you measure network traffic?

How do you take the time of a document getting visible after being
persisted in the index? By firing up queries regularly? Or by percolator?

I agree with all the tips given.

Stat your checking at the slowest part of the system, the disks. Many
factors contribute to disk speed, disk interface, setup, RAID mode,
filesystem, journal writing mode, OS VM, caching... etc etc

With bulk indexing, you can generate huge workloads and squeeze the
most indexing performance out of Elasticsearch (you can even overwhelm a
cluster if not doing it right).

Then, if you want better indexing throughput, but slower search while
indexing, you can also tune the segment merging
Elasticsearch Platform — Find real-time answers at scale | Elastic

And an advanced setting is to minimize fsync() on the translog with the
parameter index.gateway.local.sync (you can even switch it off with -1
while large bulk indexing and let the OS decide when to persist data to
disk)

Best regards,

Jörg

--

--

Topic		Replies	Views
Cluster CPU usage Elasticsearch	1	314	July 6, 2017
Powerful cluster is not able to handle 1.5Tb of data, how to optimize? Elasticsearch	12	3536	July 6, 2017
How to fully utilize the resources of Elasticsearch node Elasticsearch	4	449	October 5, 2020
Help guide a noob for optimizing elasticsearch in current cluster Elasticsearch	6	613	December 6, 2018
Trying to optimize Elasticsearch cluster Elasticsearch	3	963	February 20, 2017

Cluster resource usage

Otis

Otis

Otis

Otis

Otis

Otis

Otis

Otis

Best regards, Radu

Otis

Related topics

Best regards,
Radu