ES v1.1 continuous young gc pauses old gc, stops the world when old gc happens and splits cluster

Ankush_Jhalani · April 16, 2014, 6:57pm

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took 1.7
minutes which caused nodes to disconnect (3 pings of 30 seconds failed).
Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149283][9270] duration [782ms], collections [1]/[1s], total
[782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb], all_pools {[young]
[1gb]->[147mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old] [20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149284][9271] duration [743ms], collections [1]/[1.7s], total
[743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb], all_pools {[young]
[147mb]->[10.1mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149285][9272] duration [786ms], collections [1]/[1.5s], total
[786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb], all_pools {[young]
[10.1mb]->[2.8mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149287][9273] duration [835ms], collections [1]/[1s], total
[835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb], all_pools {[young]
[655.9mb]->[1.2mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149290][9274] duration [786ms], collections [1]/[1.7m], total
[786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old] [2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ] [ny1.node2]
[gc][old][149290][25] duration [1.7m], collections [2]/[1.7m], total
[1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the old gc
was put on pause for so long and why did it take so much when it finally
ran? We currently use Java 7 update 10, would the latest 51 help? Would
switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/2bb88e62-4240-442e-b3aa-16cfd7817550%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Dominiek_ter_Heide · April 16, 2014, 9:31pm

We are seeing the same issue here.

Our environment:

2 nodes
30GB Heap allocated to ES
~140GB of data
639 indices, 10 shards per index
~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [elasticsearch2.
trend1] bound_address {inet[/0.0.0.0:9200]}, publish_address {inet[/192.99.
45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4] to [
50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from [
200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4] to [
50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m], collections [
1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[29.9gb], all_pools
{[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [60.5mb]->[0b]/[83.1mb
]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][13996][144] duration [1.4m], collections [1]/[1.4m],total
[1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb], all_pools {[young] [21.8mb
]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b]/[83.1mb]}{[old] [28.7gb
]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][14603][155] duration [1.3m], collections [2]/[1.3m],total
[1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb], all_pools {[young] [289mb
]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b]/[83.1mb]}{[old] [28.8gb
]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][14745][158] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb], all_pools {[young] [
633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[0b]/[83.1mb]}{[old] [
29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][14857][161] duration [1.4m], collections [1]/[1.4m],total
[1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb], all_pools {[young] [
27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb]}{[old] [
28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][14978][164] duration [1.4m], collections [1]/[1.4m],total
[1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb], all_pools {[young] [
475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[0b]/[83.1mb]}{[old] [
28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15021][165] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb], all_pools {[young] [
391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[0b]/[83.1mb]}{[old] [
28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15170][168] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb], all_pools {[young] [
320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[0b]/[83.1mb]}{[old] [
29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15221][169] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[12.6m], memory [29.1gb]->[25.4gb]/[29.9gb], all_pools {[young] [25mb
]->[194.1mb]/[665.6mb]}{[survivor] [36.3mb]->[0b]/[83.1mb]}{[old] [29gb]->[
25.2gb]/[29.1gb]}

[2014-04-16 16:36:30,468][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15352][172] duration [1.3m], collections [2]/[1.3m],total
[1.3m]/[14m], memory [29.2gb]->[23.7gb]/[29.9gb], all_pools {[young] [
176.8mb]->[192.9mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb]}{[old] [
28.9gb]->[23.5gb]/[29.1gb]}

[2014-04-16 16:40:10,961][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15488][175] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[15.3m], memory [29.3gb]->[24.7gb]/[29.9gb], all_pools {[young] [
383.2mb]->[149.4mb]/[665.6mb]}{[survivor] [23.1mb]->[0b]/[83.1mb]}{[old] [
28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:42:21,572][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15530][176] duration [1.3m], collections [1]/[1.4m],total
[1.3m]/[16.7m], memory [29.7gb]->[25.9gb]/[29.9gb], all_pools {[young] [
614.8mb]->[347mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb]}{[old] [29gb
]->[25.5gb]/[29.1gb]}

[2014-04-16 16:48:02,263][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15782][181] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[18.1m], memory [29.4gb]->[25.1gb]/[29.9gb], all_pools {[young] [
399mb]->[143.4mb]/[665.6mb]}{[survivor] [51.1mb]->[0b]/[83.1mb]}{[old] [29gb
]->[24.9gb]/[29.1gb]}

[2014-04-16 16:51:10,090][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15884][183] duration [1.3m], collections [1]/[1.4m],total
[1.3m]/[19.5m], memory [29.4gb]->[25.6gb]/[29.9gb], all_pools {[young] [
554.7mb]->[194.2mb]/[665.6mb]}{[survivor] [48.1mb]->[0b]/[83.1mb]}{[old] [
28.8gb]->[25.4gb]/[29.1gb]}

[2014-04-16 16:53:19,220][WARN ][monitor.jvm ] [elasticsearch2.
trend1] [gc][old][15930][184] duration [1.3m], collections [1]/[1.3m],total
[1.3m]/[20.8m], memory [29.1gb]->[25.9gb]/[29.9gb], all_pools {[young] [
27.3mb]->[335.9mb]/[665.6mb]}{[survivor] [64.4mb]->[0b]/[83.1mb]}{[old] [
29gb]->[25.6gb]/[29.1gb]}

Which then results in the other node not being able to connect anymore:

[2014-04-16 16:36:30,433][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [79996ms]ago
, timed out [49996ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6139231]

[2014-04-16 16:36:30,433][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [49996ms]ago
, timed out [19996ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6140170]

[2014-04-16 16:40:10,934][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [79139ms]ago
, timed out [49139ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6191341]

[2014-04-16 16:40:10,934][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [49138ms]ago
, timed out [19107ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6191679]

[2014-04-16 16:42:21,506][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [83223ms]ago
, timed out [53223ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6206126]

[2014-04-16 16:42:21,506][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [53223ms]ago
, timed out [23223ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6206535]

[2014-04-16 16:48:02,238][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [81402ms]ago
, timed out [51402ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6292721]

[2014-04-16 16:48:02,239][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [51403ms]ago
, timed out [21338ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6293381]

[2014-04-16 16:51:10,053][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [82555ms]ago
, timed out [52510ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6331039]

[2014-04-16 16:51:10,053][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [52510ms]ago
, timed out [22510ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6331356]

[2014-04-16 16:53:19,190][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [82194ms]ago
, timed out [52194ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6349594]

[2014-04-16 16:53:19,190][WARN ][transport ] [elasticsearch1.
trend1] Received response for a request that has timed out, sent [52194ms]ago
, timed out [22194ms] ago, action [discovery/zen/fd/ping], node [[
elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6356292]

Any insights will be greatly appreciated,

Dominiek

On Wednesday, April 16, 2014 8:57:47 PM UTC+2, Ankush Jhalani wrote:

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took 1.7
minutes which caused nodes to disconnect (3 pings of 30 seconds failed).
Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149283][9270] duration [782ms], collections [1]/[1s], total
[782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb], all_pools {[young]
[1gb]->[147mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old] [20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149284][9271] duration [743ms], collections [1]/[1.7s], total
[743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb], all_pools {[young]
[147mb]->[10.1mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149285][9272] duration [786ms], collections [1]/[1.5s], total
[786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb], all_pools {[young]
[10.1mb]->[2.8mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149287][9273] duration [835ms], collections [1]/[1s], total
[835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb], all_pools {[young]
[655.9mb]->[1.2mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149290][9274] duration [786ms], collections [1]/[1.7m], total
[786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old] [2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ] [ny1.node2]
[gc][old][149290][25] duration [1.7m], collections [2]/[1.7m], total
[1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the old gc
was put on pause for so long and why did it take so much when it finally
ran? We currently use Java 7 update 10, would the latest 51 help? Would
switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

warkolm · April 17, 2014, 12:00am

In both your instances, if you can, have 3 master eligible nodes as it will
reduce the likelihood of a split cluster as you will always have a majority
quorum. Also look at discovery.zen.minimum_master_nodes to go with that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide dominiekth@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from[
200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],all_pools
{[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b]/[83.1mb
]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],all_pools
{[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b]/[83.1mb
]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],all_pools
{[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[0b]/[83.1mb
]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],all_pools
{[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],all_pools
{[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[0b]/[83.1mb
]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],all_pools
{[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[0b]/[83.1mb
]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],all_pools
{[young] [320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[0b]/[83.1mb
]}{[old] [29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15221][169] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[12.6m], memory [29.1gb]->[25.4gb]/[29.9gb],all_pools
{[young] [25mb]->[194.1mb]/[665.6mb]}{[survivor] [36.3mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.2gb]/[29.1gb]}

[2014-04-16 16:36:30,468][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15352][172] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[14m], memory [29.2gb]->[23.7gb]/[29.9gb],all_pools
{[young] [176.8mb]->[192.9mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [28.9gb]->[23.5gb]/[29.1gb]}

[2014-04-16 16:40:10,961][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15488][175] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[15.3m], memory [29.3gb]->[24.7gb]/[29.9gb],all_pools
{[young] [383.2mb]->[149.4mb]/[665.6mb]}{[survivor] [23.1mb]->[0b]/[83.1mb
]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:42:21,572][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15530][176] duration [1.3m], collections
[1]/[1.4m], total [1.3m]/[16.7m], memory [29.7gb]->[25.9gb]/[29.9gb],all_pools
{[young] [614.8mb]->[347mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.5gb]/[29.1gb]}

[2014-04-16 16:48:02,263][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15782][181] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[18.1m], memory [29.4gb]->[25.1gb]/[29.9gb],all_pools
{[young] [399mb]->[143.4mb]/[665.6mb]}{[survivor] [51.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[24.9gb]/[29.1gb]}

[2014-04-16 16:51:10,090][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15884][183] duration [1.3m], collections
[1]/[1.4m], total [1.3m]/[19.5m], memory [29.4gb]->[25.6gb]/[29.9gb],all_pools
{[young] [554.7mb]->[194.2mb]/[665.6mb]}{[survivor] [48.1mb]->[0b]/[83.1mb
]}{[old] [28.8gb]->[25.4gb]/[29.1gb]}

[2014-04-16 16:53:19,220][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15930][184] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[20.8m], memory [29.1gb]->[25.9gb]/[29.9gb],all_pools
{[young] [27.3mb]->[335.9mb]/[665.6mb]}{[survivor] [64.4mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.6gb]/[29.1gb]}

Which then results in the other node not being able to connect anymore:

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[79996ms] ago, timed out [49996ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6139231]

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[49996ms] ago, timed out [19996ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6140170]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[79139ms] ago, timed out [49139ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6191341]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[49138ms] ago, timed out [19107ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6191679]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[83223ms] ago, timed out [53223ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6206126]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[53223ms] ago, timed out [23223ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6206535]

[2014-04-16 16:48:02,238][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[81402ms] ago, timed out [51402ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6292721]

[2014-04-16 16:48:02,239][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[51403ms] ago, timed out [21338ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6293381]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[82555ms] ago, timed out [52510ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6331039]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[52510ms] ago, timed out [22510ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6331356]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[82194ms] ago, timed out [52194ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6349594]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out,sent
[52194ms] ago, timed out [22194ms] ago, action [discovery/zen/fd/ping],node
[[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][elasticsearch2.trend1.
bottlenose.com][inet[/192.99.45.126:9300]]], id [6356292]

Any insights will be greatly appreciated,

Dominiek

On Wednesday, April 16, 2014 8:57:47 PM UTC+2, Ankush Jhalani wrote:

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took 1.7
minutes which caused nodes to disconnect (3 pings of 30 seconds failed).
Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149283][9270] duration [782ms], collections [1]/[1s], total
[782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb], all_pools {[young]
[1gb]->[147mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149284][9271] duration [743ms], collections [1]/[1.7s], total
[743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb], all_pools {[young]
[147mb]->[10.1mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149285][9272] duration [786ms], collections [1]/[1.5s], total
[786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb], all_pools {[young]
[10.1mb]->[2.8mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149287][9273] duration [835ms], collections [1]/[1s], total
[835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb], all_pools {[young]
[655.9mb]->[1.2mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149290][9274] duration [786ms], collections [1]/[1.7m], total
[786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ] [ny1.node2]
[gc][old][149290][25] duration [1.7m], collections [2]/[1.7m], total
[1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the old
gc was put on pause for so long and why did it take so much when it finally
ran? We currently use Java 7 update 10, would the latest 51 help? Would
switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com?utm_medium=email&utm_source=footer
.
For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Brian_Flad · April 21, 2014, 2:32pm

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom markw@campaignmonitor.comwrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide dominiekth@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125
:9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec]
from [200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],all_pools
{[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b]/[83.1mb
]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],all_pools
{[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b]/[83.1mb
]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],all_pools
{[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],all_pools
{[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],all_pools
{[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],all_pools
{[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],all_pools
{[young] [320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15221][169] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[12.6m], memory [29.1gb]->[25.4gb]/[29.9gb],all_pools
{[young] [25mb]->[194.1mb]/[665.6mb]}{[survivor] [36.3mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.2gb]/[29.1gb]}

[2014-04-16 16:36:30,468][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15352][172] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[14m], memory [29.2gb]->[23.7gb]/[29.9gb],all_pools
{[young] [176.8mb]->[192.9mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[23.5gb]/[29.1gb]}

[2014-04-16 16:40:10,961][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15488][175] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[15.3m], memory [29.3gb]->[24.7gb]/[29.9gb],all_pools
{[young] [383.2mb]->[149.4mb]/[665.6mb]}{[survivor] [23.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:42:21,572][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15530][176] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[16.7m], memory [29.7gb]->[25.9gb]/[29.9gb],all_pools
{[young] [614.8mb]->[347mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.5gb]/[29.1gb]}

[2014-04-16 16:48:02,263][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15782][181] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[18.1m], memory [29.4gb]->[25.1gb]/[29.9gb],all_pools
{[young] [399mb]->[143.4mb]/[665.6mb]}{[survivor] [51.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[24.9gb]/[29.1gb]}

[2014-04-16 16:51:10,090][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15884][183] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[19.5m], memory [29.4gb]->[25.6gb]/[29.9gb],all_pools
{[young] [554.7mb]->[194.2mb]/[665.6mb]}{[survivor] [48.1mb]->[0b]/[
83.1mb]}{[old] [28.8gb]->[25.4gb]/[29.1gb]}

[2014-04-16 16:53:19,220][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15930][184] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[20.8m], memory [29.1gb]->[25.9gb]/[29.9gb],all_pools
{[young] [27.3mb]->[335.9mb]/[665.6mb]}{[survivor] [64.4mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.6gb]/[29.1gb]}

Which then results in the other node not being able to connect anymore:

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [79996ms] ago, timed out [49996ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6139231]

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [49996ms] ago, timed out [19996ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6140170]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [79139ms] ago, timed out [49139ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191341]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [49138ms] ago, timed out [19107ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191679]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [83223ms] ago, timed out [53223ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206126]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [53223ms] ago, timed out [23223ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206535]

[2014-04-16 16:48:02,238][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [81402ms] ago, timed out [51402ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6292721]

[2014-04-16 16:48:02,239][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [51403ms] ago, timed out [21338ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6293381]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [82555ms] ago, timed out [52510ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331039]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [52510ms] ago, timed out [22510ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331356]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [82194ms] ago, timed out [52194ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6349594]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed out
, sent [52194ms] ago, timed out [22194ms] ago, action [discovery/zen/fd/
ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6356292]

Any insights will be greatly appreciated,

Dominiek

On Wednesday, April 16, 2014 8:57:47 PM UTC+2, Ankush Jhalani wrote:

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took
1.7 minutes which caused nodes to disconnect (3 pings of 30 seconds
failed). Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149283][9270] duration [782ms], collections [1]/[1s], total
[782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb], all_pools {[young]
[1gb]->[147mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149284][9271] duration [743ms], collections [1]/[1.7s], total
[743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb], all_pools {[young]
[147mb]->[10.1mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149285][9272] duration [786ms], collections [1]/[1.5s], total
[786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb], all_pools {[young]
[10.1mb]->[2.8mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149287][9273] duration [835ms], collections [1]/[1s], total
[835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb], all_pools {[young]
[655.9mb]->[1.2mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149290][9274] duration [786ms], collections [1]/[1.7m], total
[786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ] [ny1.node2]
[gc][old][149290][25] duration [1.7m], collections [2]/[1.7m], total
[1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the old
gc was put on pause for so long and why did it take so much when it finally
ran? We currently use Java 7 update 10, would the latest 51 help? Would
switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--

Brian Flad

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAF3hLz%3DQwe8k8UcG60W4bvkrmts6fk_ofuyh-6hqROn0JcwGCw%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

warkolm · April 21, 2014, 10:33pm

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bflad417@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom markw@campaignmonitor.comwrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25
but we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide dominiekth@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.
45.125:9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec]
from [200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],all_pools
{[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b]/[
83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],all_pools
{[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b]/[83.1mb
]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],all_pools
{[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],all_pools
{[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],all_pools
{[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],all_pools
{[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],all_pools
{[young] [320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15221][169] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[12.6m], memory [29.1gb]->[25.4gb]/[29.9gb],all_pools
{[young] [25mb]->[194.1mb]/[665.6mb]}{[survivor] [36.3mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.2gb]/[29.1gb]}

[2014-04-16 16:36:30,468][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15352][172] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[14m], memory [29.2gb]->[23.7gb]/[29.9gb],all_pools
{[young] [176.8mb]->[192.9mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[23.5gb]/[29.1gb]}

[2014-04-16 16:40:10,961][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15488][175] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[15.3m], memory [29.3gb]->[24.7gb]/[29.9gb],all_pools
{[young] [383.2mb]->[149.4mb]/[665.6mb]}{[survivor] [23.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:42:21,572][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15530][176] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[16.7m], memory [29.7gb]->[25.9gb]/[29.9gb],all_pools
{[young] [614.8mb]->[347mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.5gb]/[29.1gb]}

[2014-04-16 16:48:02,263][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15782][181] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[18.1m], memory [29.4gb]->[25.1gb]/[29.9gb],all_pools
{[young] [399mb]->[143.4mb]/[665.6mb]}{[survivor] [51.1mb]->[0b]/[83.1mb
]}{[old] [29gb]->[24.9gb]/[29.1gb]}

[2014-04-16 16:51:10,090][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15884][183] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[19.5m], memory [29.4gb]->[25.6gb]/[29.9gb],all_pools
{[young] [554.7mb]->[194.2mb]/[665.6mb]}{[survivor] [48.1mb]->[0b]/[
83.1mb]}{[old] [28.8gb]->[25.4gb]/[29.1gb]}

[2014-04-16 16:53:19,220][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15930][184] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[20.8m], memory [29.1gb]->[25.9gb]/[29.9gb],all_pools
{[young] [27.3mb]->[335.9mb]/[665.6mb]}{[survivor] [64.4mb]->[0b]/[
83.1mb]}{[old] [29gb]->[25.6gb]/[29.1gb]}

Which then results in the other node not being able to connect anymore:

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [79996ms] ago, timed out [49996ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6139231]

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [49996ms] ago, timed out [19996ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6140170]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [79139ms] ago, timed out [49139ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191341]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [49138ms] ago, timed out [19107ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191679]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [83223ms] ago, timed out [53223ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206126]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [53223ms] ago, timed out [23223ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206535]

[2014-04-16 16:48:02,238][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [81402ms] ago, timed out [51402ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6292721]

[2014-04-16 16:48:02,239][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [51403ms] ago, timed out [21338ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6293381]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [82555ms] ago, timed out [52510ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331039]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [52510ms] ago, timed out [22510ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331356]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [82194ms] ago, timed out [52194ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6349594]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [52194ms] ago, timed out [22194ms] ago, action [discovery/zen/
fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6356292]

Any insights will be greatly appreciated,

Dominiek

On Wednesday, April 16, 2014 8:57:47 PM UTC+2, Ankush Jhalani wrote:

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took
1.7 minutes which caused nodes to disconnect (3 pings of 30 seconds
failed). Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149283][9270] duration [782ms], collections [1]/[1s], total
[782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb], all_pools {[young]
[1gb]->[147mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149284][9271] duration [743ms], collections [1]/[1.7s], total
[743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb], all_pools {[young]
[147mb]->[10.1mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149285][9272] duration [786ms], collections [1]/[1.5s], total
[786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb], all_pools {[young]
[10.1mb]->[2.8mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149287][9273] duration [835ms], collections [1]/[1s], total
[835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb], all_pools {[young]
[655.9mb]->[1.2mb]/[1.1gb]}{[survivor] [149.7mb]->[149.7mb]/[149.7mb]
}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ] [ny1.node2]
[gc][young][149290][9274] duration [786ms], collections [1]/[1.7m], total
[786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ] [ny1.node2]
[gc][old][149290][25] duration [1.7m], collections [2]/[1.7m], total
[1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the old
gc was put on pause for so long and why did it take so much when it finally
ran? We currently use Java 7 update 10, would the latest 51 help? Would
switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google
Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send
an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--

Brian Flad
Brian Flad - Philadelphia | about.me

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAF3hLz%3DQwe8k8UcG60W4bvkrmts6fk_ofuyh-6hqROn0JcwGCw%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAF3hLz%3DQwe8k8UcG60W4bvkrmts6fk_ofuyh-6hqROn0JcwGCw%40mail.gmail.com?utm_medium=email&utm_source=footer
.
For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAEM624YF5-XtG2DMPzBjpwq4U7tF4NRJZD0Cq9w%2BTsGVzXJZUg%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Brian_Flad · April 22, 2014, 2:04am

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom markw@campaignmonitor.comwrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bflad417@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2
min master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom markw@campaignmonitor.comwrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means
the best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25
but we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: markw@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide dominiekth@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we
see the Heap build up towards 96% on one node and 80% on the other. We then
see the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.
45.125:9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec]
from [200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],all_pools
{[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b]/[
83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],all_pools
{[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b]/[
83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],all_pools
{[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],all_pools
{[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m],collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],all_pools
{[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],all_pools
{[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],all_pools
{[young] [320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15221][169] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[12.6m], memory [29.1gb]->[25.4gb]/[29.9gb],all_pools
{[young] [25mb]->[194.1mb]/[665.6mb]}{[survivor] [36.3mb]->[0b]/[83.1mb
]}{[old] [29gb]->[25.2gb]/[29.1gb]}

[2014-04-16 16:36:30,468][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15352][172] duration [1.3m],collections
[2]/[1.3m], total [1.3m]/[14m], memory [29.2gb]->[23.7gb]/[29.9gb],all_pools
{[young] [176.8mb]->[192.9mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[23.5gb]/[29.1gb]}

[2014-04-16 16:40:10,961][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15488][175] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[15.3m], memory [29.3gb]->[24.7gb]/[29.9gb],all_pools
{[young] [383.2mb]->[149.4mb]/[665.6mb]}{[survivor] [23.1mb]->[0b]/[
83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:42:21,572][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15530][176] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[16.7m], memory [29.7gb]->[25.9gb]/[29.9gb],all_pools
{[young] [614.8mb]->[347mb]/[665.6mb]}{[survivor] [83.1mb]->[0b]/[
83.1mb]}{[old] [29gb]->[25.5gb]/[29.1gb]}

[2014-04-16 16:48:02,263][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15782][181] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[18.1m], memory [29.4gb]->[25.1gb]/[29.9gb],all_pools
{[young] [399mb]->[143.4mb]/[665.6mb]}{[survivor] [51.1mb]->[0b]/[
83.1mb]}{[old] [29gb]->[24.9gb]/[29.1gb]}

[2014-04-16 16:51:10,090][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15884][183] duration [1.3m],collections
[1]/[1.4m], total [1.3m]/[19.5m], memory [29.4gb]->[25.6gb]/[29.9gb],all_pools
{[young] [554.7mb]->[194.2mb]/[665.6mb]}{[survivor] [48.1mb]->[0b]/[
83.1mb]}{[old] [28.8gb]->[25.4gb]/[29.1gb]}

[2014-04-16 16:53:19,220][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15930][184] duration [1.3m],collections
[1]/[1.3m], total [1.3m]/[20.8m], memory [29.1gb]->[25.9gb]/[29.9gb],all_pools
{[young] [27.3mb]->[335.9mb]/[665.6mb]}{[survivor] [64.4mb]->[0b]/[
83.1mb]}{[old] [29gb]->[25.6gb]/[29.1gb]}

Which then results in the other node not being able to connect anymore:

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [79996ms] ago, timed out [49996ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6139231]

[2014-04-16 16:36:30,433][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [49996ms] ago, timed out [19996ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6140170]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [79139ms] ago, timed out [49139ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191341]

[2014-04-16 16:40:10,934][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [49138ms] ago, timed out [19107ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6191679]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [83223ms] ago, timed out [53223ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206126]

[2014-04-16 16:42:21,506][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [53223ms] ago, timed out [23223ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6206535]

[2014-04-16 16:48:02,238][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [81402ms] ago, timed out [51402ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6292721]

[2014-04-16 16:48:02,239][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [51403ms] ago, timed out [21338ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6293381]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [82555ms] ago, timed out [52510ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331039]

[2014-04-16 16:51:10,053][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [52510ms] ago, timed out [22510ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6331356]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [82194ms] ago, timed out [52194ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6349594]

[2014-04-16 16:53:19,190][WARN ][transport ] [
elasticsearch1.trend1] Received response for a request that has timed
out, sent [52194ms] ago, timed out [22194ms] ago, action [discovery/zen
/fd/ping], node [[elasticsearch2.trend1][I3EHG_XjSayz2OsHyZpeZA][
elasticsearch2.trend1.bottlenose.com][inet[/192.99.45.126:9300]]], id [
6356292]

Any insights will be greatly appreciated,

Dominiek

On Wednesday, April 16, 2014 8:57:47 PM UTC+2, Ankush Jhalani wrote:

We have a 4 node (2 client only, 2 data/master nodes with 25G memory
allocated to ES and 12 cores each) ES cluster, storing an index with 16
shards, ~200GB and 1 replica.

Recently running scan/scroll requests to dump data and other faceting
requests, the nodes disconnected from each and we had a split condition.
All requests were being run sequentially, not in parellel. From the logs we
notice that for 5-10 minutes, just the young gc was running even though old
memory and total memory used was over 75% (which I think is the default
CMSInitiatingOccupancyFraction=75). When finally old gc ran, it took
1.7 minutes which caused nodes to disconnect (3 pings of 30 seconds
failed). Below are some of the last traces from log -

[2014-04-15 22:07:33,526][INFO ][monitor.jvm ]
[ny1.node2] [gc][young][149283][9270] duration [782ms], collections
[1]/[1s], total [782ms]/[8.2m], memory [21.5gb]->[20.8gb]/[24.8gb],
all_pools {[young] [1gb]->[147mb]/[1.1gb]}{[survivor]
[149.7mb]->[149.7mb]/[149.7mb]}{[old] [20
.3gb]->[20.5gb]/[23.5gb]}
[2014-04-15 22:07:35,264][INFO ][monitor.jvm ]
[ny1.node2] [gc][young][149284][9271] duration [743ms], collections
[1]/[1.7s], total [743ms]/[8.2m], memory [20.8gb]->[20.8gb]/[24.8gb],
all_pools {[young] [147mb]->[10.1mb]/[1.1gb]}{[survivor]
[149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.5gb]->[20.6gb]/[23.5gb]}
[2014-04-15 22:07:36,814][INFO ][monitor.jvm ]
[ny1.node2] [gc][young][149285][9272] duration [786ms], collections
[1]/[1.5s], total [786ms]/[8.2m], memory [20.8gb]->[20.9gb]/[24.8gb],
all_pools {[young] [10.1mb]->[2.8mb]/[1.1gb]}{[survivor]
[149.7mb]->[149.7mb]/[149.7mb]}{[old
] [20.6gb]->[20.8gb]/[23.5gb]}
[2014-04-15 22:07:38,880][INFO ][monitor.jvm ]
[ny1.node2] [gc][young][149287][9273] duration [835ms], collections
[1]/[1s], total [835ms]/[8.2m], memory [21.5gb]->[21.1gb]/[24.8gb],
all_pools {[young] [655.9mb]->[1.2mb]/[1.1gb]}{[survivor]
[149.7mb]->[149.7mb]/[149.7mb]}{[old]
[20.7gb]->[20.9gb]/[23.5gb]}
[2014-04-15 22:09:24,215][INFO ][monitor.jvm ]
[ny1.node2] [gc][young][149290][9274] duration [786ms], collections
[1]/[1.7m], total [786ms]/[8.3m], memory [21.7gb]->[2.4gb]/[24.8gb],
all_pools {[young] [727.2mb]->[13.8mb]/[1.1gb]}{[survivor]
[149.7mb]->[0b]/[149.7mb]}{[old] [2
0.8gb]->[2.4gb]/[23.5gb]}
[2014-04-15 22:09:24,215][WARN ][monitor.jvm ]
[ny1.node2] [gc][old][149290][25] duration [1.7m], collections [2]/[1.7m],
total [1.7m]/[1.7m], memory [21.7gb]->[2.4gb]/[24.8gb], all_pools {[young]
[727.2mb]->[13.8mb]/[1.1gb]}{[survivor] [149.7mb]->[0b]/[149.7mb]}{[old]
[20.8gb]
->[2.4gb]/[23.5gb]}

CPU usage was pretty low on the machine, but it's confusing why the
old gc was put on pause for so long and why did it take so much when it
finally ran? We currently use Java 7 update 10, would the latest 51 help?
Would switching to GC1 help ?

Thanks!

--
You received this message because you are subscribed to the Google
Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send
an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com https://groups.google.com/d/msgid/elasticsearch/029d1fb5-f429-4d51-a11f-13ac645c78f9%40googlegroups.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google
Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send
an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAEM624YEjDcMaOCoN5sPc8FdsqC1%2BHPi%3D37i4fJj14_ZxYQdOA%40mail.gmail.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--

Brian Flad
Brian Flad - Philadelphia | about.me

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAF3hLz%3DQwe8k8UcG60W4bvkrmts6fk_ofuyh-6hqROn0JcwGCw%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAF3hLz%3DQwe8k8UcG60W4bvkrmts6fk_ofuyh-6hqROn0JcwGCw%40mail.gmail.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/CAEM624YF5-XtG2DMPzBjpwq4U7tF4NRJZD0Cq9w%2BTsGVzXJZUg%40mail.gmail.com https://groups.google.com/d/msgid/elasticsearch/CAEM624YF5-XtG2DMPzBjpwq4U7tF4NRJZD0Cq9w%2BTsGVzXJZUg%40mail.gmail.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--

Brian Flad

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAF3hLzk2MGx7-9dfiVs_LfB%2BUArLL%2BszFn6MgusvpYs7pkq2Aw%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Eric_Brandes · June 18, 2014, 6:02pm

I'd just like to chime in with a "me too". Is the answer just more nodes?
In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom <ma...@campaignmonitor.com
<javascript:>> wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com <javascript:>
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad <bfla...@gmail.com <javascript:>>
wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom <ma...@campaignmonitor.com
<javascript:>> wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com <javascript:>
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide <domin...@gmail.com
<javascript:>> wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b
]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],
all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],
all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],
all_pools {[young] [320.3mb]->[186.7mb]/[665.6mb]}{[survivor] [75.7mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24.4gb]/[29.1gb]}

[2014-04-16 16:32:57,505][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15221<span style="c

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/718203bc-9a99-4dce-8723-0c6000454d83%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Bruce_Ritchie · June 19, 2014, 8:05pm

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b
]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],
all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],
all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[29.9gb],
all_pools {[young] [320.3mb]->[186.7mb<span style="col

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/9d76b349-2607-4fff-82c5-c0bdcd636807%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Michael_Hart · June 20, 2014, 1:40pm

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay smaller
(is that even a legitimate sentence?) I'm still reading through this page the
Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.
look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything more
I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2
min master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25
but we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125
:9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec]
from [200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[
29.9gb], all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [
82.4mb]->[0b]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m],
collections [2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[
29.9gb], all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [
58.3mb]->[0b]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m],
collections [1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[
29.9gb], all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [
68.6mb]->[0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[
29.9gb], all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [
83.1mb]->[0b]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[
29.9gb], all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [
68.9mb]->[0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m],
collections [1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[
29.9gb], all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [
62.4mb]->[0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m],
collections [1]/[1.3m], total [1.3m]/[11.3m], memory [29.4gb]->[24.6gb]/[
29.9gb], all_pools {[young] [320.3mb]->[186.7mb<span style="col

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/5bf568eb-103e-4fee-8bd2-ba2b5bc76178%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Ankush_Jhalani · June 20, 2014, 1:47pm

Mike - The above sounds like happened due to machines sending too many
indexing requests and merging unable to keep up pace. Usual suspects would
be not enough cpu/disk speed bandwidth.
This doesn't sound related to memory constraints posted in the original
issue of this thread. Do you see memory GC traces in logs?

On Friday, June 20, 2014 9:40:48 AM UTC-4, Michael Hart wrote:

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay
smaller (is that even a legitimate sentence?) I'm still reading through
this page the Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.

look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything more
I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b
]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],
all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],
all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:30:45,393][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15170][168] duration [1.3m], collections
[<span style="color:#066

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/9055ca7f-9987-4206-b14e-2319d080cded%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Michael_Hart · June 20, 2014, 2:03pm

Thanks I do see the GC warnings in the logs, such as

[2014-06-19 20:17:06,603][WARN ][monitor.jvm ] [redacted] [gc][
old][179386][22718] duration [11.4s], collections [1]/[12.2s], total [11.4s
]/[25.2m], memory [7.1gb]->[6.9gb]/[7.2gb], all_pools {[young] [158.7mb]->[
7.4mb]/[266.2mb]}{[survivor] [32.4mb]->[0b]/[33.2mb]}{[old] [6.9gb]->[6.9gb
]/[6.9gb]}

CPU Idle is around 50% when the merge starts, and drops to zero by the time
that first GC old warning is logged. During recovery my SSD's sustain 2400
IOPS and during yesterday's outage I only see about 800 IOPS before ES
died. While I can throw more hardware at it, I'd prefer to do some tuning
first if possible.

The reason I was thinking of adding more shards is that largest segment is
4.9GB (just under the default maximum set
by index.merge.policy.max_merged_segment). I suppose the other option is to
reduce the index.merge.policy.max_merged_segment setting to something
smaller, but I have no idea what the implications are.

thoughts?
mike

On Friday, June 20, 2014 9:47:22 AM UTC-4, Ankush Jhalani wrote:

Mike - The above sounds like happened due to machines sending too many
indexing requests and merging unable to keep up pace. Usual suspects would
be not enough cpu/disk speed bandwidth.
This doesn't sound related to memory constraints posted in the original
issue of this thread. Do you see memory GC traces in logs?

On Friday, June 20, 2014 9:40:48 AM UTC-4, Michael Hart wrote:

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay
smaller (is that even a legitimate sentence?) I'm still reading through
this page the Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.

look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything more
I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go with
that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating
[cluster.routing.allocation.node_initial_primaries_recoveries] from [4]
to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b
]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],
all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [68.9mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[29.9gb],
all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [62.4mb]->[
0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb<span style="color:#660"

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/67faa2c6-0b15-4382-a889-e047efb8200e%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Clinton_Gormley · June 20, 2014, 10:31pm

Do you have swap disabled? (any swap plays havoc with GC)
You said you're doing scan/scroll - how many documents are you retrieving
at a time? Consider reducing the number
Are you running on a VM - that can cause you to swap even though your VM
guest thinks that swap is disabled, or steal CPU (slowing down GC)

Essentially, if all of the above are false, you shouldn't be getting slow
GCs unless you're under very heavy memory pressure (and I see that your old
gen is not too bad, so that doesn't look likely).

On 20 June 2014 16:03, Michael Hart hart.mike@gmail.com wrote:

Thanks I do see the GC warnings in the logs, such as

[2014-06-19 20:17:06,603][WARN ][monitor.jvm ] [redacted] [gc
][old][179386][22718] duration [11.4s], collections [1]/[12.2s], total [
11.4s]/[25.2m], memory [7.1gb]->[6.9gb]/[7.2gb], all_pools {[young] [
158.7mb]->[7.4mb]/[266.2mb]}{[survivor] [32.4mb]->[0b]/[33.2mb]}{[old] [
6.9gb]->[6.9gb]/[6.9gb]}

CPU Idle is around 50% when the merge starts, and drops to zero by the
time that first GC old warning is logged. During recovery my SSD's sustain
2400 IOPS and during yesterday's outage I only see about 800 IOPS before ES
died. While I can throw more hardware at it, I'd prefer to do some tuning
first if possible.

The reason I was thinking of adding more shards is that largest segment is
4.9GB (just under the default maximum set
by index.merge.policy.max_merged_segment). I suppose the other option is to
reduce the index.merge.policy.max_merged_segment setting to something
smaller, but I have no idea what the implications are.

thoughts?
mike

On Friday, June 20, 2014 9:47:22 AM UTC-4, Ankush Jhalani wrote:

Mike - The above sounds like happened due to machines sending too many
indexing requests and merging unable to keep up pace. Usual suspects would
be not enough cpu/disk speed bandwidth.
This doesn't sound related to memory constraints posted in the original
issue of this thread. Do you see memory GC traces in logs?

On Friday, June 20, 2014 9:40:48 AM UTC-4, Michael Hart wrote:

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay
smaller (is that even a legitimate sentence?) I'm still reading through
this page the Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.

look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything
more I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2
min master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go
with that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25
but we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125
:9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec]
from [200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[
29.9gb], all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [
82.4mb]->[0b]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m],
collections [2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[
29.9gb], all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [
58.3mb]->[0b]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m],
collections [1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[
29.9gb], all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [
68.6mb]->[0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[
29.9gb], all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [
83.1mb]->[0b]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m],
collections [1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[
29.9gb], all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor] [
68.9mb]->[0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb]}

[2014-04-16 16:26:54,801][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][15021][165] duration [1.3m],
collections [1]/[1.3m], total [1.3m]/[9.9m], memory [29.3gb]->[24.8gb]/[
29.9gb], all_pools {[young] [391.8mb]->[151.1mb]/[665.6mb]}{[survivor] [
62.4mb]->[0b]/[83.1mb]}{[old] [28.9gb]->[24.6gb]/[29.1gb<span
style="color:#660"

...

--
You received this message because you are subscribed to the Google Groups
"elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an
email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit
https://groups.google.com/d/msgid/elasticsearch/67faa2c6-0b15-4382-a889-e047efb8200e%40googlegroups.com
https://groups.google.com/d/msgid/elasticsearch/67faa2c6-0b15-4382-a889-e047efb8200e%40googlegroups.com?utm_medium=email&utm_source=footer
.

For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/CAPt3XKT1sz3%2BYx3p-4R-3yabUhc4XM6H2croRXAijqUBk6uCUA%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.

Michael_Hart · June 23, 2014, 2:25pm

My nodes are in Rackspace, so they are VM's, but they are configured
without swap.

I'm not entirely sure what the searches are up to, I'm going to investigate
that further.

I did correlate a rapid increase in Heap used, number of segments (up from
the norm of ~400 to 15,000) and consequently Old GC counts when the cluster
attempts to merge a 5GB segment. It seems that in spite of my really fast
disk the merge of a 5GB segment takes up to 15 minutes. I've made two
changes this morning, namely set these:

index.merge.scheduler.max_thread_count: 3
index.merge.policy.max_merged_segment: 1gb

The first is in the hope that while a large segment merge is underway, the
two other threads can still keep the small segment merges going. The second
is to keep the larger segment merges under control. I was ending up with
two 5GB segments, and a long tail of smaller ones. A quick model shows that
by dropping this to 1GB I'll have 12 x 1GB segments and a similar long tail
of smaller segments (about 50?).

I've also enabled GC logging on one node, I'll leave it running for the day
and tomorrow remove the "-XX+UseCMSInitiatingOccupancyOnly" flag (used by
default for elasticsearch) and see if there's any difference. I'll report
back here incase this is of any use for anyone.

thanks
mike

On Friday, June 20, 2014 6:31:54 PM UTC-4, Clinton Gormley wrote:

Do you have swap disabled? (any swap plays havoc with GC)

You said you're doing scan/scroll - how many documents are you
retrieving at a time? Consider reducing the number

Are you running on a VM - that can cause you to swap even though your VM
guest thinks that swap is disabled, or steal CPU (slowing down GC)

Essentially, if all of the above are false, you shouldn't be getting slow
GCs unless you're under very heavy memory pressure (and I see that your old
gen is not too bad, so that doesn't look likely).

On 20 June 2014 16:03, Michael Hart <hart...@gmail.com <javascript:>>
wrote:

Thanks I do see the GC warnings in the logs, such as

[2014-06-19 20:17:06,603][WARN ][monitor.jvm ] [redacted] [gc
][old][179386][22718] duration [11.4s], collections [1]/[12.2s], total [
11.4s]/[25.2m], memory [7.1gb]->[6.9gb]/[7.2gb], all_pools {[young] [
158.7mb]->[7.4mb]/[266.2mb]}{[survivor] [32.4mb]->[0b]/[33.2mb]}{[old] [
6.9gb]->[6.9gb]/[6.9gb]}

CPU Idle is around 50% when the merge starts, and drops to zero by the
time that first GC old warning is logged. During recovery my SSD's sustain
2400 IOPS and during yesterday's outage I only see about 800 IOPS before ES
died. While I can throw more hardware at it, I'd prefer to do some tuning
first if possible.

The reason I was thinking of adding more shards is that largest segment is
4.9GB (just under the default maximum set
by index.merge.policy.max_merged_segment). I suppose the other option is to
reduce the index.merge.policy.max_merged_segment setting to something
smaller, but I have no idea what the implications are.

thoughts?
mike

On Friday, June 20, 2014 9:47:22 AM UTC-4, Ankush Jhalani wrote:

Mike - The above sounds like happened due to machines sending too many
indexing requests and merging unable to keep up pace. Usual suspects would
be not enough cpu/disk speed bandwidth.
This doesn't sound related to memory constraints posted in the original
issue of this thread. Do you see memory GC traces in logs?

On Friday, June 20, 2014 9:40:48 AM UTC-4, Michael Hart wrote:

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay
smaller (is that even a legitimate sentence?) I'm still reading through
this page the Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.

look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything more
I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go
with that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] [27.7mb]->[154.8mb]/[665.6mb]}{[survivor] [83.1mb]->[0b
]/[83.1mb]}{[old] [28.5gb]->[24.3gb]/[29.1gb]}

[2014-04-16 16:24:48,776][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14978][164] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[8.6m], memory [29.4gb]->[24.7gb]/[29.9gb],
all_pools {[young] [475.5mb]->[125.1mb]/[665.6mb]}{[survivor</span

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/eb01d60c-b073-4f11-8395-83c59794751d%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Michael_Hart · June 24, 2014, 12:53pm

Removing the "-XX+UseCMSInitiatingOccupancyOnly" flag extended the time it
took before the JVM started full GC's from about 2 hours to 7 hours in my
cluster, but now it's back to constant full GC's. I'm out of ideas.
Suggestions?

mike

On Monday, June 23, 2014 10:25:20 AM UTC-4, Michael Hart wrote:

My nodes are in Rackspace, so they are VM's, but they are configured
without swap.

I'm not entirely sure what the searches are up to, I'm going to
investigate that further.

I did correlate a rapid increase in Heap used, number of segments (up from
the norm of ~400 to 15,000) and consequently Old GC counts when the cluster
attempts to merge a 5GB segment. It seems that in spite of my really fast
disk the merge of a 5GB segment takes up to 15 minutes. I've made two
changes this morning, namely set these:

index.merge.scheduler.max_thread_count: 3
index.merge.policy.max_merged_segment: 1gb

The first is in the hope that while a large segment merge is underway, the
two other threads can still keep the small segment merges going. The second
is to keep the larger segment merges under control. I was ending up with
two 5GB segments, and a long tail of smaller ones. A quick model shows that
by dropping this to 1GB I'll have 12 x 1GB segments and a similar long tail
of smaller segments (about 50?).

I've also enabled GC logging on one node, I'll leave it running for the
day and tomorrow remove the "-XX+UseCMSInitiatingOccupancyOnly" flag (used
by default for elasticsearch) and see if there's any difference. I'll
report back here incase this is of any use for anyone.

thanks
mike

On Friday, June 20, 2014 6:31:54 PM UTC-4, Clinton Gormley wrote:

Do you have swap disabled? (any swap plays havoc with GC)

You said you're doing scan/scroll - how many documents are you
retrieving at a time? Consider reducing the number

Are you running on a VM - that can cause you to swap even though your VM
guest thinks that swap is disabled, or steal CPU (slowing down GC)

Essentially, if all of the above are false, you shouldn't be getting slow
GCs unless you're under very heavy memory pressure (and I see that your old
gen is not too bad, so that doesn't look likely).

On 20 June 2014 16:03, Michael Hart hart...@gmail.com wrote:

Thanks I do see the GC warnings in the logs, such as

[2014-06-19 20:17:06,603][WARN ][monitor.jvm ] [redacted] [gc
][old][179386][22718] duration [11.4s], collections [1]/[12.2s], total [
11.4s]/[25.2m], memory [7.1gb]->[6.9gb]/[7.2gb], all_pools {[young] [
158.7mb]->[7.4mb]/[266.2mb]}{[survivor] [32.4mb]->[0b]/[33.2mb]}{[old] [
6.9gb]->[6.9gb]/[6.9gb]}

CPU Idle is around 50% when the merge starts, and drops to zero by the
time that first GC old warning is logged. During recovery my SSD's sustain
2400 IOPS and during yesterday's outage I only see about 800 IOPS before ES
died. While I can throw more hardware at it, I'd prefer to do some tuning
first if possible.

The reason I was thinking of adding more shards is that largest segment is
4.9GB (just under the default maximum set
by index.merge.policy.max_merged_segment). I suppose the other option is to
reduce the index.merge.policy.max_merged_segment setting to something
smaller, but I have no idea what the implications are.

thoughts?
mike

On Friday, June 20, 2014 9:47:22 AM UTC-4, Ankush Jhalani wrote:

Mike - The above sounds like happened due to machines sending too many
indexing requests and merging unable to keep up pace. Usual suspects would
be not enough cpu/disk speed bandwidth.
This doesn't sound related to memory constraints posted in the original
issue of this thread. Do you see memory GC traces in logs?

On Friday, June 20, 2014 9:40:48 AM UTC-4, Michael Hart wrote:

We're seeing the same thing. ES 1.1.0, JDK 7u55 on Ubuntu 12.04, 5 data
nodes, 3 separate masters, all are 15GB hosts with 7.5GB Heaps, storage is
SSD. Data set is ~1.6TB according to Marvel.

Our daily indices are roughly 33GB in size, with 5 shards and 2 replicas.
I'm still investigating what happened yesterday, but I do see in Marvel a
large spike in the "Indices Current Merges" graph just before the node
dies, and a corresponding increase in JVM Heap. When Heap hits 99%
everything grinds to a halt. Restarting the node "fixes" the issue, but
this is third or fourth time it's happened.

I'm still researching how to deal with this, but a couple of things I am
looking at are:

increase the number of shards so that the segment merges stay
smaller (is that even a legitimate sentence?) I'm still reading through
this page the Index Module Merge page
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-merge.html for
more details.

look at store level throttling
http://www.elasticsearch.org/guide/en/elasticsearch/reference/current/index-modules-store.html#store-throttling
.

I would love to get some feedback on my ramblings. If I find anything more
I'll update this thread.

cheers
mike

On Thursday, June 19, 2014 4:05:54 PM UTC-4, Bruce Ritchie wrote:

Java 8 with G1GC perhaps? It'll have more overhead but perhaps it'll be
more consistent wrt pauses.

On Wednesday, June 18, 2014 2:02:24 PM UTC-4, Eric Brandes wrote:

I'd just like to chime in with a "me too". Is the answer just more
nodes? In my case this is happening every week or so.

On Monday, April 21, 2014 9:04:33 PM UTC-5, Brian Flad wrote:

My dataset currently is 100GB across a few "daily" indices (~5-6GB and 15
shards each). Data nodes are 12 CPU, 12GB RAM (6GB heap).

On Mon, Apr 21, 2014 at 6:33 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

How big are your data sets? How big are your nodes?

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 22 April 2014 00:32, Brian Flad bfla...@gmail.com wrote:

We're seeing the same behavior with 1.1.1, JDK 7u55, 3 master nodes (2 min
master), and 5 data nodes. Interestingly, we see the repeated young GCs
only on a node or two at a time. Cluster operations (such as recovering
unassigned shards) grinds to a halt. After restarting a GCing node,
everything returns to normal operation in the cluster.

Brian F

On Wed, Apr 16, 2014 at 8:00 PM, Mark Walkom ma...@campaignmonitor.com
wrote:

In both your instances, if you can, have 3 master eligible nodes as it
will reduce the likelihood of a split cluster as you will always have a
majority quorum. Also look at discovery.zen.minimum_master_nodes to go
with that.
However you may just be reaching the limit of your nodes, which means the
best option is to add another node (which also neatly solves your split
brain!).

Ankush it would help if you can update java, most people recommend u25 but
we run u51 with no problems.

Regards,
Mark Walkom

Infrastructure Engineer
Campaign Monitor
email: ma...@campaignmonitor.com
web: www.campaignmonitor.com

On 17 April 2014 07:31, Dominiek ter Heide domin...@gmail.com wrote:

We are seeing the same issue here.

Our environment:

2 nodes

30GB Heap allocated to ES

~140GB of data

639 indices, 10 shards per index

~48M documents

After starting ES everything is good, but after a couple of hours we see
the Heap build up towards 96% on one node and 80% on the other. We then see
the GC take very long on the 96% node:

TOuKgmlzaVaFVA][elasticsearch1.trend1.bottlenose.com][inet[/192.99.45.125:
9300]]])

[2014-04-16 12:04:27,845][INFO ][discovery ]
[elasticsearch2.trend1] trend1/I3EHG_XjSayz2OsHyZpeZA

[2014-04-16 12:04:27,850][INFO ][http ] [
elasticsearch2.trend1] bound_address {inet[/0.0.0.0:9200]},
publish_address {inet[/192.99.45.126:9200]}

[2014-04-16 12:04:27,851][INFO ][node ]
[elasticsearch2.trend1] started

[2014-04-16 12:04:32,669][INFO ][indices.store ]
[elasticsearch2.trend1] updating indices.store.throttle.max_bytes_per_sec
from [20mb] to [1gb], note, type is [MERGE]

[2014-04-16 12:04:32,669][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][indices.recovery ]
[elasticsearch2.trend1] updating [indices.recovery.max_bytes_per_sec] from
[200mb] to [2gb]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 12:04:32,670][INFO ][cluster.routing.allocation.decider]
[elasticsearch2.trend1] updating [cluster.routing.allocation.
node_initial_primaries_recoveries] from [4] to [50]

[2014-04-16 15:25:21,409][WARN ][monitor.jvm ]
[elasticsearch2.trend1] [gc][old][11876][106] duration [1.1m],
collections [1]/[1.1m], total [1.1m]/[1.4m], memory [28.7gb]->[22gb]/[
29.9gb], all_pools {[young] [67.9mb]->[268.9mb]/[665.6mb]}{[survivor] [
60.5mb]->[0b]/[83.1mb]}{[old] [28.6gb]->[21.8gb]/[29.1gb]}

[2014-04-16 16:02:32,523][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][13996][144] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[3m], memory [28.8gb]->[23.5gb]/[29.9gb],
all_pools {[young] [21.8mb]->[238.2mb]/[665.6mb]}{[survivor] [82.4mb]->[0b
]/[83.1mb]}{[old] [28.7gb]->[23.3gb]/[29.1gb]}

[2014-04-16 16:14:12,386][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14603][155] duration [1.3m], collections
[2]/[1.3m], total [1.3m]/[4.4m], memory [29.2gb]->[23.9gb]/[29.9gb],
all_pools {[young] [289mb]->[161.3mb]/[665.6mb]}{[survivor] [58.3mb]->[0b
]/[83.1mb]}{[old] [28.8gb]->[23.8gb]/[29.1gb]}

[2014-04-16 16:17:55,480][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14745][158] duration [1.3m], collections
[1]/[1.3m], total [1.3m]/[5.7m], memory [29.7gb]->[24.1gb]/[29.9gb],
all_pools {[young] [633.8mb]->[149.7mb]/[665.6mb]}{[survivor] [68.6mb]->[
0b]/[83.1mb]}{[old] [29gb]->[24gb]/[29.1gb]}

[2014-04-16 16:21:17,950][WARN ][monitor.jvm ] [
elasticsearch2.trend1] [gc][old][14857][161] duration [1.4m], collections
[1]/[1.4m], total [1.4m]/[7.2m], memory [28.6gb]->[24.5gb]/[29.9gb],
all_pools {[young] <

...

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/e34fe1bb-67c5-4559-b142-0b238f0ec65a%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Bruce_Ritchie · June 24, 2014, 1:22pm

You may want to try upgrading ES - release notes for 1.2.0 indicate a
change wrt throttling indexing when merges fall behind and earlier release
notes post 1.1.0 have notes about a potential memory leak fix among many
other improvements and fixes.

Best I can think of

Bruce

--
You received this message because you are subscribed to the Google Groups "elasticsearch" group.
To unsubscribe from this group and stop receiving emails from it, send an email to elasticsearch+unsubscribe@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/elasticsearch/58147218-c37f-467a-bdd6-3d7457b8dabd%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

Topic		Replies	Views
Why does one of the coordinating nodes in my ES cluster occasionally stop GC for a short period of time? Elasticsearch	2	18	November 20, 2024
Frequently gc in one node Elasticsearch	6	1226	May 28, 2018
Strange young GC pauses with ES 1.3 and Java 8 Elasticsearch	5	1722	July 5, 2017
Young GC inconsistent durations Elasticsearch	1	820	January 5, 2017
Debug Old GC after startup and on indexing (40 second hangs every other minute) Elasticsearch	1	635	July 5, 2017

ES v1.1 continuous young gc pauses old gc, stops the world when old gc happens and splits cluster

Related topics