Skip to content

Commit 4ca5a0b

Browse files
committed
fix(engine) #5636: capture the departing counters before the removal, not after
Round 3 review on #5640. Point 1 was a real bug, not polish. unregisterDatabase removed the database from the set FIRST and folded its counters SECOND. A throw from accumulateMonotonic in between dropped the database out of `databases` with its contribution never folded into retainedStats, so the next scrape came back lower than the last - which, now that these series are typed as Prometheus counters, is read as a reset and fabricates exactly the rate() spike the baseline exists to prevent. The old comment called that "the pre-#5636 behaviour", which understated it: before, a close decreased a GAUGE and meant nothing. Capture now happens into a temp before the removal, so the window is closed rather than argued away. The one case that still steps back - the capture itself failing, where the database has to leave the registry regardless or every later toJSON() throws on the same dead source - is logged at WARNING instead of FINE, because it is the only remaining path that can produce the artifact and an operator staring at an unexplained spike needs that line. Point 2: statOf defaulting a missing key to 0 is right for the scrape path but means a typo in DB_STAT_KEYS degrades to a silently wrong total, and nothing else would catch it - every other assertion reads through the same defaulting. Now checked against a real getStats() map, reading Profiler's OWN key list reflectively; a second copy of the list in the test would have passed happily while production carried the typo. Verified by planting one. Point 3: metersKeepReportingAfterTheBinderIsCollected did not pin what it claimed. System.gc() is a hint, and since the meters read through the static cache the values came back either way - so it would have kept passing if someone regressed CACHE to an instance field, the exact bug it existed to catch. Replaced with a structural assertion that no field of the binder is an instance field, which does fail on that regression (verified by making CACHE non-static). Points 4 and 5 were confirmations of deliberate choices; no change.
1 parent 9ce18eb commit 4ca5a0b

3 files changed

Lines changed: 76 additions & 11 deletions

File tree

‎engine/src/main/java/com/arcadedb/Profiler.java‎

