Elasticsearch garbage collection - is this a worry?

We are running Elasticsearch 5.2 in Docker containers. It's somewhat slow. It's running on not-particularly-fast hardware, which doesn't help, but I was wondering if the garbage collection messages in the log are indicating something else we can tune?

We've given the JVM 1.5GB using ES_JAVA_OPTS. We're a bit constrained in how much more we can give.

7/11/2017 10:24:52 AM[2017-07-11T00:24:52,519][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44382][16534] duration [718ms], collections [1]/[1.4s], total [718ms]/[1.5h], memory [925.6mb]->[726.3mb]/[1.4gb], all_pools {[young] [225mb]->[2kb]/[266.2mb]}{[survivor] [33.2mb]->[33.2mb]/[33.2mb]}{[old] [667.3mb]->[693.1mb]/[1.1gb]}
7/11/2017 10:24:52 AM[2017-07-11T00:24:52,520][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44382] overhead, spent [718ms] collecting in the last [1.4s]
7/11/2017 10:24:53 AM[2017-07-11T00:24:53,520][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44383] overhead, spent [365ms] collecting in the last [1.3s]
7/11/2017 10:25:00 AM[2017-07-11T00:25:00,524][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44390] overhead, spent [298ms] collecting in the last [1s]
7/11/2017 10:25:15 AM[2017-07-11T00:25:15,872][WARN ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44405] overhead, spent [540ms] collecting in the last [1s]
7/11/2017 10:25:18 AM[2017-07-11T00:25:18,919][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44408] overhead, spent [339ms] collecting in the last [1s]
7/11/2017 10:25:20 AM[2017-07-11T00:25:20,923][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44410] overhead, spent [317ms] collecting in the last [1s]
7/11/2017 10:25:23 AM[2017-07-11T00:25:23,968][WARN ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44413] overhead, spent [596ms] collecting in the last [1s]
7/11/2017 10:25:28 AM[2017-07-11T00:25:28,655][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44417][16545] duration [801ms], collections [1]/[1.6s], total [801ms]/[1.5h], memory [1012.6mb]->[810.8mb]/[1.4gb], all_pools {[young] [210.4mb]->[1.2mb]/[266.2mb]}{[survivor] [33.2mb]->[28.6mb]/[33.2mb]}{[old] [768.9mb]->[780.9mb]/[1.1gb]}
7/11/2017 10:25:28 AM[2017-07-11T00:25:28,655][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44417] overhead, spent [801ms] collecting in the last [1.6s]
7/11/2017 10:25:34 AM[2017-07-11T00:25:34,248][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44421][16547] duration [1.7s], collections [2]/[2.5s], total [1.7s]/[1.5h], memory [1001.8mb]->[843.9mb]/[1.4gb], all_pools {[young] [192.2mb]->[979.5kb]/[266.2mb]}{[survivor] [28.6mb]->[19.5mb]/[33.2mb]}{[old] [780.9mb]->[823.4mb]/[1.1gb]}
7/11/2017 10:25:34 AM[2017-07-11T00:25:34,248][WARN ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44421] overhead, spent [1.7s] collecting in the last [2.5s]
7/11/2017 10:25:48 AM[2017-07-11T00:25:48,115][WARN ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44433][16550] duration [1.2s], collections [1]/[1.9s], total [1.2s]/[1.5h], memory [1gb]->[877mb]/[1.4gb], all_pools {[young] [239.9mb]->[2mb]/[266.2mb]}{[survivor] [33.2mb]->[33.2mb]/[33.2mb]}{[old] [824.4mb]->[841.7mb]/[1.1gb]}
7/11/2017 10:25:48 AM[2017-07-11T00:25:48,115][WARN ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44433] overhead, spent [1.2s] collecting in the last [1.9s]
7/11/2017 10:25:49 AM[2017-07-11T00:25:49,116][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44434][16551] duration [873ms], collections [1]/[1.8s], total [873ms]/[1.5h], memory [877mb]->[975.4mb]/[1.4gb], all_pools {[young] [2mb]->[83.2mb]/[266.2mb]}{[survivor] [33.2mb]->[21.1mb]/[33.2mb]}{[old] [841.7mb]->[870.9mb]/[1.1gb]}
7/11/2017 10:25:49 AM[2017-07-11T00:25:49,116][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44434] overhead, spent [873ms] collecting in the last [1.8s]
7/11/2017 10:26:24 AM[2017-07-11T00:26:24,130][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44469] overhead, spent [409ms] collecting in the last [1s]
7/11/2017 10:26:27 AM[2017-07-11T00:26:27,059][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][young][44471][16556] duration [835ms], collections [1]/[1.9s], total [835ms]/[1.5h], memory [1gb]->[941.1mb]/[1.4gb], all_pools {[young] [174mb]->[9.9mb]/[266.2mb]}{[survivor] [33.2mb]->[23mb]/[33.2mb]}{[old] [886.7mb]->[908.1mb]/[1.1gb]}
7/11/2017 10:26:27 AM[2017-07-11T00:26:27,059][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44471] overhead, spent [835ms] collecting in the last [1.9s]
7/11/2017 10:26:44 AM[2017-07-11T00:26:44,482][INFO ][o.e.m.j.JvmGcMonitorService] [UqQjI85] [gc][44488] overhead, spent [688ms] collecting in the last [1.4s]

I'm concerned about the messages that say (eg) "spent [1.2s] collecting in the last [1.9s]" - is this accurate? Is this much time being spent garbage collecting?

We've tried bumping up JVM memory (eg to 2GB) to see if that helps, but it doesn't really seem to have much impact.

It looks like you are suffering from heap pressure. You can either increase the heap size or try to reduce the memory usage. How much data/indices/shards do you have in the cluster? What kind of workload are you running against the cluster?

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