From 96bfbe62500d0769306728a18256a407a08d1a4f Mon Sep 17 00:00:00 2001 From: Ariel Weisberg Date: Tue, 8 Apr 2025 15:08:22 -0400 Subject: [PATCH] Dropwizard Meter causes timeouts when infrequently used patch by Ariel Weisberg; reviewed by Maxim Muzafarov for CASSANDRA-19332 --- CHANGES.txt | 1 + .../metrics/CassandraMetricsRegistry.java | 77 ++++++++++++++++++- .../metrics/CassandraMetricsRegistryTest.java | 38 ++++++++- 3 files changed, 110 insertions(+), 6 deletions(-) diff --git a/CHANGES.txt b/CHANGES.txt index 0f9e790dc7..25aea7b20a 100644 --- a/CHANGES.txt +++ b/CHANGES.txt @@ -1,4 +1,5 @@ 4.0.18 + * Fix Dropwizard Meter causes timeouts when infrequently used (CASSANDRA-19332) * Update OWASP dependency checker to version 12.1.0 (CASSANDRA-20501) * Suppress CVE-2025-25193 (CASSANDRA-20504) * Include in source tree and build packages a Snyk policy file that lists known false positives (CASSANDRA-20319) diff --git a/src/java/org/apache/cassandra/metrics/CassandraMetricsRegistry.java b/src/java/org/apache/cassandra/metrics/CassandraMetricsRegistry.java index 1ae24556e4..2a2794c27a 100644 --- a/src/java/org/apache/cassandra/metrics/CassandraMetricsRegistry.java +++ b/src/java/org/apache/cassandra/metrics/CassandraMetricsRegistry.java @@ -18,20 +18,38 @@ package org.apache.cassandra.metrics; import java.lang.reflect.Method; +import java.util.ArrayList; import java.util.Collection; import java.util.Collections; +import java.util.List; import java.util.Locale; import java.util.Map; import java.util.Optional; import java.util.concurrent.ConcurrentHashMap; +import java.util.concurrent.ScheduledFuture; +import java.util.concurrent.ThreadLocalRandom; import java.util.concurrent.TimeUnit; import javax.management.MalformedObjectNameException; import javax.management.ObjectName; import com.google.common.annotations.VisibleForTesting; +import org.github.jamm.Unmetered; +import org.slf4j.Logger; +import org.slf4j.LoggerFactory; -import com.codahale.metrics.*; +import com.codahale.metrics.Counter; +import com.codahale.metrics.Gauge; +import com.codahale.metrics.Histogram; +import com.codahale.metrics.Meter; +import com.codahale.metrics.Metered; +import com.codahale.metrics.Metric; +import com.codahale.metrics.MetricRegistry; +import com.codahale.metrics.Timer; +import org.apache.cassandra.concurrent.ScheduledExecutors; import org.apache.cassandra.utils.MBeanWrapper; +import org.apache.cassandra.utils.Throwables; + +import static com.google.common.base.Preconditions.checkArgument; /** * Makes integrating 3.0 metrics API with 2.0. @@ -41,14 +59,30 @@ import org.apache.cassandra.utils.MBeanWrapper; */ public class CassandraMetricsRegistry extends MetricRegistry { - public static final CassandraMetricsRegistry Metrics = new CassandraMetricsRegistry(); + private static final Logger logger = LoggerFactory.getLogger(CassandraMetricsRegistry.class); + + public static final CassandraMetricsRegistry Metrics = new CassandraMetricsRegistry(TimeUnit.DAYS.toMicros(1)); private final Map threadPoolMetrics = new ConcurrentHashMap<>(); + /** + * {@link org.apache.cassandra.repair.RepairJobTest#testNoTreesRetainedAfterDifference() RepairJobTest#testNoTreesRetainedAfterDifference()} + * calls {@link org.apache.cassandra.utils.ObjectSizes#measureDeep(Object) ObjectSizes.measureDeep(Object)} on + * {@link org.apache.cassandra.repair.RepairSession RepairSession} which reachs the {@link #mBeanServer} reference + * to {@link org.apache.cassandra.utils.MBeanWrapper#instance} via the lambda in {@link #periodicMeterTicker} which + * then attempts to private final fields accessible that can't be changed. We didn't want to measure that stuff + * anyways, but the executor tasks actualy really do need to be measured for that test to work so make this @Unmetered. + */ + @Unmetered private final MBeanWrapper mBeanServer = MBeanWrapper.instance; - private CassandraMetricsRegistry() + final ScheduledFuture periodicMeterTicker; + + CassandraMetricsRegistry(long tickMetersPeriodMicros) { super(); + checkArgument(tickMetersPeriodMicros >= 0); + long initialDelay = ThreadLocalRandom.current().nextLong(tickMetersPeriodMicros); + periodicMeterTicker = ScheduledExecutors.scheduledTasks.scheduleAtFixedRate(this::tickMeters, initialDelay, tickMetersPeriodMicros, TimeUnit.MICROSECONDS); } public Counter counter(MetricName name) @@ -219,6 +253,43 @@ public class CassandraMetricsRegistry extends MetricRegistry if (mBeanServer.isRegistered(name.getMBeanName())) MBeanWrapper.instance.unregisterMBean(name.getMBeanName(), MBeanWrapper.OnException.IGNORE); } + + /** + * Very infrequently used meters generate a linear amount of tick work based on how long it has been + * since the meter was last marked or read. On scales of a year this can be enough to cause the first request + * that needs to mark the meter to time out. Once a day read every meter to force them to run Meter.tickIfNecessary + * so we only ever run at most one day worth of tick work per meter in the request path. + * + * This can be removed if we ever upgrade and switch the default MovingAverage from EWMA to SlidingWindowTimeAverages + */ + private void tickMeters() + { + List failures = new ArrayList<>(); + int droppedFailures = 0; + for (Meter meter : getMeters().values()) + { + try + { + meter.getOneMinuteRate(); + } + catch (Throwable t) + { + if (failures.size() < 10) + failures.add(t); + else + droppedFailures++; + } + } + if (!failures.isEmpty()) + { + Throwable failure = null; + for (Throwable t : failures) + failure = Throwables.merge(failure, t); + // To avoid the scheduled task being cancelled don't leak exceptions + // Runs only once a day so noise is not an issue + logger.error(String.format("Had error(s) attempting to tick meter. Dropped %d exceptions.", droppedFailures), failure); + } + } /** * Strips a single final '$' from input diff --git a/test/unit/org/apache/cassandra/metrics/CassandraMetricsRegistryTest.java b/test/unit/org/apache/cassandra/metrics/CassandraMetricsRegistryTest.java index cd9866c319..0877812b73 100644 --- a/test/unit/org/apache/cassandra/metrics/CassandraMetricsRegistryTest.java +++ b/test/unit/org/apache/cassandra/metrics/CassandraMetricsRegistryTest.java @@ -20,18 +20,24 @@ */ package org.apache.cassandra.metrics; -import static org.junit.Assert.*; - import java.lang.management.ManagementFactory; import java.util.Collection; +import java.util.concurrent.CountDownLatch; +import java.util.concurrent.TimeUnit; +import java.util.concurrent.atomic.AtomicInteger; -import org.apache.cassandra.metrics.CassandraMetricsRegistry.MetricName; import org.junit.Test; +import com.codahale.metrics.Meter; import com.codahale.metrics.jvm.BufferPoolMetricSet; import com.codahale.metrics.jvm.GarbageCollectorMetricSet; import com.codahale.metrics.jvm.MemoryUsageGaugeSet; +import org.apache.cassandra.metrics.CassandraMetricsRegistry.MetricName; +import static org.junit.Assert.assertArrayEquals; +import static org.junit.Assert.assertEquals; +import static org.junit.Assert.assertNotNull; +import static org.junit.Assert.assertTrue; public class CassandraMetricsRegistryTest { @@ -107,4 +113,30 @@ public class CassandraMetricsRegistryTest assertArrayEquals(count, CassandraMetricsRegistry.delta(count, new long[3])); assertArrayEquals(new long[6], CassandraMetricsRegistry.delta(count, new long[]{0, 1, 2, 3, 4, 5, 6, 7, 8, 9})); } + + @Test + public void testTickMeters() throws InterruptedException + { + CassandraMetricsRegistry cmr = new CassandraMetricsRegistry(TimeUnit.SECONDS.toMicros(1)); + int numMeters = 1000; + CountDownLatch ticked = new CountDownLatch(numMeters); + AtomicInteger counted = new AtomicInteger(); + Meter m = new Meter() + { + @Override + public double getOneMinuteRate() { + if (counted.incrementAndGet() % 2 == 0) + throw new RuntimeException("test failure handling"); + ticked.countDown(); + return super.getOneMinuteRate(); + } + }; + for (int ii = 0; ii < numMeters; ii++) + { + cmr.register("ignored" + ii, m); + } + assertNotNull(cmr.periodicMeterTicker); + assertTrue(cmr.periodicMeterTicker.getDelay(TimeUnit.SECONDS) <= 1); + assertTrue(ticked.await(1, TimeUnit.MINUTES)); + } }