Lines changed: 22 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -102,21 +102,36 @@ public synchronized void registerDatabase(final DatabaseInternal database) {
102102
* lock-free, so no database lock can be on the other side of the wait.
103103
*/
104104
public synchronized void unregisterDatabase(final DatabaseInternal database) {
105-
if (!databases.remove(database))
105+
if (!databases.contains(database))
106106
// ALREADY UNREGISTERED: DO NOT FOLD ITS COUNTERS IN TWICE
107107
return;
108108

109+
// CAPTURE BEFORE REMOVING, NOT AFTER. Removing first and folding second leaves a window in which a throw from
110+
// accumulateMonotonic drops the database out of `databases` with its contribution never folded into
111+
// retainedStats - so the next scrape is LOWER than the last, which a Prometheus counter reads as a reset and
112+
// turns into a fabricated rate() spike. That is the exact artifact this baseline exists to prevent, so the
113+
// ordering below closes the window rather than relying on the read not to fail.
114+
final long[] departing = new long[STATS_COUNT];
115+
boolean captured = false;
109116
try {
110-
final long[] departing = new long[STATS_COUNT];
111117
accumulateMonotonic(departing, database);
112-
for (int i = 0; i < MONOTONIC_STATS; i++)
113-
retainedStats[i] += departing[i];
118+
captured = true;
114119
} catch (final Exception e) {
115-
// THE CALLER IS MID-CLOSE: A STAT SOURCE ALREADY TORN DOWN MUST NOT TAKE THE CLOSE PATH DOWN WITH IT. THE ONLY
116-
// COST IS THAT THIS DATABASE'S CONTRIBUTION IS LOST, WHICH IS THE PRE-#5636 BEHAVIOUR FOR EVERY DATABASE.
120+
// THE CALLER IS MID-CLOSE: A STAT SOURCE ALREADY TORN DOWN MUST NOT TAKE THE CLOSE PATH DOWN WITH IT. The
121+
// database still has to leave the registry - keeping it would make every later toJSON() throw on the same
122+
// dead source - so this one case genuinely does decrease the totals, and on a typed counter that reads as a
123+
// reset. Logged at WARNING, not FINE: it is the only path that can still produce the artifact, and an
124+
// operator seeing an unexplained rate spike needs this line to explain it.
117125
LogManager.instance()
118-
.log(this, Level.FINE, "Could not retain the profiler counters of a closing database", e);
126+
.log(this, Level.WARNING, "Could not retain the profiler counters of a closing database: the engine "
127+
+ "totals will step back by its contribution, which appears as a counter reset in Prometheus", e);
119128
}
129+
130+
databases.remove(database);
131+
132+
if (captured)
133+
for (int i = 0; i < MONOTONIC_STATS; i++)
134+
retainedStats[i] += departing[i];
120135
}
121136

122137
/**

‎engine/src/test/java/com/arcadedb/Issue5636ProfilerMonotonicTest.java‎

Lines changed: 36 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,8 @@
2828
import org.junit.jupiter.api.Test;
2929

3030
import java.io.File;
31+
import java.lang.reflect.Field;
32+
import java.util.Map;
3133

3234
import static org.assertj.core.api.Assertions.assertThat;
3335

@@ -97,9 +99,42 @@ void closingADatabaseDoesNotRewindTheJvmWideCounters() {
9799
}
98100
}
99101

102+
/**
103+
* {@code statOf} degrades a missing or non-numeric key to 0 so a metrics scrape survives it. That is the right
104+
* trade at runtime, but it also means a typo in {@code DB_STAT_KEYS} - or a source key someone renames later -
105+
* silently produces a wrong total instead of failing. Nothing else would catch it: every other assertion here
106+
* reads through the same defaulting. So the key list is checked against a real stats map.
107+
*/
108+
@Test
109+
void everyAccumulatedStatKeyExistsInARealStatsMap() throws Exception {
110+
// Read Profiler's OWN key list, not a copy of it: a second copy here would pass happily while the production
111+
// list carried the typo. This is the one assertion that has to reach into the class under test.
112+
final Field keysField = Profiler.class.getDeclaredField("DB_STAT_KEYS");
113+
keysField.setAccessible(true);
114+
final String[] dbStatKeys = (String[]) keysField.get(null);
115+
assertThat(dbStatKeys).isNotEmpty();
116+
117+
try (final DatabaseFactory factory = new DatabaseFactory(DB_PATH)) {
118+
final DatabaseInternal db = (DatabaseInternal) factory.create();
119+
try {
120+
final Map<String, Object> dbStats = db.getStats();
121+
for (final String key : dbStatKeys)
122+
assertThat(dbStats.get(key)).as("Profiler.DB_STAT_KEYS entry '%s' is not in DatabaseInternal.getStats()", key)
123+
.isInstanceOf(Number.class);
124+
125+
final Map<String, Object> walStats = db.getTransactionManager().getStats();
126+
for (final String key : new String[] { "pagesWritten", "bytesWritten", "logFiles" })
127+
assertThat(walStats.get(key)).as("Profiler reads WAL stat '%s', which TransactionManager does not emit", key)
128+
.isInstanceOf(Number.class);
129+
} finally {
130+
db.drop();
131+
}
132+
}
133+
}
134+
100135
/**
101136
* A database that is never registered - or is unregistered twice - must not double-count. Guards the
102-
* {@code if (!databases.remove(database)) return;} short-circuit that makes the fold idempotent.
137+
* {@code if (!databases.contains(database)) return;} short-circuit that makes the fold idempotent.
103138
*/
104139
@Test
105140
void unregisteringTwiceFoldsTheCountersOnlyOnce() {

‎server/src/test/java/com/arcadedb/server/monitor/EngineMetricsBinderTest.java‎

Lines changed: 18 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,9 @@
2323
import io.micrometer.core.instrument.simple.SimpleMeterRegistry;
2424
import org.junit.jupiter.api.Test;
2525

26+
import java.lang.reflect.Field;
27+
import java.lang.reflect.Modifier;
28+
2629
import static org.assertj.core.api.Assertions.assertThat;
2730

2831
/**
@@ -108,11 +111,23 @@ void registersPageMergeCounters() {
108111
/**
109112
* Micrometer's {@code (obj, fn)} builders hold a WEAK reference to {@code obj}, and the only production caller does
110113
* {@code new EngineMetricsBinder().bindTo(registry)} - so anchoring the meters to the binder instance would let
111-
* every one of them silently stop reporting at the next GC. The meters read through a static cache instead; this
112-
* pins that they survive the binder becoming unreachable.
114+
* every one of them silently stop reporting at the next GC.
115+
* <p>
116+
* Asserted structurally rather than by forcing a collection: {@code System.gc()} is only a hint, and because the
117+
* meters read through the static cache the values come back either way - so a GC-based test would keep passing if
118+
* someone regressed the cache to an instance field, which is the exact bug it is supposed to catch. What actually
119+
* has to hold is that whatever the meters are anchored to outlives the binder, i.e. that no instance field of the
120+
* binder can be the anchor.
113121
*/
114122
@Test
115-
void metersKeepReportingAfterTheBinderIsCollected() {
123+
void theMetersAreAnchoredToSomethingThatOutlivesTheBinder() {
124+
for (final Field field : EngineMetricsBinder.class.getDeclaredFields())
125+
assertThat(Modifier.isStatic(field.getModifiers()))
126+
.as("EngineMetricsBinder.%s is an instance field. Micrometer holds the meter's read target by WEAK "
127+
+ "reference and the binder is discarded right after bindTo(), so anchoring a meter here would make "
128+
+ "every engine metric stop reporting at the next GC.", field.getName())
129+
.isTrue();
130+
116131
final SimpleMeterRegistry registry = new SimpleMeterRegistry();
117132
new EngineMetricsBinder().bindTo(registry);
118133

0 commit comments

Comments
 (0)