[
https://issues.apache.org/jira/browse/HDDS-16741?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel
]
Andrey Yarovoy updated HDDS-16741:
----------------------------------
Description:
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.
was:
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.
> 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
> 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]
