Hello All!
I have been using ES 1.7.5 in production for a while now, and have been struggling with a problem.
(13 nodes, 508 indices, 3,072 shards, 487,592,574 docs 498.01GB)
It appears to go like this:
Heap normally lives at ~60-70%, and seems happy there.
Every now and then, for no apparent reason, the heap on a datavm gradually climbs from its 60-70% to 99%.
Then GC kicks in, recovering no heap whatsoever (if I am reading it correctly)
Then, due to GC taking too long, i'm assuming the current master kicks it out of the cluster.
It somehow doesnt go OOM (even though heap is like 99.9999% full) and re-joins the cluster without ever printing the OOM error to the log.
The normal recovery process kicks in and the cluster recovers, and hangs out at the usual 60-70% heap usage after full recovery.
I have marvel, and have checked what used to be the culprits (fieldata) -the increase in JVM heap did no correlate with fieldata usage, or query cache, or filter cache.
I'm suspecting segment merging as I have some (i think) huge segments, but im only suspecting this as I have no other culprits as of yet.
Could someone help me try to indentify a method to finding the underlying issue? and do you folks agree with my commentary on the below logs?
Thanks for any help in advance,
Matt
In the following logs, taken from the datavm that had the issue, i see lots of throttling messages, with increasingly futile attempts at recovering memory, with the cluster going red @ 17:58
First log excerpt (Everything cool - at least I think so, although GC didnt seem to recover much)
[2017-08-16 16:22:25,606][INFO ][index.engine ] [esdatavm6] [_live_84_2016_07_07_0700][2] stop throttling indexing: numMergesInFlight=3, maxNumMerges=4
[2017-08-16 16:36:13,542][INFO ][index.engine ] [esdatavm6] [_live_130_16_09_29_b][1] now throttling indexing: numMergesInFlight=5, maxNumMerges=4
[2017-08-16 16:36:13,935][INFO ][index.engine ] [esdatavm6] [_live_130_16_09_29_b][1] stop throttling indexing: numMergesInFlight=3, maxNumMerges=4
[2017-08-16 16:55:28,131][INFO ][monitor.jvm ] [esdatavm6] [gc][old][542279][185] duration [13.4s], collections [2]/[13.9s], total [13.4s]/[1.8m], memory [12.8gb]->[12.6gb]/[13.7gb], all_pools {[young] [265.7mb]->[47.9mb]/[266.2mb]}{[survivor] [26.6mb]->[0b]/[33.2mb]}{[old] [12.5gb]->[12.5gb]/[13.4gb]}
[2017-08-16 16:57:49,988][INFO ][index.engine ] [esdatavm6] [_live_172_16_12_05][0] now throttling indexing: numMergesInFlight=5, maxNumMerges=4
[2017-08-16 16:57:50,035][INFO ][index.engine ] [esdatavm6] [_live_172_16_12_05][0] stop throttling indexing: numMergesInFlight=3, maxNumMerges=4
[2017-08-16 16:57:50,035][INFO ][index.engine ] [esdatavm6] [_live_172_16_12_05][0] now throttling indexing: numMergesInFlight=5, maxNumMerges=4
then loads of GC attempts:
[2017-08-16 17:46:08,873][WARN ][monitor.jvm ] [esdatavm6] [gc][old][542736][400] duration [16.3s], collections [1]/[16.5s], total [16.3s]/[47m], memory [13.6gb]->[13.6gb]/[13.7gb], all_pools {[young] [260.4mb]->[266.2mb]/[266.2mb]}{[survivor] [14.8mb]->[15.4mb]/[33.2mb]}{[old] [13.4gb]->[13.4gb]/[13.4gb]}
[2017-08-16 17:46:20,961][WARN ][monitor.jvm ] [esdatavm6] [gc][old][542737][401] duration [12s], collections [1]/[12s], total [12s]/[47.2m], memory [13.6gb]->[13.6gb]/[13.7gb], all_pools {[young] [266.2mb]->[262.8mb]/[266.2mb]}{[survivor] [15.4mb]->[16mb]/[33.2mb]}{[old] [13.4gb]->[13.4gb]/[13.4gb]}
then the node leaving the cluster:
[2017-08-16 17:58:34,789][INFO ][discovery.zen ] [esdatavm6] master_left [[esMaster2][6HhG_Ju8QiqEuUFCiTFG-w][esMaster2][inet[/10.0.0.12:9300]]{data=false, master=true}], reason [do not exists on master, act as master failure]
[2017-08-16 17:58:34,790][WARN ][discovery.zen ] [esdatavm6] master left (reason = do not exists on master, act as master failure), current nodes: {[esClient2][GbA_l0ETSOakK8dHAfBaHQ][esClient2][inet[/10.0.1.7:9300]]{data=false, master=false},[esdatavm4][uCRJjSfQRuO3VcOmiHNcTA][esdatavm4][inet[/10.0.1.12:9300]]{master=false},[esMaster0][nuJsCqEnSC-lD3qTw5or2g][esMaster0][inet[/10.0.0.10:9300]]{data=false, master=true},[esdatavm1][-R2Vg_DPQjKgKxHMv2bHHQ][esdatavm1][inet[/10.0.1.14:9300]]{master=false},[esdatavm2][nKqErgEVQ2ms9PyTeSRZ5Q][esdatavm2][inet[/10.0.1.16:9300]]{master=false},[esdatavm5][7BpcdVV-TyquPNawKZbS8A][esdatavm5][inet[/10.0.1.13:9300]]{master=false},[esMaster1][MHHoeURhTlSzctK4cwW8Dw][esMaster1][inet[/10.0.0.11:9300]]{data=false, master=true},[esClient1][g6A8E2UtTkaq1FWPDQiE1g][esClient1][inet[/10.0.1.4:9300]]{data=false, master=false},[esdatavm6][ralIDjIzQd-RPYdiKnUkag][esdatavm6][inet[10.0.1.19/10.0.1.19:9300]]{master=false},[esdatavm3][53Yj_I7FQQeouolj0N_g-A][esdatavm3][inet[/10.0.1.15:9300]]{master=false},[esClient0][auVrdAeRSsaMsbPP8WusPw][esClient0][inet[/10.0.1.6:9300]]{data=false, master=false},[esdatavm0][v-yYtWgrSoyr-iiSunbzOA][esdatavm0][inet[/10.0.1.10:9300]]{master=false},}
[2017-08-16 17:58:34,870][INFO ][cluster.service ] [esdatavm6] removed {[esMaster2][6HhG_Ju8QiqEuUFCiTFG-w][esMaster2][inet[/10.0.0.12:9300]]{data=false, master=true},}, reason: zen-disco-master_failed ([esMaster2][6HhG_Ju8QiqEuUFCiTFG-w][esMaster2][inet[/10.0.0.12:9300]]{data=false, master=true})
[2017-08-16 17:58:47,116][WARN ][monitor.jvm ] [esdatavm6] [gc][old][542771][455] duration [12.1s], collections [1]/[12.3s], total [12.1s]/[59.5m], memory [13.6gb]->[13.6gb]/[13.7gb], all_pools {[young] [266.2mb]->[266.2mb]/[266.2mb]}{[survivor] [26mb]->[26.3mb]/[33.2mb]}{[old] [13.4gb]->[13.4gb]/[13.4gb]}