From bf3ee9646e133fa8921e451f81062cb3dd6492d4 Mon Sep 17 00:00:00 2001 From: Joe Gallo Date: Tue, 7 Dec 2021 10:25:10 -0500 Subject: [PATCH 1/4] Make sure the current counter is never negative and assert at dev-time if we try to make it go negative. --- .../org/elasticsearch/ingest/IngestMetric.java | 12 +++++++++++- .../elasticsearch/ingest/IngestMetricTests.java | 14 ++++++++++++++ 2 files changed, 25 insertions(+), 1 deletion(-) diff --git a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java index 264435576762f..0738d8f03ea87 100644 --- a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java +++ b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java @@ -52,7 +52,17 @@ void preIngest() { * @param ingestTimeInNanos The time it took to perform the action. */ void postIngest(long ingestTimeInNanos) { - ingestCurrent.decrementAndGet(); + // this is decrementAndGet with a zero floor and an assert + ingestCurrent.updateAndGet(current -> { + if (current > 0) { + current--; + } else { + // then we've double decremented! + assert false; + } + return current; + }); + this.ingestTimeInNanos.inc(ingestTimeInNanos); ingestCount.inc(); } diff --git a/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java b/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java index 32a9ae5088356..4e51891e61395 100644 --- a/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java +++ b/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java @@ -31,4 +31,18 @@ public void testIngestTimeInNanos() { assertThat(1L, equalTo(metric.createStats().getIngestTimeInMillis())); } + public void testPostIngestDoubleDecrement() { + IngestMetric metric = new IngestMetric(); + + metric.preIngest(); + assertThat(1L, equalTo(metric.createStats().getIngestCurrent())); + + metric.postIngest(500000L); + assertThat(0L, equalTo(metric.createStats().getIngestCurrent())); + + // the second postIngest triggers an assert (at dev-time), but does not cause the 'current' counter to go negative (at run-time) + expectThrows(AssertionError.class, () -> metric.postIngest(500000L)); + assertThat(0L, equalTo(metric.createStats().getIngestCurrent())); + } + } From 416b1cf5aa5214af14da4ecf0f5a8c91169bd903 Mon Sep 17 00:00:00 2001 From: Joe Gallo Date: Tue, 7 Dec 2021 10:41:23 -0500 Subject: [PATCH 2/4] Log any double decrements (up to once an hour) --- .../org/elasticsearch/ingest/IngestMetric.java | 14 +++++++++++++- 1 file changed, 13 insertions(+), 1 deletion(-) diff --git a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java index 0738d8f03ea87..74db071fc32ca 100644 --- a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java +++ b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java @@ -8,6 +8,8 @@ package org.elasticsearch.ingest; +import org.apache.logging.log4j.LogManager; +import org.apache.logging.log4j.Logger; import org.elasticsearch.common.metrics.CounterMetric; import java.util.concurrent.TimeUnit; @@ -22,6 +24,8 @@ */ class IngestMetric { + private static final Logger logger = LogManager.getLogger(IngestMetric.class); + /** * The time it takes to complete the measured item. */ @@ -47,17 +51,25 @@ void preIngest() { ingestCurrent.incrementAndGet(); } + private static long doubleDecrementLogMillis = -1; + /** * Call this after the performing the ingest action, even if the action failed. * @param ingestTimeInNanos The time it took to perform the action. */ void postIngest(long ingestTimeInNanos) { - // this is decrementAndGet with a zero floor and an assert + // this is decrementAndGet with a zero floor, logging, and an assert ingestCurrent.updateAndGet(current -> { if (current > 0) { current--; } else { // then we've double decremented! + long now = System.currentTimeMillis(); + if (now - doubleDecrementLogMillis > TimeUnit.HOURS.toMillis(1)) { + logger.warn("ingest metric current count double-decremented", new Throwable()); + doubleDecrementLogMillis = now; + } + // fail at dev-time so we fix this assert false; } return current; From 1d33a01d8e9a1428dd81ae5053b062653091e1e9 Mon Sep 17 00:00:00 2001 From: Joe Gallo Date: Tue, 7 Dec 2021 13:38:12 -0500 Subject: [PATCH 3/4] Keep the assert, drop the logging If we trigger this during a test, we'll fail loudly at test time (rather than requiring a subsequent cluster stats call to see that there's an issue). --- .../elasticsearch/ingest/IngestMetric.java | 25 ++----------------- .../ingest/IngestMetricTests.java | 4 +-- 2 files changed, 4 insertions(+), 25 deletions(-) diff --git a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java index 74db071fc32ca..7e65e5efe6ccc 100644 --- a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java +++ b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java @@ -8,8 +8,6 @@ package org.elasticsearch.ingest; -import org.apache.logging.log4j.LogManager; -import org.apache.logging.log4j.Logger; import org.elasticsearch.common.metrics.CounterMetric; import java.util.concurrent.TimeUnit; @@ -24,8 +22,6 @@ */ class IngestMetric { - private static final Logger logger = LogManager.getLogger(IngestMetric.class); - /** * The time it takes to complete the measured item. */ @@ -51,30 +47,13 @@ void preIngest() { ingestCurrent.incrementAndGet(); } - private static long doubleDecrementLogMillis = -1; - /** * Call this after the performing the ingest action, even if the action failed. * @param ingestTimeInNanos The time it took to perform the action. */ void postIngest(long ingestTimeInNanos) { - // this is decrementAndGet with a zero floor, logging, and an assert - ingestCurrent.updateAndGet(current -> { - if (current > 0) { - current--; - } else { - // then we've double decremented! - long now = System.currentTimeMillis(); - if (now - doubleDecrementLogMillis > TimeUnit.HOURS.toMillis(1)) { - logger.warn("ingest metric current count double-decremented", new Throwable()); - doubleDecrementLogMillis = now; - } - // fail at dev-time so we fix this - assert false; - } - return current; - }); - + long current = ingestCurrent.decrementAndGet(); + assert current >= 0: "ingest metric current count double-decremented"; this.ingestTimeInNanos.inc(ingestTimeInNanos); ingestCount.inc(); } diff --git a/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java b/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java index 4e51891e61395..d4fd0d6c0ef52 100644 --- a/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java +++ b/server/src/test/java/org/elasticsearch/ingest/IngestMetricTests.java @@ -40,9 +40,9 @@ public void testPostIngestDoubleDecrement() { metric.postIngest(500000L); assertThat(0L, equalTo(metric.createStats().getIngestCurrent())); - // the second postIngest triggers an assert (at dev-time), but does not cause the 'current' counter to go negative (at run-time) + // the second postIngest triggers an assertion error expectThrows(AssertionError.class, () -> metric.postIngest(500000L)); - assertThat(0L, equalTo(metric.createStats().getIngestCurrent())); + assertThat(-1L, equalTo(metric.createStats().getIngestCurrent())); } } From 8b197dc06fa4282512025c0e6fc337216c1260ad Mon Sep 17 00:00:00 2001 From: Joe Gallo Date: Tue, 7 Dec 2021 13:59:37 -0500 Subject: [PATCH 4/4] Spotless --- server/src/main/java/org/elasticsearch/ingest/IngestMetric.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java index 7e65e5efe6ccc..de26acff1a024 100644 --- a/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java +++ b/server/src/main/java/org/elasticsearch/ingest/IngestMetric.java @@ -53,7 +53,7 @@ void preIngest() { */ void postIngest(long ingestTimeInNanos) { long current = ingestCurrent.decrementAndGet(); - assert current >= 0: "ingest metric current count double-decremented"; + assert current >= 0 : "ingest metric current count double-decremented"; this.ingestTimeInNanos.inc(ingestTimeInNanos); ingestCount.inc(); }