dongjoon-hyun commented on code in PR #949:
URL:
https://github.com/apache/spark-kubernetes-operator/pull/949#discussion_r4437461938
##########
docs/migration_guide.md:
##########
@@ -125,9 +125,23 @@ affect building the project, CI, tests or examples.
`kubernetes_client_http_response_latency_seconds_sum`, is the sum of all
recorded values. 1.0
exported the mean of roughly the last 5 minutes multiplied by the count
instead, which can
decrease between scrapes, so `rate()` of it and the average derived from it
were wrong. Also, the
- `0.5` and `0.999` quantiles of the `operator_sdk_*` histograms are the
median and the 99.9th
+ `0.5` and `0.999` quantiles of the operator histograms and timers are the
median and the 99.9th
percentile instead of the mean and the 99th percentile. A histogram or timer
of a custom metrics
source has no `_sum` unless it is a `SummingHistogram` or a `SummingTimer`.
+- Since 1.1.0, the `operator.sdk` metrics source times the controller
executions, i.e. the
+ reconciliations and cleanups, with timers instead of histograms, so the
source has no histograms
+ anymore. The timers record nanoseconds. 1.0 recorded whole seconds, so an
execution under one
+ second, which most are, was recorded as `0`, and the quantiles and `_sum` of
these histograms
+ were mostly `0`. With the default text-based Prometheus format, the timers
are exported in
+ seconds with a `_duration_seconds` suffix regardless of
+ `spark.kubernetes.operator.metrics.sanitizePrometheusMetricsNameEnabled`,
e.g.
+
`operator_sdk_sparkapplication_sparkappreconciler_reconcile_both_duration_seconds`
instead of
+ `operator_sdk_sparkapplication_sparkappreconciler_reconcile_both`, plus
`_m1_rate`, `_m5_rate`
Review Comment:
`reconcile_both` seems to come from `successTypeName` of
`TestingExecutionBase` in the test. JOSDK names a successful reconciliation
`resource`, `status` or `both` depending on the returned `UpdateControl`, and
`SparkAppReconciler` and `SparkClusterReconciler` always return
`UpdateControl.noUpdate()`, also via `ReconcilerUtils.toUpdateControl`, which
is `resource`. So neither 1.0 nor 1.1 exports `..._reconcile_both`, and users
searching their dashboards for these names would find nothing and may conclude
that they are not affected. Could you use
`operator_sdk_sparkapplication_sparkappreconciler_reconcile_resource_duration_seconds`
and `operator_sdk_sparkapplication_sparkappreconciler_reconcile_resource`
instead? FYI, the other outcomes are `reconcile_failure`, `cleanup_delete`,
`cleanup_finalizernotremoved` and `cleanup_failure`.
##########
docs/migration_guide.md:
##########
@@ -125,9 +125,23 @@ affect building the project, CI, tests or examples.
`kubernetes_client_http_response_latency_seconds_sum`, is the sum of all
recorded values. 1.0
exported the mean of roughly the last 5 minutes multiplied by the count
instead, which can
decrease between scrapes, so `rate()` of it and the average derived from it
were wrong. Also, the
- `0.5` and `0.999` quantiles of the `operator_sdk_*` histograms are the
median and the 99.9th
+ `0.5` and `0.999` quantiles of the operator histograms and timers are the
median and the 99.9th
percentile instead of the mean and the 99th percentile. A histogram or timer
of a custom metrics
source has no `_sum` unless it is a `SummingHistogram` or a `SummingTimer`.
+- Since 1.1.0, the `operator.sdk` metrics source times the controller
executions, i.e. the
+ reconciliations and cleanups, with timers instead of histograms, so the
source has no histograms
+ anymore. The timers record nanoseconds. 1.0 recorded whole seconds, so an
execution under one
+ second, which most are, was recorded as `0`, and the quantiles and `_sum` of
these histograms
+ were mostly `0`. With the default text-based Prometheus format, the timers
are exported in
+ seconds with a `_duration_seconds` suffix regardless of
+ `spark.kubernetes.operator.metrics.sanitizePrometheusMetricsNameEnabled`,
e.g.
+
`operator_sdk_sparkapplication_sparkappreconciler_reconcile_both_duration_seconds`
instead of
+ `operator_sdk_sparkapplication_sparkappreconciler_reconcile_both`, plus
`_m1_rate`, `_m5_rate`
+ and `_m15_rate` gauges per timer. With
Review Comment:
`formatTimer` also exports `<name>_count` under `# TYPE <name> gauge`, which
keeps the name and the value of the `_count` of the 1.0 summary, e.g.
`operator_sdk_sparkapplication_sparkappreconciler_reconcile_resource_count`. So
only the 6 quantiles and `_sum` move to `_duration_seconds`, and the queries on
`_count`, e.g. `rate(..._count[5m])`, keep working. Could you mention it, so
that users don't rewrite them unnecessarily? It also means 4 extra series per
timer (8 -> 12), not 3.
##########
spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetrics.java:
##########
@@ -316,10 +341,6 @@ public void reconciliationSucceeded(HasMetadata resource,
Map<String, Object> me
.dec();
}
- private long toSeconds(long startTimeInMilliseconds) {
Review Comment:
Like `toSeconds`, `BaseOperatorSource.getHistogram` and its `histograms` map
lose their last callers with this PR, and the
`assertInstanceOf(SummingHistogram.class, ...)` removed from
`OperatorJosdkMetricsTest` was their only test. Shall we remove them as well?
Or, since `getHistogram` is a `protected` method of a public class, we may keep
it with a direct test instead, because nothing would catch a change that drops
its `SummingHistogram::new`, i.e. the `_sum` of custom sources.
##########
spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetrics.java:
##########
@@ -192,6 +191,32 @@ public <T> T
timeControllerExecution(ControllerExecution<T> execution) throws Ex
}
throw e;
}
+ final long durationNanos = clock.nanoTime() - startTime;
+ final String successType = execution.successTypeName(result);
+ if (resourceClass.isPresent()) {
+ String metricsPrefix = getMetricNamePrefix(resourceClass.get());
+ recordDuration(metricsPrefix, namespaceOptional, durationNanos, name,
execName, successType);
+ getCounter(metricsPrefix, name, execName, SUCCESS, successType).inc();
+ if (namespaceOptional.isPresent()) {
+ getCounter(metricsPrefix, namespaceOptional.get(), name, execName,
SUCCESS, successType)
+ .inc();
+ }
+ }
+ return result;
+ }
+
+ private void recordDuration(
+ String metricsPrefix,
+ Optional<String> namespaceOptional,
+ long durationNanos,
+ String name,
+ String execName,
+ String type) {
+ getTimer(metricsPrefix, name, execName, type).update(durationNanos,
TimeUnit.NANOSECONDS);
Review Comment:
Following up on 3 of my previous review, which is still open: the 4 extra
series per timer carry no new information. `<name>_count` equals
`<name>_duration_seconds_count`, and the `_m1_rate`, `_m5_rate` and `_m15_rate`
gauges can be derived with `rate(<name>_duration_seconds_count[...])`.
For scale, the number of timers is 2 kinds x (1 + watched namespaces) x 5
outcomes (`reconcile_resource`, `reconcile_failure`, `cleanup_delete`,
`cleanup_finalizernotremoved` and `cleanup_failure`). So an operator watching
100 namespaces has up to about 1,010 timers, i.e. about 4,040 more series per
scrape. With `prometheusTextBasedFormatEnabled=false`, it is 15 instead of 11
series per metric.
##########
spark-operator/src/test/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetricsTest.java:
##########
@@ -68,29 +76,57 @@ void testTimeControllerExecution() throws Exception {
operatorMetrics.timeControllerExecution(successExecution);
Map<String, Metric> metrics =
operatorMetrics.metricRegistry().getMetrics();
assertEquals(4, metrics.size());
- assertInstanceOf(
- SummingHistogram.class,
metrics.get("sparkapplication.test-controller.reconcile.both"));
-
assertTrue(metrics.containsKey("sparkapplication.testns.test-controller.reconcile.both"));
+ // The execution took 10 ms, which is recorded with sub-second precision
in nanoseconds.
+ long durationNanos = Duration.ofMillis(10).toNanos();
+ assertEquals(
+ durationNanos, recordedNanos(metrics,
"sparkapplication.test-controller.reconcile.both"));
+ assertEquals(
+ durationNanos,
+ recordedNanos(metrics,
"sparkapplication.testns.test-controller.reconcile.both"));
assertTrue(metrics.containsKey("sparkapplication.test-controller.reconcile.success.both"));
assertTrue(
metrics.containsKey("sparkapplication.testns.test-controller.reconcile.success.both"));
FooTestingExecutionBase<SparkApplication> failedExecution = new
FooTestingExecutionBase<>();
- try {
- operatorMetrics.timeControllerExecution(failedExecution);
- } catch (Exception e) {
- assertEquals("Foo exception", e.getMessage());
- assertEquals(8, metrics.size());
-
assertTrue(metrics.containsKey("sparkapplication.test-controller.reconcile.failure"));
- assertTrue(
- metrics.containsKey(
- "sparkapplication.test-controller.reconcile.failure.exception"
- + ".nosuchfieldexception"));
-
assertTrue(metrics.containsKey("sparkapplication.testns.test-controller.reconcile.failure"));
- assertTrue(
- metrics.containsKey(
- "sparkapplication.testns.test-controller.reconcile.failure."
- + "exception.nosuchfieldexception"));
+ Exception e =
+ assertThrows(
+ NoSuchFieldException.class,
+ () -> operatorMetrics.timeControllerExecution(failedExecution));
+ assertEquals("Foo exception", e.getMessage());
+ assertEquals(8, metrics.size());
+ long failureNanos = Duration.ofMillis(5).toNanos();
+ assertEquals(
+ failureNanos,
+ recordedNanos(metrics,
"sparkapplication.test-controller.reconcile.failure"));
+ assertTrue(
+ metrics.containsKey(
+ "sparkapplication.test-controller.reconcile.failure.exception"
+ + ".nosuchfieldexception"));
+ assertEquals(
+ failureNanos,
+ recordedNanos(metrics,
"sparkapplication.testns.test-controller.reconcile.failure"));
+ assertTrue(
+ metrics.containsKey(
+ "sparkapplication.testns.test-controller.reconcile.failure."
+ + "exception.nosuchfieldexception"));
+ }
+
+ @Test
+ void testTimeControllerExecutionIsExportedInSeconds() throws Exception {
+ operatorMetrics.timeControllerExecution(new TestingExecutionBase<>());
+ TestingPrometheusPullModelHandler handler =
+ new
TestingPrometheusPullModelHandler(operatorMetrics.metricRegistry());
Review Comment:
nit: This formats the source registry directly, so the names lack the
`operator_sdk_` prefix, and the test doesn't cover how
`MetricsSystem.registerSource` exposes these timers through the parent
registry. For example, if the registration exposed a wrapper or a copy instead
of the `SummingTimer` itself, `..._duration_seconds_sum` would silently
disappear in production while this test still passes. How about formatting a
parent registry instead, e.g. after
`parent.register(operatorMetrics.sourceName(),
operatorMetrics.metricRegistry())`, and asserting the documented
`operator_sdk_..._duration_seconds` names?
##########
spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetrics.java:
##########
@@ -192,6 +191,32 @@ public <T> T
timeControllerExecution(ControllerExecution<T> execution) throws Ex
}
throw e;
}
+ final long durationNanos = clock.nanoTime() - startTime;
+ final String successType = execution.successTypeName(result);
+ if (resourceClass.isPresent()) {
+ String metricsPrefix = getMetricNamePrefix(resourceClass.get());
+ recordDuration(metricsPrefix, namespaceOptional, durationNanos, name,
execName, successType);
+ getCounter(metricsPrefix, name, execName, SUCCESS, successType).inc();
+ if (namespaceOptional.isPresent()) {
+ getCounter(metricsPrefix, namespaceOptional.get(), name, execName,
SUCCESS, successType)
+ .inc();
+ }
+ }
+ return result;
+ }
+
+ private void recordDuration(
+ String metricsPrefix,
+ Optional<String> namespaceOptional,
+ long durationNanos,
+ String name,
+ String execName,
+ String type) {
+ getTimer(metricsPrefix, name, execName, type).update(durationNanos,
TimeUnit.NANOSECONDS);
+ if (namespaceOptional.isPresent()) {
+ getTimer(metricsPrefix, namespaceOptional.get(), name, execName, type)
+ .update(durationNanos, TimeUnit.NANOSECONDS);
Review Comment:
nit, outside this PR: `PrometheusPullModelHandler.formatTimer` calls
`timer.getSnapshot()` twice per timer on every scrape, once for the `null`
check and once for the values, and each call copies and sorts up to 1028
samples of the reservoir. Now that these reservoirs hold distinct nanosecond
values instead of mostly `0`, the discarded snapshot costs more to sort, on the
HTTP handler thread. Taking the snapshot once into a local variable would avoid
it. `formatHistogram` has the same pattern.
##########
spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetrics.java:
##########
@@ -134,7 +144,9 @@ public void eventReceived(Event event, Map<String, Object>
metadata) {
}
/**
- * Times the execution of a controller operation and records success or
failure metrics.
+ * Times the execution of a controller operation and records success or
failure metrics. The
+ * duration is measured with the monotonic clock in nanoseconds and recorded
in timers, which
+ * {@link org.apache.spark.k8s.operator.metrics.PrometheusPullModelHandler}
exports in seconds.
Review Comment:
Like the migration guide, this holds only with the default text-based
format. With
`spark.kubernetes.operator.metrics.prometheusTextBasedFormatEnabled=false`,
`handle()` falls back to Spark's `PrometheusServlet`, which exports these
timers in raw nanoseconds, e.g. `..._50thPercentile{type="timers"} 1.0E7` for
10 ms. How about adding "with the default text-based format"?
##########
docs/migration_guide.md:
##########
@@ -125,9 +125,23 @@ affect building the project, CI, tests or examples.
`kubernetes_client_http_response_latency_seconds_sum`, is the sum of all
recorded values. 1.0
exported the mean of roughly the last 5 minutes multiplied by the count
instead, which can
decrease between scrapes, so `rate()` of it and the average derived from it
were wrong. Also, the
- `0.5` and `0.999` quantiles of the `operator_sdk_*` histograms are the
median and the 99.9th
+ `0.5` and `0.999` quantiles of the operator histograms and timers are the
median and the 99.9th
percentile instead of the mean and the 99th percentile. A histogram or timer
of a custom metrics
source has no `_sum` unless it is a `SummingHistogram` or a `SummingTimer`.
+- Since 1.1.0, the `operator.sdk` metrics source times the controller
executions, i.e. the
+ reconciliations and cleanups, with timers instead of histograms, so the
source has no histograms
+ anymore. The timers record nanoseconds. 1.0 recorded whole seconds, so an
execution under one
+ second, which most are, was recorded as `0`, and the quantiles and `_sum` of
these histograms
+ were mostly `0`. With the default text-based Prometheus format, the timers
are exported in
+ seconds with a `_duration_seconds` suffix regardless of
+ `spark.kubernetes.operator.metrics.sanitizePrometheusMetricsNameEnabled`,
e.g.
+
`operator_sdk_sparkapplication_sparkappreconciler_reconcile_both_duration_seconds`
instead of
+ `operator_sdk_sparkapplication_sparkappreconciler_reconcile_both`, plus
`_m1_rate`, `_m5_rate`
+ and `_m15_rate` gauges per timer. With
+ `spark.kubernetes.operator.metrics.prometheusTextBasedFormatEnabled=false`,
Spark's
+ `PrometheusServlet` exports them as `{type="timers"}` in raw nanoseconds,
and other Spark sinks,
+ e.g. JMX, Console or CSV, apply their own duration unit. Update queries and
dashboards
Review Comment:
Thank you for adding this. Besides the unit, these sinks now see timers
instead of histograms. For example, since `JmxReporter` puts the metric type
into the `ObjectName`, `JmxSink` registers these MBeans as
`metrics:name=operator.sdk.<...>,type=timers` instead of `type=histograms`,
with a different set of attributes, so a `jmx_exporter` rule matching
`type=histograms` silently stops matching. Likewise, the Console and CSV sinks
report them as timers with different fields. Could you mention it as well?
##########
docs/migration_guide.md:
##########
@@ -125,9 +125,23 @@ affect building the project, CI, tests or examples.
`kubernetes_client_http_response_latency_seconds_sum`, is the sum of all
recorded values. 1.0
exported the mean of roughly the last 5 minutes multiplied by the count
instead, which can
decrease between scrapes, so `rate()` of it and the average derived from it
were wrong. Also, the
- `0.5` and `0.999` quantiles of the `operator_sdk_*` histograms are the
median and the 99.9th
+ `0.5` and `0.999` quantiles of the operator histograms and timers are the
median and the 99.9th
Review Comment:
Thank you for updating this. However, "the operator histograms and timers"
now also covers metrics whose quantiles did not change. In
[1.0.0](https://github.com/apache/spark-kubernetes-operator/blob/1.0.0/spark-operator/src/main/java/org/apache/spark/k8s/operator/metrics/PrometheusPullModelHandler.java#L245-L280),
`formatTimer` already exported the median and the 99.9th percentile, and so
did `formatHistogram` for a name containing `nanos`. Only the other histograms
used the mean and the 99th percentile.
After this PR, the only built-in histogram is
`kubernetes.client.http.response.latency.nanos`, and the `sparkapp.latency.*`
metrics were timers in 1.0 as well, so this sentence matches no built-in
metric. For example,
`kubernetes_client_http_response_latency_seconds{quantile="0.5"}` was the
median in 1.0 too. Shall we limit it to the histograms of custom metrics
sources whose names don't contain `nanos`?
##########
spark-operator/src/test/java/org/apache/spark/k8s/operator/metrics/source/OperatorJosdkMetricsTest.java:
##########
@@ -55,11 +61,13 @@ class OperatorJosdkMetricsTest {
"test-controller-name");
private static final String controllerName = "test-controller";
+ private ManualClock clock;
private OperatorJosdkMetrics operatorMetrics;
@BeforeEach
void setup() {
- operatorMetrics = new OperatorJosdkMetrics();
+ clock = new ManualClock();
Review Comment:
Since `new ManualClock()` starts at `0`, `startTime` is `0` in the first
execution of each test, so both tests still pass if the success path records
`clock.nanoTime()` instead of `clock.nanoTime() - startTime`. Only the failure
path, which starts at 10 ms, would catch such a regression, while in
production, `System.nanoTime()` has an arbitrary origin and every successful
execution would record a huge duration. How about starting at a non-zero time,
e.g. `new ManualClock(1000)`? The expected durations stay the same.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: [email protected]
For queries about this service, please contact Infrastructure at:
[email protected]
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
