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.