Add GC overhead logging
This commit adds simple GC overhead logging. This logging captures intervals where the JVM is spending a lot of time performing GC but it is not necessarily the case that each GC is large. For a start, this logging is simple and does not attempt to incorporate whether or not the collections were efficient (that is, we are only capturing that a lot of GC is happening, not that a lot of useless GC is happening). Relates #18419
This commit is contained in:
Jason Tedor
parent
3954306af2
commit
cad0608cdb
|
|
@ -397,6 +397,9 @@ public final class ClusterSettings extends AbstractScopedSettings {
|
|||
JvmGcMonitorService.ENABLED_SETTING,
|
||||
JvmGcMonitorService.REFRESH_INTERVAL_SETTING,
|
||||
JvmGcMonitorService.GC_SETTING,
|
||||
JvmGcMonitorService.GC_OVERHEAD_WARN_SETTING,
|
||||
JvmGcMonitorService.GC_OVERHEAD_INFO_SETTING,
|
||||
JvmGcMonitorService.GC_OVERHEAD_DEBUG_SETTING,
|
||||
PageCacheRecycler.LIMIT_HEAP_SETTING,
|
||||
PageCacheRecycler.WEIGHT_BYTES_SETTING,
|
||||
PageCacheRecycler.WEIGHT_INT_SETTING,
|
||||
|
|
|
|||
|
|
@ -18,19 +18,6 @@
|
|||
*/
|
||||
package org.elasticsearch.common.settings;
|
||||
|
||||
import java.io.IOException;
|
||||
import java.util.ArrayList;
|
||||
import java.util.Arrays;
|
||||
import java.util.EnumSet;
|
||||
import java.util.List;
|
||||
import java.util.Map;
|
||||
import java.util.Objects;
|
||||
import java.util.function.BiConsumer;
|
||||
import java.util.function.Consumer;
|
||||
import java.util.function.Function;
|
||||
import java.util.regex.Pattern;
|
||||
import java.util.stream.Collectors;
|
||||
|
||||
import org.elasticsearch.ElasticsearchException;
|
||||
import org.elasticsearch.ElasticsearchParseException;
|
||||
import org.elasticsearch.action.support.ToXContentToBytes;
|
||||
|
|
@ -50,6 +37,19 @@ import org.elasticsearch.common.xcontent.XContentFactory;
|
|||
import org.elasticsearch.common.xcontent.XContentParser;
|
||||
import org.elasticsearch.common.xcontent.XContentType;
|
||||
|
||||
import java.io.IOException;
|
||||
import java.util.ArrayList;
|
||||
import java.util.Arrays;
|
||||
import java.util.EnumSet;
|
||||
import java.util.List;
|
||||
import java.util.Map;
|
||||
import java.util.Objects;
|
||||
import java.util.function.BiConsumer;
|
||||
import java.util.function.Consumer;
|
||||
import java.util.function.Function;
|
||||
import java.util.regex.Pattern;
|
||||
import java.util.stream.Collectors;
|
||||
|
||||
/**
|
||||
* A setting. Encapsulates typical stuff like default value, parsing, and scope.
|
||||
* Some (SettingsProperty.Dynamic) can by modified at run time using the API.
|
||||
|
|
@ -504,7 +504,7 @@ public class Setting<T> extends ToXContentToBytes {
|
|||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be >= " + minValue);
|
||||
}
|
||||
if (value > maxValue) {
|
||||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be =< " + maxValue);
|
||||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be <= " + maxValue);
|
||||
}
|
||||
return value;
|
||||
}
|
||||
|
|
@ -572,7 +572,7 @@ public class Setting<T> extends ToXContentToBytes {
|
|||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be >= " + minValue);
|
||||
}
|
||||
if (value.bytes() > maxValue.bytes()) {
|
||||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be =< " + maxValue);
|
||||
throw new IllegalArgumentException("Failed to parse value [" + s + "] for setting [" + key + "] must be <= " + maxValue);
|
||||
}
|
||||
return value;
|
||||
}
|
||||
|
|
|
|||
|
|
@ -31,6 +31,7 @@ import org.elasticsearch.monitor.jvm.JvmStats.GarbageCollector;
|
|||
import org.elasticsearch.threadpool.ThreadPool;
|
||||
|
||||
import java.util.HashMap;
|
||||
import java.util.Locale;
|
||||
import java.util.Map;
|
||||
import java.util.Objects;
|
||||
import java.util.concurrent.ScheduledFuture;
|
||||
|
|
@ -45,6 +46,7 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
private final boolean enabled;
|
||||
private final TimeValue interval;
|
||||
private final Map<String, GcThreshold> gcThresholds;
|
||||
private final GcOverheadThreshold gcOverheadThreshold;
|
||||
|
||||
private volatile ScheduledFuture scheduledFuture;
|
||||
|
||||
|
|
@ -57,6 +59,27 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
private static String GC_COLLECTOR_PREFIX = "monitor.jvm.gc.collector.";
|
||||
public final static Setting<Settings> GC_SETTING = Setting.groupSetting(GC_COLLECTOR_PREFIX, Property.NodeScope);
|
||||
|
||||
public final static Setting<Integer> GC_OVERHEAD_WARN_SETTING =
|
||||
Setting.intSetting("monitor.jvm.gc.overhead.warn", 50, 0, 100, Property.NodeScope);
|
||||
public final static Setting<Integer> GC_OVERHEAD_INFO_SETTING =
|
||||
Setting.intSetting("monitor.jvm.gc.overhead.info", 25, 0, 100, Property.NodeScope);
|
||||
public final static Setting<Integer> GC_OVERHEAD_DEBUG_SETTING =
|
||||
Setting.intSetting("monitor.jvm.gc.overhead.debug", 10, 0, 100, Property.NodeScope);
|
||||
|
||||
static class GcOverheadThreshold {
|
||||
final int warnThreshold;
|
||||
final int infoThreshold;
|
||||
final int debugThreshold;
|
||||
|
||||
public GcOverheadThreshold(final int warnThreshold, final int infoThreshold, final int debugThreshold) {
|
||||
this.warnThreshold = warnThreshold;
|
||||
this.infoThreshold = infoThreshold;
|
||||
this.debugThreshold = debugThreshold;
|
||||
}
|
||||
}
|
||||
|
||||
|
||||
|
||||
static class GcThreshold {
|
||||
public final String name;
|
||||
public final long warnThreshold;
|
||||
|
|
@ -102,7 +125,42 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
gcThresholds.putIfAbsent("default", new GcThreshold("default", 10000, 5000, 2000));
|
||||
this.gcThresholds = unmodifiableMap(gcThresholds);
|
||||
|
||||
logger.debug("enabled [{}], interval [{}], gc_threshold [{}]", enabled, interval, this.gcThresholds);
|
||||
if (GC_OVERHEAD_WARN_SETTING.get(settings) <= GC_OVERHEAD_INFO_SETTING.get(settings)) {
|
||||
final String message =
|
||||
String.format(
|
||||
Locale.ROOT,
|
||||
"[%s] must be greater than [%s] [%d] but was [%d]",
|
||||
GC_OVERHEAD_WARN_SETTING.getKey(),
|
||||
GC_OVERHEAD_INFO_SETTING.getKey(),
|
||||
GC_OVERHEAD_INFO_SETTING.get(settings),
|
||||
GC_OVERHEAD_WARN_SETTING.get(settings));
|
||||
throw new IllegalArgumentException(message);
|
||||
}
|
||||
if (GC_OVERHEAD_INFO_SETTING.get(settings) <= GC_OVERHEAD_DEBUG_SETTING.get(settings)) {
|
||||
final String message =
|
||||
String.format(
|
||||
Locale.ROOT,
|
||||
"[%s] must be greater than [%s] [%d] but was [%d]",
|
||||
GC_OVERHEAD_INFO_SETTING.getKey(),
|
||||
GC_OVERHEAD_DEBUG_SETTING.getKey(),
|
||||
GC_OVERHEAD_DEBUG_SETTING.get(settings),
|
||||
GC_OVERHEAD_INFO_SETTING.get(settings));
|
||||
throw new IllegalArgumentException(message);
|
||||
}
|
||||
|
||||
this.gcOverheadThreshold = new GcOverheadThreshold(
|
||||
GC_OVERHEAD_WARN_SETTING.get(settings),
|
||||
GC_OVERHEAD_INFO_SETTING.get(settings),
|
||||
GC_OVERHEAD_DEBUG_SETTING.get(settings));
|
||||
|
||||
logger.debug(
|
||||
"enabled [{}], interval [{}], gc_threshold [{}], overhead [{}, {}, {}]",
|
||||
this.enabled,
|
||||
this.interval,
|
||||
this.gcThresholds,
|
||||
this.gcOverheadThreshold.warnThreshold,
|
||||
this.gcOverheadThreshold.infoThreshold,
|
||||
this.gcOverheadThreshold.debugThreshold);
|
||||
}
|
||||
|
||||
private static TimeValue getValidThreshold(Settings settings, String key, String level) {
|
||||
|
|
@ -120,15 +178,12 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
return GC_COLLECTOR_PREFIX + key + "." + level;
|
||||
}
|
||||
|
||||
private static final String LOG_MESSAGE =
|
||||
"[gc][{}][{}][{}] duration [{}], collections [{}]/[{}], total [{}]/[{}], memory [{}]->[{}]/[{}], all_pools {}";
|
||||
|
||||
@Override
|
||||
protected void doStart() {
|
||||
if (!enabled) {
|
||||
return;
|
||||
}
|
||||
scheduledFuture = threadPool.scheduleWithFixedDelay(new JvmMonitor(gcThresholds) {
|
||||
scheduledFuture = threadPool.scheduleWithFixedDelay(new JvmMonitor(gcThresholds, gcOverheadThreshold) {
|
||||
@Override
|
||||
void onMonitorFailure(Throwable t) {
|
||||
logger.debug("failed to monitor", t);
|
||||
|
|
@ -138,9 +193,17 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
void onSlowGc(final Threshold threshold, final long seq, final SlowGcEvent slowGcEvent) {
|
||||
logSlowGc(logger, threshold, seq, slowGcEvent, JvmGcMonitorService::buildPools);
|
||||
}
|
||||
|
||||
@Override
|
||||
void onGcOverhead(final Threshold threshold, final long current, final long elapsed, final long seq) {
|
||||
logGcOverhead(logger, threshold, current, elapsed, seq);
|
||||
}
|
||||
}, interval);
|
||||
}
|
||||
|
||||
private static final String SLOW_GC_LOG_MESSAGE =
|
||||
"[gc][{}][{}][{}] duration [{}], collections [{}]/[{}], total [{}]/[{}], memory [{}]->[{}]/[{}], all_pools {}";
|
||||
|
||||
static void logSlowGc(
|
||||
final ESLogger logger,
|
||||
final JvmMonitor.Threshold threshold,
|
||||
|
|
@ -162,7 +225,7 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
case WARN:
|
||||
if (logger.isWarnEnabled()) {
|
||||
logger.warn(
|
||||
LOG_MESSAGE,
|
||||
SLOW_GC_LOG_MESSAGE,
|
||||
name,
|
||||
seq,
|
||||
totalGcCollectionCount,
|
||||
|
|
@ -180,7 +243,7 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
case INFO:
|
||||
if (logger.isInfoEnabled()) {
|
||||
logger.info(
|
||||
LOG_MESSAGE,
|
||||
SLOW_GC_LOG_MESSAGE,
|
||||
name,
|
||||
seq,
|
||||
totalGcCollectionCount,
|
||||
|
|
@ -198,7 +261,7 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
case DEBUG:
|
||||
if (logger.isDebugEnabled()) {
|
||||
logger.debug(
|
||||
LOG_MESSAGE,
|
||||
SLOW_GC_LOG_MESSAGE,
|
||||
name,
|
||||
seq,
|
||||
totalGcCollectionCount,
|
||||
|
|
@ -239,6 +302,33 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
return sb.toString();
|
||||
}
|
||||
|
||||
private static final String OVERHEAD_LOG_MESSAGE = "[gc][{}] overhead, spent [{}] collecting in the last [{}]";
|
||||
|
||||
static void logGcOverhead(
|
||||
final ESLogger logger,
|
||||
final JvmMonitor.Threshold threshold,
|
||||
final long current,
|
||||
final long elapsed,
|
||||
final long seq) {
|
||||
switch (threshold) {
|
||||
case WARN:
|
||||
if (logger.isWarnEnabled()) {
|
||||
logger.warn(OVERHEAD_LOG_MESSAGE, seq, TimeValue.timeValueMillis(current), TimeValue.timeValueMillis(elapsed));
|
||||
}
|
||||
break;
|
||||
case INFO:
|
||||
if (logger.isInfoEnabled()) {
|
||||
logger.info(OVERHEAD_LOG_MESSAGE, seq, TimeValue.timeValueMillis(current), TimeValue.timeValueMillis(elapsed));
|
||||
}
|
||||
break;
|
||||
case DEBUG:
|
||||
if (logger.isDebugEnabled()) {
|
||||
logger.debug(OVERHEAD_LOG_MESSAGE, seq, TimeValue.timeValueMillis(current), TimeValue.timeValueMillis(elapsed));
|
||||
}
|
||||
break;
|
||||
}
|
||||
}
|
||||
|
||||
@Override
|
||||
protected void doStop() {
|
||||
if (!enabled) {
|
||||
|
|
@ -287,16 +377,18 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
private long lastTime = now();
|
||||
private JvmStats lastJvmStats = jvmStats();
|
||||
private long seq = 0;
|
||||
private final Map<String, GcThreshold> gcThresholds;
|
||||
private final Map<String, JvmGcMonitorService.GcThreshold> gcThresholds;
|
||||
final GcOverheadThreshold gcOverheadThreshold;
|
||||
|
||||
public JvmMonitor(Map<String, GcThreshold> gcThresholds) {
|
||||
public JvmMonitor(final Map<String, GcThreshold> gcThresholds, final GcOverheadThreshold gcOverheadThreshold) {
|
||||
this.gcThresholds = Objects.requireNonNull(gcThresholds);
|
||||
this.gcOverheadThreshold = Objects.requireNonNull(gcOverheadThreshold);
|
||||
}
|
||||
|
||||
@Override
|
||||
public void run() {
|
||||
try {
|
||||
monitorLongGc();
|
||||
monitorGc();
|
||||
} catch (Throwable t) {
|
||||
onMonitorFailure(t);
|
||||
}
|
||||
|
|
@ -304,12 +396,21 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
|
||||
abstract void onMonitorFailure(Throwable t);
|
||||
|
||||
synchronized void monitorLongGc() {
|
||||
synchronized void monitorGc() {
|
||||
seq++;
|
||||
final long currentTime = now();
|
||||
JvmStats currentJvmStats = jvmStats();
|
||||
|
||||
final long elapsed = TimeUnit.NANOSECONDS.toMillis(currentTime - lastTime);
|
||||
|
||||
monitorSlowGc(currentJvmStats, elapsed);
|
||||
monitorGcOverhead(currentJvmStats, elapsed);
|
||||
|
||||
lastTime = currentTime;
|
||||
lastJvmStats = currentJvmStats;
|
||||
}
|
||||
|
||||
final void monitorSlowGc(JvmStats currentJvmStats, long elapsed) {
|
||||
for (int i = 0; i < currentJvmStats.getGc().getCollectors().length; i++) {
|
||||
GarbageCollector gc = currentJvmStats.getGc().getCollectors()[i];
|
||||
GarbageCollector prevGc = lastJvmStats.getGc().getCollectors()[i];
|
||||
|
|
@ -350,8 +451,31 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
JvmInfo.jvmInfo().getMem().getHeapMax()));
|
||||
}
|
||||
}
|
||||
lastTime = currentTime;
|
||||
lastJvmStats = currentJvmStats;
|
||||
}
|
||||
|
||||
final void monitorGcOverhead(final JvmStats currentJvmStats, final long elapsed) {
|
||||
long current = 0;
|
||||
for (int i = 0; i < currentJvmStats.getGc().getCollectors().length; i++) {
|
||||
GarbageCollector gc = currentJvmStats.getGc().getCollectors()[i];
|
||||
GarbageCollector prevGc = lastJvmStats.getGc().getCollectors()[i];
|
||||
current += gc.getCollectionTime().millis() - prevGc.getCollectionTime().millis();
|
||||
}
|
||||
checkGcOverhead(current, elapsed, seq);
|
||||
}
|
||||
|
||||
void checkGcOverhead(final long current, final long elapsed, final long seq) {
|
||||
final int fraction = (int) ((100 * current) / (double) elapsed);
|
||||
Threshold overheadThreshold = null;
|
||||
if (fraction >= gcOverheadThreshold.warnThreshold) {
|
||||
overheadThreshold = Threshold.WARN;
|
||||
} else if (fraction >= gcOverheadThreshold.infoThreshold) {
|
||||
overheadThreshold = Threshold.INFO;
|
||||
} else if (fraction >= gcOverheadThreshold.debugThreshold) {
|
||||
overheadThreshold = Threshold.DEBUG;
|
||||
}
|
||||
if (overheadThreshold != null) {
|
||||
onGcOverhead(overheadThreshold, current, elapsed, seq);
|
||||
}
|
||||
}
|
||||
|
||||
JvmStats jvmStats() {
|
||||
|
|
@ -364,6 +488,8 @@ public class JvmGcMonitorService extends AbstractLifecycleComponent<JvmGcMonitor
|
|||
|
||||
abstract void onSlowGc(final Threshold threshold, final long seq, final SlowGcEvent slowGcEvent);
|
||||
|
||||
abstract void onGcOverhead(final Threshold threshold, final long total, final long elapsed, final long seq);
|
||||
|
||||
}
|
||||
|
||||
}
|
||||
|
|
|
|||
|
|
@ -430,7 +430,7 @@ public class SettingTests extends ESTestCase {
|
|||
integerSetting.get(Settings.builder().put("foo.bar", 11).build());
|
||||
fail();
|
||||
} catch (IllegalArgumentException ex) {
|
||||
assertEquals("Failed to parse value [11] for setting [foo.bar] must be =< 10", ex.getMessage());
|
||||
assertEquals("Failed to parse value [11] for setting [foo.bar] must be <= 10", ex.getMessage());
|
||||
}
|
||||
|
||||
try {
|
||||
|
|
|
|||
|
|
@ -79,6 +79,46 @@ public class JvmGcMonitorServiceSettingsTests extends ESTestCase {
|
|||
}, true, null);
|
||||
}
|
||||
|
||||
public void testIllegalOverheadSettings() throws InterruptedException {
|
||||
for (final String threshold : new String[] { "warn", "info", "debug" }) {
|
||||
final Settings.Builder builder = Settings.builder();
|
||||
builder.put("monitor.jvm.gc.overhead." + threshold, randomIntBetween(Integer.MIN_VALUE, -1));
|
||||
execute(builder.build(), (command, interval) -> null, t -> {
|
||||
assertThat(t, instanceOf(IllegalArgumentException.class));
|
||||
assertThat(t.getMessage(), containsString("setting [monitor.jvm.gc.overhead." + threshold + "] must be >= 0"));
|
||||
}, true, null);
|
||||
}
|
||||
|
||||
for (final String threshold : new String[] { "warn", "info", "debug" }) {
|
||||
final Settings.Builder builder = Settings.builder();
|
||||
builder.put("monitor.jvm.gc.overhead." + threshold, randomIntBetween(100 + 1, Integer.MAX_VALUE));
|
||||
execute(builder.build(), (command, interval) -> null, t -> {
|
||||
assertThat(t, instanceOf(IllegalArgumentException.class));
|
||||
assertThat(t.getMessage(), containsString("setting [monitor.jvm.gc.overhead." + threshold + "] must be <= 100"));
|
||||
}, true, null);
|
||||
}
|
||||
|
||||
final Settings.Builder infoWarnOutOfOrderBuilder = Settings.builder();
|
||||
final int info = randomIntBetween(2, 98);
|
||||
infoWarnOutOfOrderBuilder.put("monitor.jvm.gc.overhead.info", info);
|
||||
final int warn = randomIntBetween(1, info - 1);
|
||||
infoWarnOutOfOrderBuilder.put("monitor.jvm.gc.overhead.warn", warn);
|
||||
execute(infoWarnOutOfOrderBuilder.build(), (command, interval) -> null, t -> {
|
||||
assertThat(t, instanceOf(IllegalArgumentException.class));
|
||||
assertThat(t.getMessage(), containsString("[monitor.jvm.gc.overhead.warn] must be greater than [monitor.jvm.gc.overhead.info] [" + info + "] but was [" + warn + "]"));
|
||||
}, true, null);
|
||||
|
||||
final Settings.Builder debugInfoOutOfOrderBuilder = Settings.builder();
|
||||
debugInfoOutOfOrderBuilder.put("monitor.jvm.gc.overhead.info", info);
|
||||
final int debug = randomIntBetween(info + 1, 99);
|
||||
debugInfoOutOfOrderBuilder.put("monitor.jvm.gc.overhead.debug", debug);
|
||||
debugInfoOutOfOrderBuilder.put("monitor.jvm.gc.overhead.warn", randomIntBetween(debug + 1, 100)); // or the test will fail for the wrong reason
|
||||
execute(debugInfoOutOfOrderBuilder.build(), (command, interval) -> null, t -> {
|
||||
assertThat(t, instanceOf(IllegalArgumentException.class));
|
||||
assertThat(t.getMessage(), containsString("[monitor.jvm.gc.overhead.info] must be greater than [monitor.jvm.gc.overhead.debug] [" + debug + "] but was [" + info + "]"));
|
||||
}, true, null);
|
||||
}
|
||||
|
||||
private static void execute(Settings settings, BiFunction<Runnable, TimeValue, ScheduledFuture<?>> scheduler, Runnable asserts) throws InterruptedException {
|
||||
execute(settings, scheduler, null, false, asserts);
|
||||
}
|
||||
|
|
|
|||
|
|
@ -133,4 +133,43 @@ public class JvmGcMonitorServiceTests extends ESTestCase {
|
|||
verifyNoMoreInteractions(logger);
|
||||
}
|
||||
|
||||
public void testGcOverheadLogging() {
|
||||
final JvmGcMonitorService.JvmMonitor.Threshold threshold = randomFrom(JvmGcMonitorService.JvmMonitor.Threshold.values());
|
||||
final int current = randomIntBetween(1, Integer.MAX_VALUE);
|
||||
final long elapsed = randomIntBetween(current, Integer.MAX_VALUE);
|
||||
final long seq = randomIntBetween(1, Integer.MAX_VALUE);
|
||||
final ESLogger logger = mock(ESLogger.class);
|
||||
when(logger.isWarnEnabled()).thenReturn(true);
|
||||
when(logger.isInfoEnabled()).thenReturn(true);
|
||||
when(logger.isDebugEnabled()).thenReturn(true);
|
||||
JvmGcMonitorService.logGcOverhead(logger, threshold, current, elapsed, seq);
|
||||
switch(threshold) {
|
||||
case WARN:
|
||||
verify(logger).isWarnEnabled();
|
||||
verify(logger).warn(
|
||||
"[gc][{}] overhead, spent [{}] collecting in the last [{}]",
|
||||
seq,
|
||||
TimeValue.timeValueMillis(current),
|
||||
TimeValue.timeValueMillis(elapsed));
|
||||
break;
|
||||
case INFO:
|
||||
verify(logger).isInfoEnabled();
|
||||
verify(logger).info(
|
||||
"[gc][{}] overhead, spent [{}] collecting in the last [{}]",
|
||||
seq,
|
||||
TimeValue.timeValueMillis(current),
|
||||
TimeValue.timeValueMillis(elapsed));
|
||||
break;
|
||||
case DEBUG:
|
||||
verify(logger).isDebugEnabled();
|
||||
verify(logger).debug(
|
||||
"[gc][{}] overhead, spent [{}] collecting in the last [{}]",
|
||||
seq,
|
||||
TimeValue.timeValueMillis(current),
|
||||
TimeValue.timeValueMillis(elapsed));
|
||||
break;
|
||||
}
|
||||
verifyNoMoreInteractions(logger);
|
||||
}
|
||||
|
||||
}
|
||||
|
|
|
|||
|
|
@ -41,10 +41,12 @@ import static org.mockito.Mockito.when;
|
|||
|
||||
public class JvmMonitorTests extends ESTestCase {
|
||||
|
||||
private static final JvmGcMonitorService.GcOverheadThreshold IGNORE = new JvmGcMonitorService.GcOverheadThreshold(0, 0, 0);
|
||||
|
||||
public void testMonitorFailure() {
|
||||
AtomicBoolean shouldFail = new AtomicBoolean();
|
||||
AtomicBoolean invoked = new AtomicBoolean();
|
||||
JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(Collections.emptyMap()) {
|
||||
JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(Collections.emptyMap(), IGNORE) {
|
||||
@Override
|
||||
void onMonitorFailure(Throwable t) {
|
||||
invoked.set(true);
|
||||
|
|
@ -53,7 +55,7 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
}
|
||||
|
||||
@Override
|
||||
synchronized void monitorLongGc() {
|
||||
synchronized void monitorGc() {
|
||||
if (shouldFail.get()) {
|
||||
throw new RuntimeException("simulated");
|
||||
}
|
||||
|
|
@ -62,6 +64,10 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
@Override
|
||||
void onSlowGc(final Threshold threshold, final long seq, final SlowGcEvent slowGcEvent) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void onGcOverhead(Threshold threshold, long total, long elapsed, long seq) {
|
||||
}
|
||||
};
|
||||
|
||||
monitor.run();
|
||||
|
|
@ -166,7 +172,7 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
|
||||
final AtomicInteger count = new AtomicInteger();
|
||||
|
||||
JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(gcThresholds) {
|
||||
JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(gcThresholds, IGNORE) {
|
||||
@Override
|
||||
void onMonitorFailure(Throwable t) {
|
||||
}
|
||||
|
|
@ -198,6 +204,10 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
}
|
||||
}
|
||||
|
||||
@Override
|
||||
void onGcOverhead(Threshold threshold, long total, long elapsed, long seq) {
|
||||
}
|
||||
|
||||
@Override
|
||||
long now() {
|
||||
return now.get();
|
||||
|
|
@ -213,7 +223,7 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
|
||||
now.set(start + TimeUnit.NANOSECONDS.convert(expectedElapsed, TimeUnit.MILLISECONDS));
|
||||
jvmStats.set(monitorJvmStats);
|
||||
monitor.monitorLongGc();
|
||||
monitor.monitorGc();
|
||||
|
||||
assertThat(count.get(), equalTo((youngGcThreshold ? 1 : 0) + (oldGcThreshold ? 1 : 0)));
|
||||
}
|
||||
|
|
@ -235,14 +245,140 @@ public class JvmMonitorTests extends ESTestCase {
|
|||
|
||||
private JvmStats jvmStats(JvmStats.GarbageCollector youngCollector, JvmStats.GarbageCollector oldCollector) {
|
||||
final JvmStats jvmStats = mock(JvmStats.class);
|
||||
final JvmStats.GarbageCollectors initialGcs = mock(JvmStats.GarbageCollectors.class);
|
||||
final JvmStats.GarbageCollector[] initialCollectors = new JvmStats.GarbageCollector[2];
|
||||
initialCollectors[0] = youngCollector;
|
||||
initialCollectors[1] = oldCollector;
|
||||
when(initialGcs.getCollectors()).thenReturn(initialCollectors);
|
||||
when(jvmStats.getGc()).thenReturn(initialGcs);
|
||||
final JvmStats.GarbageCollectors gcs = mock(JvmStats.GarbageCollectors.class);
|
||||
final JvmStats.GarbageCollector[] collectors = new JvmStats.GarbageCollector[2];
|
||||
collectors[0] = youngCollector;
|
||||
collectors[1] = oldCollector;
|
||||
when(gcs.getCollectors()).thenReturn(collectors);
|
||||
when(jvmStats.getGc()).thenReturn(gcs);
|
||||
when(jvmStats.getMem()).thenReturn(JvmStats.jvmStats().getMem());
|
||||
return jvmStats;
|
||||
}
|
||||
|
||||
public void testMonitorGc() {
|
||||
final int youngCollectionCount = randomIntBetween(1, 16);
|
||||
final int youngCollectionIncrement = randomIntBetween(1, 16);
|
||||
final int youngCollectionTime = randomIntBetween(1, 1 << 10);
|
||||
final int youngCollectionTimeIncrement = randomIntBetween(1, 1 << 10);
|
||||
final int oldCollectionCount = randomIntBetween(1, 16);
|
||||
final int oldCollectionIncrement = randomIntBetween(1, 16);
|
||||
final int oldCollectionTime = randomIntBetween(1, 1 << 10);
|
||||
final int oldCollectionTimeIncrement = randomIntBetween(1, 1 << 10);
|
||||
|
||||
final JvmStats.GarbageCollector lastYoungCollector = collector("young", youngCollectionCount, youngCollectionTime);
|
||||
final JvmStats.GarbageCollector lastOldCollector = collector("old", oldCollectionCount, oldCollectionTime);
|
||||
final JvmStats lastjvmStats = jvmStats(lastYoungCollector, lastOldCollector);
|
||||
|
||||
final JvmStats.GarbageCollector currentYoungCollector =
|
||||
collector("young", youngCollectionCount + youngCollectionIncrement, youngCollectionTime + youngCollectionTimeIncrement);
|
||||
final JvmStats.GarbageCollector currentOldCollector =
|
||||
collector("old", oldCollectionCount + oldCollectionIncrement, oldCollectionTime + oldCollectionTimeIncrement);
|
||||
final JvmStats currentJvmStats = jvmStats(currentYoungCollector, currentOldCollector);
|
||||
final long expectedElapsed =
|
||||
randomIntBetween(
|
||||
Math.max(youngCollectionTime + youngCollectionTimeIncrement, oldCollectionTime + oldCollectionTimeIncrement),
|
||||
Integer.MAX_VALUE);
|
||||
|
||||
final AtomicBoolean invoked = new AtomicBoolean();
|
||||
|
||||
final JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(Collections.emptyMap(), IGNORE) {
|
||||
|
||||
@Override
|
||||
void onMonitorFailure(Throwable t) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void onSlowGc(Threshold threshold, long seq, SlowGcEvent slowGcEvent) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void onGcOverhead(Threshold threshold, long total, long elapsed, long seq) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void checkGcOverhead(long current, long elapsed, long seq) {
|
||||
invoked.set(true);
|
||||
assertThat(current, equalTo((long)(youngCollectionTimeIncrement + oldCollectionTimeIncrement)));
|
||||
assertThat(elapsed, equalTo(expectedElapsed));
|
||||
}
|
||||
|
||||
@Override
|
||||
JvmStats jvmStats() {
|
||||
return lastjvmStats;
|
||||
}
|
||||
};
|
||||
|
||||
monitor.monitorGcOverhead(currentJvmStats, expectedElapsed);
|
||||
assertTrue(invoked.get());
|
||||
}
|
||||
|
||||
private JvmStats.GarbageCollector collector(final String name, final int collectionCount, final int collectionTime) {
|
||||
final JvmStats.GarbageCollector gc = mock(JvmStats.GarbageCollector.class);
|
||||
when(gc.getName()).thenReturn(name);
|
||||
when(gc.getCollectionCount()).thenReturn((long)collectionCount);
|
||||
when(gc.getCollectionTime()).thenReturn(TimeValue.timeValueMillis(collectionTime));
|
||||
return gc;
|
||||
}
|
||||
|
||||
public void testCheckGcOverhead() {
|
||||
final int debugThreshold = randomIntBetween(1, 98);
|
||||
final int infoThreshold = randomIntBetween(debugThreshold + 1, 99);
|
||||
final int warnThreshold = randomIntBetween(infoThreshold + 1, 100);
|
||||
final JvmGcMonitorService.GcOverheadThreshold gcOverheadThreshold =
|
||||
new JvmGcMonitorService.GcOverheadThreshold(warnThreshold, infoThreshold, debugThreshold);
|
||||
|
||||
final JvmGcMonitorService.JvmMonitor.Threshold expectedThreshold;
|
||||
int fraction = 0;
|
||||
final long expectedCurrent;
|
||||
final long expectedElapsed;
|
||||
if (randomBoolean()) {
|
||||
expectedThreshold = randomFrom(JvmGcMonitorService.JvmMonitor.Threshold.values());
|
||||
switch (expectedThreshold) {
|
||||
case WARN:
|
||||
fraction = randomIntBetween(warnThreshold, 100);
|
||||
break;
|
||||
case INFO:
|
||||
fraction = randomIntBetween(infoThreshold, warnThreshold - 1);
|
||||
break;
|
||||
case DEBUG:
|
||||
fraction = randomIntBetween(debugThreshold, infoThreshold - 1);
|
||||
break;
|
||||
}
|
||||
} else {
|
||||
expectedThreshold = null;
|
||||
fraction = randomIntBetween(0, debugThreshold - 1);
|
||||
}
|
||||
|
||||
expectedElapsed = 100 * randomIntBetween(1, 1000);
|
||||
expectedCurrent = fraction * expectedElapsed / 100;
|
||||
|
||||
final AtomicBoolean invoked = new AtomicBoolean();
|
||||
final long expectedSeq = randomIntBetween(1, Integer.MAX_VALUE);
|
||||
|
||||
final JvmGcMonitorService.JvmMonitor monitor = new JvmGcMonitorService.JvmMonitor(Collections.emptyMap(), gcOverheadThreshold) {
|
||||
|
||||
@Override
|
||||
void onMonitorFailure(final Throwable t) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void onSlowGc(Threshold threshold, long seq, SlowGcEvent slowGcEvent) {
|
||||
}
|
||||
|
||||
@Override
|
||||
void onGcOverhead(final Threshold threshold, final long current, final long elapsed, final long seq) {
|
||||
invoked.set(true);
|
||||
assertThat(threshold, equalTo(expectedThreshold));
|
||||
assertThat(current, equalTo(expectedCurrent));
|
||||
assertThat(elapsed, equalTo(expectedElapsed));
|
||||
assertThat(seq, equalTo(expectedSeq));
|
||||
}
|
||||
|
||||
};
|
||||
|
||||
monitor.checkGcOverhead(expectedCurrent, expectedElapsed, expectedSeq);
|
||||
|
||||
assertThat(invoked.get(), equalTo(expectedThreshold != null));
|
||||
}
|
||||
|
||||
}
|
||||
|
|
|
|||
Loading…
Reference in New Issue