diff --git a/CHANGELOG.md b/CHANGELOG.md index 62d675fbf..04759a5be 100644 --- a/CHANGELOG.md +++ b/CHANGELOG.md @@ -12,6 +12,25 @@ ### New Features +- **[client-v2, jdbc-v2]** Added a Micrometer implementation of the metrics SPI. + `Client.Builder.setMetricsRecorder(new MicrometerMetricsRecorder(meterRegistry))` reports the metrics of every client + operation to a Micrometer `MeterRegistry`: a timer `db.client.operation.duration` per completed operation, a timer + `clickhouse.client.operation.serialization.duration` when the client measured the serialization step, a counter + `clickhouse.client.operation.count` per completed operation, and a counter `clickhouse.client.operation.retries` per + retried attempt. Previously the client could bind only its connection-pool gauges to Micrometer, so exporting the + metrics of the operations themselves was left to the application. Meter names, units, descriptions and tag keys are + the standard ones of the SPI - the recorder derives them through `MetricsSupport`, so they are the names of + `MetricName` and the keys of `MetricAttribute` and mean the same as for every other recorder. A successful operation + carries no `error.type` tag and a failed one does, so the outcomes are separate time series of the same meter and a + failure the server reported also carries `db.response.status_code`; a duration the client did not measure is not + recorded, so no operation is reported with a made-up duration. The seconds of the SPI are handed to the registry as + nanoseconds, because a Micrometer timer keeps its own time unit, so a backend publishes the duration in the unit it + expects. The no-argument constructor reports to `Metrics.globalRegistry`, which is what the jdbc-v2 + `jdbc_metrics_recorder` property needs, so a JDBC connection exports its metrics to Micrometer by naming the class - + `jdbc_metrics_recorder=com.clickhouse.client.api.observability.micrometer.MicrometerMetricsRecorder` - without + application code. `micrometer-core` stays an optional dependency of `client-v2` and is not shaded into the `all` + artifacts, so a client that does not use this recorder needs no Micrometer on the classpath. + (https://github.com/ClickHouse/clickhouse-java/issues/2975) - **[client-v2, jdbc-v2]** Added a metrics SPI that lets an application export the metrics of client operations to any metrics backend. `Client.Builder.setMetricsRecorder(MetricsRecorder)` registers a backend-agnostic recorder from the `com.clickhouse.client.api.observability` package, and the jdbc-v2 property `jdbc_metrics_recorder` names the recorder diff --git a/client-v2/pom.xml b/client-v2/pom.xml index 398bbb69f..c1b4e92d2 100644 --- a/client-v2/pom.xml +++ b/client-v2/pom.xml @@ -73,7 +73,7 @@ io.micrometer micrometer-core - 1.14.3 + ${micrometer.version} true compile @@ -94,6 +94,14 @@ + + + io.micrometer + micrometer-registry-prometheus + ${micrometer.version} + test + io.opentelemetry opentelemetry-sdk diff --git a/client-v2/src/main/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorder.java b/client-v2/src/main/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorder.java new file mode 100644 index 000000000..ebcc3ca51 --- /dev/null +++ b/client-v2/src/main/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorder.java @@ -0,0 +1,232 @@ +package com.clickhouse.client.api.observability.micrometer; + +import com.clickhouse.client.api.insert.InsertSettings; +import com.clickhouse.client.api.metrics.OperationMetrics; +import com.clickhouse.client.api.observability.DefaultMetricsRecorder; +import com.clickhouse.client.api.observability.MetricAttribute; +import com.clickhouse.client.api.observability.MetricName; +import com.clickhouse.client.api.observability.MetricsRecorder; +import com.clickhouse.client.api.observability.MetricsSupport; +import com.clickhouse.client.api.query.QuerySettings; +import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.MeterRegistry; +import io.micrometer.core.instrument.Metrics; +import io.micrometer.core.instrument.Tag; +import io.micrometer.core.instrument.Tags; +import io.micrometer.core.instrument.Timer; + +import java.time.Duration; +import java.util.ArrayList; +import java.util.List; +import java.util.Map; +import java.util.concurrent.TimeUnit; + +/** + * {@link MetricsRecorder} that reports the metrics of client operations to a Micrometer + * {@link MeterRegistry}. + *

+ * It is registered like any other recorder: + *

