ES 1.7.5 Heap filling up, Leaves cluster due to long GC


(Dendle) #1

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]}


(Daniel Mitterdorfer) #2

Hi @dendle,

a long GC can indeed be the reason for this behavior.

Older versions of Elasticsearch had some problems w.r.t. to OOMEs. This got better in 5.x (maybe 2.x already, I don't recall OTOH) and Elasticsearch will usually terminate if a OOME has occurred.

I see two possible approaches:

  • You can increase the log level and check whether you find the culprit by seeing what it is doing at the time heap usage increases.
  • You can take regular heap dumps: One when heap usage is ok (60 - 70% usage) and one when heap usage is climbing. You can take heap dumps with jmap -dump:format=b,file=your_heap_dump.hprof <PID> (see also Oracle docs). Eclipse MAT has a feature that allows you to diff heap dumps.

Daniel


(Dendle) #3

Thanks for the info Daniel,
Cheers!
Matt


(system) #4

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