[
https://issues.apache.org/jira/browse/HDDS-16741?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy reassigned HDDS-16741:
-------------------------------------
Assignee: Andrey Yarovoy
> GrpcMetrics queue and processing times are recorded from timestamps shared
> across concurrent calls
> --------------------------------------------------------------------------------------------------
>
> Key: HDDS-16741
> URL: https://issues.apache.org/jira/browse/HDDS-16741
> Project: Apache Ozone
> Issue Type: Bug
> Components: OM
> Reporter: Andrey Yarovoy
> Assignee: Andrey Yarovoy
> Priority: Major
>
> The `GrpcQueueTime*` and `GrpcProcessingTime*` metrics published by
> `GrpcMetrics` do not report the
> latency of any individual gRPC call. Three independent causes, all in
> `GrpcMetricsServerRequestInterceptor`:
> *1. The timestamps are server-wide, not per-call.*
> `receivedTime`, `startTime` and `endTime` are plain instance fields on the
> interceptor:
> {code:java}
> public class GrpcMetricsServerRequestInterceptor implements ServerInterceptor
> {
> private final GrpcMetrics grpcMetrics;
> private long receivedTime;
> private long startTime;
> private long endTime;
> {code}
> `GrpcOzoneManagerServer` constructs exactly one instance and hands it to
> `ServerInterceptors.intercept(...)`, so that one object serves every call on
> the server. `interceptCall`
> writes `receivedTime`, the returned listener's `onMessage` writes
> `startTime`, and `onComplete` writes
> `endTime`. With concurrent calls these writes interleave, so the deltas
> {code:java}
> int queueTime = (int) (startTime - receivedTime);
> int processingTime = (int) (endTime - startTime);
> {code}
> routinely subtract timestamps taken from *different* calls. The results are
> not noisy versions of the
> real latency, they are arbitrary — including negative, when the later call's
> timestamp lands first.
> The timestamps belong in per-call scope: `receivedTime` as a local in
> `interceptCall`, captured by the
> listener, and `startTime` as a field on the listener instance, which gRPC
> creates per call and whose
> callbacks it invokes serially.
> *2. A nanosecond delta is truncated to `int`.*
> Both timestamps come from `System.nanoTime()`, and the delta is cast to `int`
> before being passed to
> `addGrpcQueueTime(int)` / `addGrpcProcessingTime(int)`. An `int` of
> nanoseconds overflows at ~2.147 s,
> so even a correctly-paired measurement wraps to a negative or small value for
> any call slower than
> that — precisely the calls the metric exists to show. The accessors should
> take `long`.
> *3. Nanoseconds are published under a millisecond label.*
> No conversion happens anywhere between `System.nanoTime()` and the metric,
> yet the quantiles are
> created as
> {code:java}
> registry.newQuantiles("grpcQueueTime" + interval + "s", "grpc queue time in
> millisecond", ...)
> {code}
> and held in fields named `grpcQueueTimeMillisQuantiles` /
> `grpcProcessingTimeMillisQuantiles`. So the
> emitted values are nanoseconds described as milliseconds — a factor of
> 1,000,000. This also makes the
> gRPC numbers incomparable with the IPC ones, where `RpcMetrics.TIMEUNIT` is
> `TimeUnit.MILLISECONDS` and `Server` passes milliseconds.
> Fixing any one of the three in isolation still leaves the metric wrong, so
> they belong together.
> Note on compatibility: this changes the *values* of
> `GrpcQueueTime\{NumOps,AvgTime}`,
> `GrpcProcessingTime\{NumOps,AvgTime}` and the two quantile families —
> necessarily, since the current
> values are wrong. Metric names stay unchanged. If the millisecond conversion
> is considered a visible
> change rather than a correction, the alternative is to keep nanoseconds and
> fix the descriptions and
> field names instead; worth deciding on the Jira.
> *Testing*
> Unit test on the interceptor alone, following the mock-based idiom in
> `hadoop-ozone/common/src/test/java/org/apache/hadoop/ozone/om/protocolPB/grpc/TestClientAddressServerInterceptor.java`
> (mock `ServerCall` / `ServerCallHandler`, drive `interceptCall` then the
> returned listener): interleave
> two calls' `onMessage` / `onComplete` callbacks and assert both recorded
> durations are non-negative and
> attributable to their own call, which fails on the current code. Plus a case
> asserting a duration above
> 2.147 s is not truncated.
--
This message was sent by Atlassian Jira
(v8.20.10#820010)
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