{@code
+ * Client client = new Client.Builder()
+ *         .addEndpoint("http://localhost:8123")
+ *         .setMetricsRecorder(new MicrometerMetricsRecorder(meterRegistry))
+ *         .build();
+ * }
+ * The no-argument constructor reports to {@link Metrics#globalRegistry}, so the recorder can also be + * named by the jdbc-v2 {@code jdbc_metrics_recorder} connection property, which instantiates the + * class it names through its public no-argument constructor. + *

+ * Every meter carries the client's standard name, description and unit, which are the ones of + * {@link MetricName}, and the recorded values and attributes are derived by {@link MetricsSupport}, + * so the tag keys are the ones listed in {@link MetricAttribute} and both mean the same as for every + * other recorder. Four meters are reported: + *

+ * Every meter of a metric carries the same tag keys - all keys of {@link MetricAttribute} - and the + * value of an attribute the client did not report is {@link #ABSENT_ATTRIBUTE_VALUE}. A tag of a + * Micrometer meter is a label of the exported time series, and a label that appears on one outcome + * only makes the series of a metric hard to aggregate and is rejected outright by some registries, so + * the recorder reports the same labels for every outcome instead of leaving a tag out. A successful + * operation therefore reports no error type while a failed one does, and the two outcomes are + * separate time series of the same meter. + * A duration the client did not measure is not reported at all, so a recorded duration is always one + * the client observed. + *

+ * A Micrometer timer keeps its own time unit, so the seconds of the SPI are handed to the registry as + * nanoseconds and the registry publishes them in the unit its backend expects. A timer records a + * count, a sum and a maximum; percentiles and a histogram are a decision of the application, which + * enables them for these meters with a Micrometer {@code MeterFilter}. + *

+ * Instances are thread-safe and can be shared by several clients. + */ +public class MicrometerMetricsRecorder extends DefaultMetricsRecorder { + + /** + * Value of the tag of an attribute the client did not report. Every meter of a metric carries every + * tag key, so an absent value is reported as this placeholder instead of the tag being left out. + */ + public static final String ABSENT_ATTRIBUTE_VALUE = "none"; + + private static final double NANOS_PER_SECOND = 1_000_000_000d; + + private final MeterRegistry registry; + + /** + * Creates a recorder that reports to the {@linkplain Metrics#globalRegistry global} Micrometer + * registry. Use it when the application configures Micrometer globally, and when the recorder is + * named by the jdbc-v2 {@code jdbc_metrics_recorder} property, which needs a no-argument + * constructor. + */ + public MicrometerMetricsRecorder() { + this(Metrics.globalRegistry); + } + + /** + * Creates a recorder that reports to the given registry. + * + * @param registry - registry the meters are registered with; must not be {@code null} + */ + public MicrometerMetricsRecorder(MeterRegistry registry) { + if (registry == null) { + throw new IllegalArgumentException("registry must not be null"); + } + this.registry = registry; + } + + /** + * Returns the registry this recorder reports to. + * + * @return meter registry; never {@code null} + */ + public MeterRegistry getRegistry() { + return registry; + } + + @Override + public void recordQuerySuccess(QuerySettings settings, OperationMetrics metrics) { + MetricsSupport support = getMetricsSupport(); + recordCompletion(support.operationDuration(metrics), support.serializationDuration(metrics), + support.queryAttributes(settings, null)); + } + + @Override + public void recordInsertSuccess(InsertSettings settings, String tableName, OperationMetrics metrics) { + MetricsSupport support = getMetricsSupport(); + recordCompletion(support.operationDuration(metrics), support.serializationDuration(metrics), + support.insertAttributes(settings, tableName, null)); + } + + @Override + public void recordQueryFailure(QuerySettings settings, Duration duration, Throwable t) { + MetricsSupport support = getMetricsSupport(); + recordCompletion(support.duration(duration), MetricsSupport.DURATION_UNKNOWN, + support.queryAttributes(settings, t)); + } + + @Override + public void recordInsertFailure(InsertSettings settings, String tableName, Duration duration, Throwable t) { + MetricsSupport support = getMetricsSupport(); + recordCompletion(support.duration(duration), MetricsSupport.DURATION_UNKNOWN, + support.insertAttributes(settings, tableName, t)); + } + + @Override + public void recordQueryRetry(QuerySettings settings, Throwable cause) { + count(MetricName.OPERATION_RETRIES, tagsOf(getMetricsSupport().queryAttributes(settings, cause))); + } + + @Override + public void recordInsertRetry(InsertSettings settings, String tableName, Throwable cause) { + count(MetricName.OPERATION_RETRIES, + tagsOf(getMetricsSupport().insertAttributes(settings, tableName, cause))); + } + + /** + * Reports the meters of one completed operation - the operation is counted, and each duration the + * client measured is recorded. + * + * @param duration - duration of the operation in seconds, or {@link MetricsSupport#DURATION_UNKNOWN} + * @param serializationDuration - duration of the serialization step in seconds, or + * {@link MetricsSupport#DURATION_UNKNOWN} + * @param attributes - attributes of the operation, keyed by {@link MetricAttribute#getKey()} + */ + protected void recordCompletion(double duration, double serializationDuration, Map attributes) { + Tags tags = tagsOf(attributes); + count(MetricName.OPERATION_COUNT, tags); + recordDuration(MetricName.OPERATION_DURATION, duration, tags); + recordDuration(MetricName.OPERATION_SERIALIZATION_DURATION, serializationDuration, tags); + } + + /** + * Records a duration on the timer of the given metric. A duration the client did not measure is + * not reported, so the timer counts only the operations it has a duration of. + * + * @param name - metric to record + * @param seconds - duration in seconds, or {@link MetricsSupport#DURATION_UNKNOWN} + * @param tags - tags of the meter + */ + protected void recordDuration(MetricName name, double seconds, Tags tags) { + if (Double.isNaN(seconds) || seconds < 0) { + return; + } + Timer.builder(name.getKey()) + .description(name.getDescription()) + .tags(tags) + .register(registry) + .record((long) (seconds * NANOS_PER_SECOND), TimeUnit.NANOSECONDS); + } + + /** + * Increments the counter of the given metric by one. + * + * @param name - metric to count + * @param tags - tags of the meter + */ + protected void count(MetricName name, Tags tags) { + Counter.builder(name.getKey()) + .description(name.getDescription()) + .baseUnit(baseUnitOf(name)) + .tags(tags) + .register(registry) + .increment(); + } + + /** + * Returns the base unit a meter of the given metric is registered with. A Micrometer registry + * reports the base unit as a part of the name of the meter, so a unit that is a UCUM annotation + * like {@code {operation}} - which names what is counted rather than a unit of measure - is not + * reported, and the metric keeps the name of {@link MetricName}. + * + * @param name - metric a meter is registered for + * @return base unit of the meter, or {@code null} when it has none + */ + protected String baseUnitOf(MetricName name) { + String unit = name.getUnit(); + return unit != null && unit.startsWith("{") ? null : unit; + } + + /** + * Converts the attributes of an operation to Micrometer tags. Every key of + * {@link MetricAttribute} is reported, because a registry may require that every meter of a metric + * carries the same tag keys; the value of an attribute the client did not report is + * {@link #ABSENT_ATTRIBUTE_VALUE}. + * + * @param attributes - attributes of the operation, keyed by {@link MetricAttribute#getKey()} + * @return tags of the meter + */ + protected Tags tagsOf(Map attributes) { + MetricAttribute[] keys = MetricAttribute.values(); + List tags = new ArrayList<>(keys.length); + for (MetricAttribute key : keys) { + Object value = attributes == null ? null : attributes.get(key.getKey()); + tags.add(Tag.of(key.getKey(), value == null ? ABSENT_ATTRIBUTE_VALUE : String.valueOf(value))); + } + return Tags.of(tags); + } +} diff --git a/client-v2/src/test/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorderUnitTest.java b/client-v2/src/test/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorderUnitTest.java new file mode 100644 index 000000000..777743a80 --- /dev/null +++ b/client-v2/src/test/java/com/clickhouse/client/api/observability/micrometer/MicrometerMetricsRecorderUnitTest.java @@ -0,0 +1,335 @@ +package com.clickhouse.client.api.observability.micrometer; + +import com.clickhouse.client.api.ServerException; +import com.clickhouse.client.api.insert.InsertSettings; +import com.clickhouse.client.api.internal.ClientStatisticsHolder; +import com.clickhouse.client.api.metrics.ClientMetrics; +import com.clickhouse.client.api.metrics.OperationMetrics; +import com.clickhouse.client.api.metrics.OperationType; +import com.clickhouse.client.api.observability.MetricAttribute; +import com.clickhouse.client.api.observability.MetricName; +import com.clickhouse.client.api.query.QuerySettings; +import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.Meter; +import io.micrometer.core.instrument.Metrics; +import io.micrometer.core.instrument.Tag; +import io.micrometer.core.instrument.Timer; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import io.micrometer.prometheusmetrics.PrometheusConfig; +import io.micrometer.prometheusmetrics.PrometheusMeterRegistry; +import org.testng.Assert; +import org.testng.annotations.AfterMethod; +import org.testng.annotations.BeforeMethod; +import org.testng.annotations.DataProvider; +import org.testng.annotations.Test; + +import java.time.Duration; +import java.util.ArrayList; +import java.util.Collections; +import java.util.List; +import java.util.concurrent.TimeUnit; + +public class MicrometerMetricsRecorderUnitTest { + + private static final String DATABASE = "metrics_db"; + + private SimpleMeterRegistry registry; + private MicrometerMetricsRecorder recorder; + + @BeforeMethod + void setUp() { + registry = new SimpleMeterRegistry(); + recorder = new MicrometerMetricsRecorder(registry); + } + + @AfterMethod + void tearDown() { + registry.close(); + } + + @Test + public void testQuerySuccessRecordsDurationCountAndStandardTags() { + recorder.recordQuerySuccess(querySettings(), measuredMetrics(OperationType.QUERY, ClientMetrics.OP_DURATION)); + + Timer duration = onlyTimer(MetricName.OPERATION_DURATION); + Assert.assertEquals(duration.count(), 1L); + Assert.assertTrue(duration.totalTime(TimeUnit.NANOSECONDS) > 0, + "Unexpected duration: " + duration.totalTime(TimeUnit.NANOSECONDS)); + Assert.assertEquals(tag(duration, MetricAttribute.DB_SYSTEM_NAME), "clickhouse"); + Assert.assertEquals(tag(duration, MetricAttribute.DB_NAMESPACE), DATABASE); + Assert.assertEquals(tag(duration, MetricAttribute.DB_OPERATION_NAME), "query"); + Assert.assertEquals(tag(duration, MetricAttribute.ERROR_TYPE), + MicrometerMetricsRecorder.ABSENT_ATTRIBUTE_VALUE, "the operation succeeded"); + Assert.assertEquals(tag(duration, MetricAttribute.DB_COLLECTION_NAME), + MicrometerMetricsRecorder.ABSENT_ATTRIBUTE_VALUE, "a query has no table"); + + Assert.assertEquals(onlyCounter(MetricName.OPERATION_COUNT).count(), 1d); + Assert.assertTrue(timers(MetricName.OPERATION_SERIALIZATION_DURATION).isEmpty(), + "the client measures the serialization step of an insert only"); + Assert.assertTrue(counters(MetricName.OPERATION_RETRIES).isEmpty(), "no attempt failed"); + } + + @Test + public void testInsertSuccessRecordsSerializationDurationAndTargetTable() { + recorder.recordInsertSuccess(insertSettings(), "events", + measuredMetrics(OperationType.INSERT, ClientMetrics.OP_DURATION, ClientMetrics.OP_SERIALIZATION)); + + Timer duration = onlyTimer(MetricName.OPERATION_DURATION); + Assert.assertEquals(duration.count(), 1L); + Assert.assertEquals(tag(duration, MetricAttribute.DB_OPERATION_NAME), "insert"); + Assert.assertEquals(tag(duration, MetricAttribute.DB_COLLECTION_NAME), "events"); + + Timer serialization = onlyTimer(MetricName.OPERATION_SERIALIZATION_DURATION); + Assert.assertEquals(serialization.count(), 1L); + Assert.assertTrue(serialization.totalTime(TimeUnit.NANOSECONDS) > 0); + Assert.assertEquals(tag(serialization, MetricAttribute.DB_COLLECTION_NAME), "events"); + + Assert.assertEquals(onlyCounter(MetricName.OPERATION_COUNT).count(), 1d); + } + + @Test + public void testDurationTheClientDidNotMeasureIsNotRecorded() { + recorder.recordQuerySuccess(querySettings(), null); + + Assert.assertTrue(timers(MetricName.OPERATION_DURATION).isEmpty(), + "a duration the client did not measure must not be recorded as a value"); + Assert.assertTrue(timers(MetricName.OPERATION_SERIALIZATION_DURATION).isEmpty()); + Assert.assertEquals(onlyCounter(MetricName.OPERATION_COUNT).count(), 1d, + "the operation still completed and is counted"); + } + + @Test + public void testFailedOperationRecordsMeasuredDurationAndErrorType() { + IllegalStateException failure = new IllegalStateException("boom"); + + recorder.recordQueryFailure(querySettings(), Duration.ofMillis(1500), failure); + + Timer duration = onlyTimer(MetricName.OPERATION_DURATION); + Assert.assertEquals(duration.count(), 1L); + Assert.assertEquals(duration.totalTime(TimeUnit.SECONDS), 1.5d, 1e-6, + "the seconds of the SPI must reach the registry unscaled"); + Assert.assertEquals(tag(duration, MetricAttribute.ERROR_TYPE), IllegalStateException.class.getName()); + Assert.assertEquals(tag(duration, MetricAttribute.DB_RESPONSE_STATUS_CODE), + MicrometerMetricsRecorder.ABSENT_ATTRIBUTE_VALUE, + "a client-side failure carries no server error code"); + + Counter count = onlyCounter(MetricName.OPERATION_COUNT); + Assert.assertEquals(count.count(), 1d, "a failed operation is counted too"); + Assert.assertEquals(tag(count, MetricAttribute.ERROR_TYPE), IllegalStateException.class.getName()); + } + + @Test + public void testServerFailureCarriesTheServerErrorCode() { + ServerException serverException = new ServerException(60, "table not found", 404, "q-1"); + + recorder.recordInsertFailure(insertSettings(), "events", Duration.ofMillis(250), + new RuntimeException(serverException)); + + Timer duration = onlyTimer(MetricName.OPERATION_DURATION); + Assert.assertEquals(duration.totalTime(TimeUnit.SECONDS), 0.25d, 1e-6); + Assert.assertEquals(tag(duration, MetricAttribute.ERROR_TYPE), ServerException.class.getName()); + Assert.assertEquals(tag(duration, MetricAttribute.DB_RESPONSE_STATUS_CODE), "60"); + Assert.assertEquals(tag(duration, MetricAttribute.DB_COLLECTION_NAME), "events"); + } + + @Test + public void testSuccessAndFailureOfTheSameMetricAreSeparateTimeSeries() { + recorder.recordQuerySuccess(querySettings(), measuredMetrics(OperationType.QUERY, ClientMetrics.OP_DURATION)); + recorder.recordQueryFailure(querySettings(), Duration.ofMillis(100), new IllegalStateException("boom")); + + List durations = timers(MetricName.OPERATION_DURATION); + Assert.assertEquals(durations.size(), 2, "Unexpected timers: " + durations); + Assert.assertEquals(registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.ERROR_TYPE.getKey(), IllegalStateException.class.getName()) + .timer().count(), 1L); + Assert.assertEquals(counters(MetricName.OPERATION_COUNT).size(), 2, + "the number of operations by outcome is the count of separate series"); + } + + @Test + public void testEveryMeterOfAMetricCarriesTheSameTagKeys() { + recorder.recordQuerySuccess(querySettings(), measuredMetrics(OperationType.QUERY, ClientMetrics.OP_DURATION)); + recorder.recordQueryFailure(querySettings(), Duration.ofMillis(100), + new RuntimeException(new ServerException(60, "table not found", 404, "q-1"))); + recorder.recordInsertSuccess(insertSettings(), "events", + measuredMetrics(OperationType.INSERT, ClientMetrics.OP_DURATION)); + recorder.recordInsertRetry(insertSettings(), "events", new IllegalStateException("boom")); + + List expectedKeys = new ArrayList<>(); + for (MetricAttribute attribute : MetricAttribute.values()) { + expectedKeys.add(attribute.getKey()); + } + Collections.sort(expectedKeys); + for (Meter meter : registry.getMeters()) { + List keys = new ArrayList<>(); + for (Tag tag : meter.getId().getTags()) { + keys.add(tag.getKey()); + Assert.assertNotNull(tag.getValue(), "Unexpected tag: " + tag); + } + Collections.sort(keys); + Assert.assertEquals(keys, expectedKeys, "Unexpected tag keys of " + meter.getId()); + } + } + + @Test + public void testEveryOutcomeOfAMetricIsExportedWithTheSameLabels() { + PrometheusMeterRegistry prometheusRegistry = new PrometheusMeterRegistry(PrometheusConfig.DEFAULT); + MicrometerMetricsRecorder prometheusRecorder = new MicrometerMetricsRecorder(prometheusRegistry); + try { + prometheusRecorder.recordQuerySuccess(querySettings(), + measuredMetrics(OperationType.QUERY, ClientMetrics.OP_DURATION)); + prometheusRecorder.recordInsertFailure(insertSettings(), "events", Duration.ofMillis(100), + new RuntimeException(new ServerException(60, "table not found", 404, "q-1"))); + + List series = new ArrayList<>(); + for (String line : prometheusRegistry.scrape().split("\n")) { + if (line.startsWith("db_client_operation_duration_seconds_count")) { + series.add(line); + } + } + Assert.assertEquals(series.size(), 2, "Unexpected series: " + series); + for (String line : series) { + for (MetricAttribute attribute : MetricAttribute.values()) { + Assert.assertTrue(line.contains(attribute.getKey().replace('.', '_') + "="), + "Series without " + attribute.getKey() + ": " + line); + } + } + } finally { + prometheusRegistry.close(); + } + } + + @Test + public void testFailureWithoutAMeasuredDurationIsStillCounted() { + recorder.recordQueryFailure(querySettings(), null, new IllegalStateException("boom")); + + Assert.assertTrue(timers(MetricName.OPERATION_DURATION).isEmpty(), + "a duration the client did not measure must not be recorded as a value"); + Counter count = onlyCounter(MetricName.OPERATION_COUNT); + Assert.assertEquals(count.count(), 1d, "the operation still failed and is counted"); + Assert.assertEquals(tag(count, MetricAttribute.ERROR_TYPE), IllegalStateException.class.getName()); + } + + @Test + public void testEachRetriedAttemptIsCounted() { + recorder.recordQueryRetry(querySettings(), new IllegalStateException("first")); + recorder.recordQueryRetry(querySettings(), new IllegalStateException("second")); + + Counter retries = onlyCounter(MetricName.OPERATION_RETRIES); + Assert.assertEquals(retries.count(), 2d, "an operation that succeeds on its third attempt reports two retries"); + Assert.assertEquals(tag(retries, MetricAttribute.DB_OPERATION_NAME), "query"); + Assert.assertEquals(tag(retries, MetricAttribute.ERROR_TYPE), IllegalStateException.class.getName()); + Assert.assertTrue(counters(MetricName.OPERATION_COUNT).isEmpty(), "a retried attempt is not a completion"); + } + + @Test + public void testInsertRetryCarriesTheTargetTable() { + recorder.recordInsertRetry(insertSettings(), "events", new IllegalStateException("boom")); + + Counter retries = onlyCounter(MetricName.OPERATION_RETRIES); + Assert.assertEquals(retries.count(), 1d); + Assert.assertEquals(tag(retries, MetricAttribute.DB_OPERATION_NAME), "insert"); + Assert.assertEquals(tag(retries, MetricAttribute.DB_COLLECTION_NAME), "events"); + } + + @Test(dataProvider = "reportedMetrics") + public void testMeterIsRegisteredWithTheStandardNameAndDescription(MetricName name) { + recorder.recordInsertSuccess(insertSettings(), "events", + measuredMetrics(OperationType.INSERT, ClientMetrics.OP_DURATION, ClientMetrics.OP_SERIALIZATION)); + recorder.recordInsertRetry(insertSettings(), "events", new IllegalStateException("boom")); + + Meter meter = registry.find(name.getKey()).meter(); + Assert.assertNotNull(meter, "no meter named " + name.getKey()); + Assert.assertEquals(meter.getId().getDescription(), name.getDescription()); + if (meter instanceof Timer) { + // a timer keeps the base time unit of the registry, the SPI unit of a duration is the same one + Assert.assertEquals(meter.getId().getBaseUnit(), "seconds"); + } else { + Assert.assertNull(meter.getId().getBaseUnit(), + "a UCUM annotation names what is counted and would end up in the name of the meter"); + } + } + + @DataProvider(name = "reportedMetrics") + public static Object[][] reportedMetrics() { + return new Object[][]{ + {MetricName.OPERATION_DURATION}, + {MetricName.OPERATION_SERIALIZATION_DURATION}, + {MetricName.OPERATION_COUNT}, + {MetricName.OPERATION_RETRIES}, + }; + } + + @Test + public void testRecorderWithoutARegistryReportsToTheGlobalOne() { + SimpleMeterRegistry globalMember = new SimpleMeterRegistry(); + Metrics.addRegistry(globalMember); + try { + MicrometerMetricsRecorder globalRecorder = new MicrometerMetricsRecorder(); + Assert.assertSame(globalRecorder.getRegistry(), Metrics.globalRegistry); + + globalRecorder.recordQueryFailure(querySettings(), Duration.ofMillis(100), + new IllegalStateException("boom")); + + Timer duration = globalMember.find(MetricName.OPERATION_DURATION.getKey()).timer(); + Assert.assertNotNull(duration, "the meters must reach the registries of the global one"); + Assert.assertEquals(duration.count(), 1L); + } finally { + Metrics.removeRegistry(globalMember); + globalMember.close(); + } + } + + @Test(expectedExceptions = IllegalArgumentException.class, + expectedExceptionsMessageRegExp = "registry must not be null") + public void testRecorderWithoutAValidRegistryIsRejected() { + new MicrometerMetricsRecorder(null); + } + + private OperationMetrics measuredMetrics(OperationType type, ClientMetrics... measured) { + ClientStatisticsHolder holder = new ClientStatisticsHolder(); + for (ClientMetrics metric : measured) { + holder.start(metric); + } + OperationMetrics metrics = new OperationMetrics(holder, type); + metrics.operationComplete(); + return metrics; + } + + private QuerySettings querySettings() { + return new QuerySettings().setDatabase(DATABASE); + } + + private InsertSettings insertSettings() { + return new InsertSettings().setDatabase(DATABASE); + } + + private Timer onlyTimer(MetricName name) { + List found = timers(name); + Assert.assertEquals(found.size(), 1, "Expected exactly one " + name.getKey() + " but got " + found); + return found.get(0); + } + + private Counter onlyCounter(MetricName name) { + List found = counters(name); + Assert.assertEquals(found.size(), 1, "Expected exactly one " + name.getKey() + " but got " + found); + return found.get(0); + } + + private List timers(MetricName name) { + return new ArrayList<>(registry.find(name.getKey()).timers()); + } + + private List counters(MetricName name) { + return new ArrayList<>(registry.find(name.getKey()).counters()); + } + + private static String tag(Meter meter, MetricAttribute attribute) { + for (Tag tag : meter.getId().getTags()) { + if (tag.getKey().equals(attribute.getKey())) { + return tag.getValue(); + } + } + return null; + } +} diff --git a/client-v2/src/test/java/com/clickhouse/client/observability/micrometer/MicrometerMetricsRecorderTest.java b/client-v2/src/test/java/com/clickhouse/client/observability/micrometer/MicrometerMetricsRecorderTest.java new file mode 100644 index 000000000..630db6015 --- /dev/null +++ b/client-v2/src/test/java/com/clickhouse/client/observability/micrometer/MicrometerMetricsRecorderTest.java @@ -0,0 +1,149 @@ +package com.clickhouse.client.observability.micrometer; + +import com.clickhouse.client.BaseIntegrationTest; +import com.clickhouse.client.ClickHouseNode; +import com.clickhouse.client.ClickHouseProtocol; +import com.clickhouse.client.ClickHouseServerForTest; +import com.clickhouse.client.api.Client; +import com.clickhouse.client.api.ServerException; +import com.clickhouse.client.api.enums.Protocol; +import com.clickhouse.client.api.observability.MetricAttribute; +import com.clickhouse.client.api.observability.MetricName; +import com.clickhouse.client.api.observability.micrometer.MicrometerMetricsRecorder; +import com.clickhouse.client.api.query.QueryResponse; +import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.Timer; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.testng.Assert; +import org.testng.annotations.AfterMethod; +import org.testng.annotations.BeforeMethod; +import org.testng.annotations.Test; + +import java.util.Collections; +import java.util.concurrent.ExecutionException; +import java.util.concurrent.TimeUnit; + +public class MicrometerMetricsRecorderTest extends BaseIntegrationTest { + + private static final String TABLE = "micrometer_metrics_recorder_test_table"; + + private SimpleMeterRegistry registry; + private Client client; + private String database; + + @BeforeMethod(groups = {"integration"}) + void setUp() throws Exception { + ClickHouseNode node = getServer(ClickHouseProtocol.HTTP); + database = ClickHouseServerForTest.getDatabase(); + registry = new SimpleMeterRegistry(); + client = new Client.Builder() + .addEndpoint(Protocol.HTTP, node.getHost(), node.getPort(), isCloud()) + .setUsername("default") + .setPassword(ClickHouseServerForTest.getPassword()) + .setDefaultDatabase(database) + .setMetricsRecorder(new MicrometerMetricsRecorder(registry)) + .build(); + client.execute("DROP TABLE IF EXISTS " + TABLE).get(); + client.execute("CREATE TABLE " + TABLE + " (value String) ENGINE = MergeTree ORDER BY value").get(); + registry.clear(); + } + + @AfterMethod(groups = {"integration"}) + void tearDown() throws Exception { + if (client != null) { + client.execute("DROP TABLE IF EXISTS " + TABLE).get(); + client.close(); + } + if (registry != null) { + registry.close(); + } + } + + @Test(groups = {"integration"}) + public void testSuccessfulQueryIsTimedAndCounted() throws Exception { + try (QueryResponse response = client.query("SELECT value FROM " + TABLE).get()) { + Assert.assertNotNull(response); + } + + Timer duration = registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.DB_OPERATION_NAME.getKey(), "query") + .tag(MetricAttribute.DB_NAMESPACE.getKey(), database) + .timer(); + Assert.assertNotNull(duration, "Unexpected meters: " + registry.getMeters()); + Assert.assertEquals(duration.count(), 1L); + Assert.assertTrue(duration.totalTime(TimeUnit.NANOSECONDS) > 0); + + Counter count = registry.find(MetricName.OPERATION_COUNT.getKey()).counter(); + Assert.assertNotNull(count); + Assert.assertEquals(count.count(), 1d); + Assert.assertEquals(duration.getId().getTag(MetricAttribute.ERROR_TYPE.getKey()), + MicrometerMetricsRecorder.ABSENT_ATTRIBUTE_VALUE, "the operation succeeded"); + } + + @Test(groups = {"integration"}) + public void testSuccessfulInsertIsTimedWithItsSerializationStep() throws Exception { + client.register(ValuePojo.class, client.getTableSchema(TABLE)); + registry.clear(); + + client.insert(TABLE, Collections.singletonList(new ValuePojo("a"))).get().close(); + + Timer duration = registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.DB_OPERATION_NAME.getKey(), "insert") + .tag(MetricAttribute.DB_COLLECTION_NAME.getKey(), TABLE) + .timer(); + Assert.assertNotNull(duration, "Unexpected meters: " + registry.getMeters()); + Assert.assertEquals(duration.count(), 1L); + + Timer serialization = registry.find(MetricName.OPERATION_SERIALIZATION_DURATION.getKey()).timer(); + Assert.assertNotNull(serialization); + Assert.assertEquals(serialization.count(), 1L); + Assert.assertTrue(serialization.totalTime(TimeUnit.NANOSECONDS) > 0); + Assert.assertEquals(serialization.getId().getTag(MetricAttribute.DB_COLLECTION_NAME.getKey()), TABLE); + } + + @Test(groups = {"integration"}) + public void testFailedQueryIsTimedWithTheServerErrorCode() { + try { + client.query("SELECT * FROM table_that_does_not_exist_at_all").get(); + Assert.fail("querying a missing table must fail"); + } catch (ExecutionException e) { + Assert.assertTrue(e.getCause() instanceof ServerException, "Unexpected cause: " + e.getCause()); + } catch (ServerException e) { + // synchronous operations report the server failure directly + } catch (Exception e) { + Assert.fail("Unexpected exception: " + e); + } + + Timer duration = registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.ERROR_TYPE.getKey(), ServerException.class.getName()) + .tag(MetricAttribute.DB_RESPONSE_STATUS_CODE.getKey(), String.valueOf(ServerException.TABLE_NOT_FOUND)) + .timer(); + Assert.assertNotNull(duration, "Unexpected meters: " + registry.getMeters()); + Assert.assertEquals(duration.count(), 1L); + Assert.assertTrue(duration.totalTime(TimeUnit.NANOSECONDS) > 0); + + Counter count = registry.find(MetricName.OPERATION_COUNT.getKey()) + .tag(MetricAttribute.ERROR_TYPE.getKey(), ServerException.class.getName()).counter(); + Assert.assertNotNull(count, "a failed operation is counted too"); + Assert.assertEquals(count.count(), 1d); + } + + public static class ValuePojo { + private String value; + + public ValuePojo() { + } + + public ValuePojo(String value) { + this.value = value; + } + + public String getValue() { + return value; + } + + public void setValue(String value) { + this.value = value; + } + } +} diff --git a/docs/features.md b/docs/features.md index 071c99d2f..308f694de 100644 --- a/docs/features.md +++ b/docs/features.md @@ -130,3 +130,17 @@ Compatibility-sensitive traits: - A failure sets the OpenTelemetry span status to `ERROR`, records `error.type`, and records the failure itself as an OpenTelemetry exception event, so its message and stack trace are reported too; the ClickHouse error code and the HTTP status are recorded as separate attributes, not as the status description. - `Span#end()` is idempotent: a span is exported once even if it is ended more than once. - The recorder does not make any span current. The client hands its response to the caller before the response body is read, so spans are ended on threads the recorder does not control and an application that wants the client's span in its own context must make it current itself. + +## `client-v2` and `jdbc-v2` Micrometer metrics recording + +- Micrometer metrics recording: `new MicrometerMetricsRecorder(meterRegistry)` (package `com.clickhouse.client.api.observability.micrometer`) is a `MetricsRecorder` that reports the metrics of client operations to a Micrometer `MeterRegistry`. It is registered like any other recorder, with `Client.Builder.setMetricsRecorder(...)`. The no-argument constructor reports to the global registry `io.micrometer.core.instrument.Metrics.globalRegistry`, so the class can also be named by the jdbc-v2 `jdbc_metrics_recorder` property, which instantiates the recorder it names through a public no-argument constructor - that is how a JDBC connection exports its metrics to Micrometer without application code. `micrometer-core` is an optional dependency of `client-v2`: this recorder is usable only by an application that already provides Micrometer at runtime, and it is not shaded into the `client-v2` `all` artifact or into `clickhouse-jdbc-all`, so a client that does not use it needs no Micrometer on the classpath. +- Reported meters follow the `client-v2` metrics contract: the names, units and descriptions are the ones of `MetricName`, and the recorded values and attributes are derived through `MetricsSupport`, so the tag keys are the ones listed in `MetricAttribute`. Four meters are reported - a `Timer` named `db.client.operation.duration` per completed operation, a `Timer` named `clickhouse.client.operation.serialization.duration` when the client measured the serialization step, a `Counter` named `clickhouse.client.operation.count` per completed operation, and a `Counter` named `clickhouse.client.operation.retries` per retried attempt. + +Compatibility-sensitive traits: + +- Every meter of a metric carries the same tag keys - all keys of `MetricAttribute` - and an attribute the client did not report is tagged `none` (`MicrometerMetricsRecorder.ABSENT_ATTRIBUTE_VALUE`) rather than left out, because a tag is a label of the exported time series and a label present on one outcome only makes the series of a metric hard to aggregate. A successful operation therefore reports `error.type=none` and a failed one the type of its failure, so the two outcomes are separate time series of the same meter and the number of operations by outcome is the count of those series. A failure the server reported also carries `db.response.status_code`. +- A duration the client did not measure (`MetricsSupport.DURATION_UNKNOWN`) is not recorded, so a timer counts only the operations it has a duration of, and no operation is reported with a made-up duration. The operation is still counted. +- Durations are handed to the registry in nanoseconds, because a Micrometer timer keeps its own time unit while the SPI reports seconds. A registry therefore publishes the duration in the unit its backend expects, without a scaling error. +- Attribute values become tag values through `String.valueOf`. The unit of a counted metric (`{operation}`, `{retry}`) is a UCUM annotation that names what is counted rather than a unit of measure, and a Micrometer registry reports the base unit as a part of the name of the meter, so it is not passed to the registry and the meter keeps the name of `MetricName`. A timer is registered with the base time unit of the registry. +- The timers record a count, a sum and a maximum. Percentiles and a histogram are a decision of the application, which enables them for these meters with a Micrometer `MeterFilter`; the recorder does not enable them, because they multiply the exported series. +- Each completed operation increments the count meter exactly once and each retried attempt increments the retry meter exactly once, so a retry is never counted as a completion. diff --git a/jdbc-v2/pom.xml b/jdbc-v2/pom.xml index be33c5512..d47fbbf14 100644 --- a/jdbc-v2/pom.xml +++ b/jdbc-v2/pom.xml @@ -121,6 +121,14 @@ ${lombok.version} test + + + io.micrometer + micrometer-core + ${micrometer.version} + test + diff --git a/jdbc-v2/src/test/java/com/clickhouse/jdbc/MicrometerMetricsRecorderTest.java b/jdbc-v2/src/test/java/com/clickhouse/jdbc/MicrometerMetricsRecorderTest.java new file mode 100644 index 000000000..9ebb520df --- /dev/null +++ b/jdbc-v2/src/test/java/com/clickhouse/jdbc/MicrometerMetricsRecorderTest.java @@ -0,0 +1,100 @@ +package com.clickhouse.jdbc; + +import com.clickhouse.client.api.observability.MetricAttribute; +import com.clickhouse.client.api.observability.MetricName; +import com.clickhouse.client.api.observability.micrometer.MicrometerMetricsRecorder; +import io.micrometer.core.instrument.Counter; +import io.micrometer.core.instrument.Metrics; +import io.micrometer.core.instrument.Timer; +import io.micrometer.core.instrument.simple.SimpleMeterRegistry; +import org.testng.Assert; +import org.testng.annotations.AfterMethod; +import org.testng.annotations.BeforeMethod; +import org.testng.annotations.Test; + +import java.sql.Connection; +import java.sql.ResultSet; +import java.sql.Statement; +import java.util.Properties; +import java.util.concurrent.TimeUnit; + +public class MicrometerMetricsRecorderTest extends JdbcIntegrationTest { + + private SimpleMeterRegistry registry; + + @BeforeMethod(groups = {"integration"}) + void setUp() { + // the global registry keeps the meters of every recorder that reported to it, and hands them to + // a registry added later, so each case starts from an empty one + Metrics.globalRegistry.clear(); + registry = new SimpleMeterRegistry(); + Metrics.addRegistry(registry); + } + + @AfterMethod(groups = {"integration"}) + void tearDown() { + Metrics.removeRegistry(registry); + Metrics.globalRegistry.clear(); + registry.close(); + } + + @Test(groups = {"integration"}) + public void testConnectionNamingTheRecorderReportsToTheGlobalRegistry() throws Exception { + Properties properties = new Properties(); + properties.setProperty(DriverProperties.METRICS_RECORDER.getKey(), + MicrometerMetricsRecorder.class.getName()); + + try (Connection connection = getJdbcConnection(properties); + Statement statement = connection.createStatement()) { + try (ResultSet rs = statement.executeQuery("SELECT 1")) { + Assert.assertTrue(rs.next()); + } + } + + Timer duration = registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.DB_OPERATION_NAME.getKey(), "query") + .timer(); + Assert.assertNotNull(duration, "Unexpected meters: " + registry.getMeters()); + Assert.assertTrue(duration.count() > 0); + Assert.assertTrue(duration.totalTime(TimeUnit.NANOSECONDS) > 0); + Assert.assertEquals(duration.getId().getTag(MetricAttribute.DB_SYSTEM_NAME.getKey()), "clickhouse"); + + Counter count = registry.find(MetricName.OPERATION_COUNT.getKey()).counter(); + Assert.assertNotNull(count); + Assert.assertTrue(count.count() > 0); + } + + @Test(groups = {"integration"}) + public void testConnectionsShareOneTimeSeries() throws Exception { + Properties properties = new Properties(); + properties.setProperty(DriverProperties.METRICS_RECORDER.getKey(), + MicrometerMetricsRecorder.class.getName()); + + for (int i = 0; i < 2; i++) { + try (Connection connection = getJdbcConnection(properties); + Statement statement = connection.createStatement()) { + try (ResultSet rs = statement.executeQuery("SELECT 1")) { + Assert.assertTrue(rs.next()); + } + } + } + + // each connection creates its own recorder, and all of them report to the global registry + Assert.assertEquals(registry.find(MetricName.OPERATION_DURATION.getKey()) + .tag(MetricAttribute.DB_OPERATION_NAME.getKey(), "query").timers().size(), 1, + "Unexpected meters: " + registry.getMeters()); + } + + @Test(groups = {"integration"}) + public void testConnectionWithoutThePropertyReportsNothing() throws Exception { + try (Connection connection = getJdbcConnection(); + Statement statement = connection.createStatement()) { + try (ResultSet rs = statement.executeQuery("SELECT 1")) { + Assert.assertTrue(rs.next()); + } + } + + Assert.assertNull(registry.find(MetricName.OPERATION_DURATION.getKey()).timer(), + "a connection that did not ask for metrics must not report any"); + } +} diff --git a/pom.xml b/pom.xml index 997034129..e0e625a2a 100644 --- a/pom.xml +++ b/pom.xml @@ -92,6 +92,7 @@ 8.5.12 2.10.1 4.0.1 + 1.14.3 0.31.1 1.51.0 3.23.4