Andrey Yarovoy created HDDS-16741:
-------------------------------------
Summary: 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
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}
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}
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}
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]
