Instrument proxy frontend latency metric (#320)

* Instrument proxy frontend latency metric

Backend latency only captures the time spent waiting for the GAE backend
to respond to a request, which is not representitive of what clients
experience. For instance it does not take into account the time the
proxy spends on processing the requests and the time it takes to send a
response to the client.

This PR adds a metric for frontend latency, which is the time spent on
answering a client request. This should serve as a better proxy for the
latency clients observe.

* Rename AbstractMetrics to BaseMetrics
This commit is contained in:
Lai Jiang 2019-10-29 16:02:47 -04:00 committed by GitHub
parent 7da94c90dc
commit 3106958f18
No known key found for this signature in database
GPG key ID: 4AEE18F83AFDEB23
12 changed files with 418 additions and 88 deletions

View file

@ -32,6 +32,7 @@ import google.registry.proxy.ProxyConfig.Environment;
import google.registry.proxy.WebWhoisProtocolsModule.HttpWhoisProtocol;
import google.registry.proxy.WhoisProtocolModule.WhoisProtocol;
import google.registry.proxy.handler.BackendMetricsHandler;
import google.registry.proxy.handler.FrontendMetricsHandler;
import google.registry.proxy.handler.ProxyProtocolHandler;
import google.registry.proxy.handler.QuotaHandler.EppQuotaHandler;
import google.registry.proxy.handler.QuotaHandler.WhoisQuotaHandler;
@ -74,7 +75,7 @@ import org.junit.Before;
*/
public abstract class ProtocolModuleTest {
protected static final ProxyConfig PROXY_CONFIG = getProxyConfig(LOCAL);
protected static final ProxyConfig PROXY_CONFIG = getProxyConfig(Environment.LOCAL);
protected TestComponent testComponent;
@ -106,6 +107,7 @@ public abstract class ProtocolModuleTest {
LoggingHandler.class,
// Metrics instrumentation is tested separately.
BackendMetricsHandler.class,
FrontendMetricsHandler.class,
// Quota management is tested separately.
WhoisQuotaHandler.class,
EppQuotaHandler.class,

View file

@ -133,7 +133,8 @@ public class BackendMetricsHandlerTest {
verify(metrics)
.requestSent(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, request.content().readableBytes());
verify(metrics).responseReceived(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, response, 1);
verify(metrics)
.responseReceived(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, response, Duration.millis(1));
verifyNoMoreInteractions(metrics);
}
@ -154,7 +155,8 @@ public class BackendMetricsHandlerTest {
verify(metrics)
.requestSent(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, request.content().readableBytes());
verify(metrics).responseReceived(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, response, 1);
verify(metrics)
.responseReceived(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, response, Duration.millis(1));
verifyNoMoreInteractions(metrics);
}
@ -178,46 +180,46 @@ public class BackendMetricsHandlerTest {
// First request, time = 0
assertThat(channel.writeOutbound(request1)).isTrue();
assertHttpRequestEquivalent(request1, channel.readOutbound());
DateTime sentTime1 = fakeClock.nowUtc();
DateTime requestTime1 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(5));
// Second request, time = 5
assertThat(channel.writeOutbound(request2)).isTrue();
assertHttpRequestEquivalent(request2, channel.readOutbound());
DateTime sentTime2 = fakeClock.nowUtc();
DateTime requestTime2 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(7));
// First response, time = 12, latency = 12 - 0 = 12
assertThat(channel.writeInbound(response1)).isTrue();
assertHttpResponseEquivalent(response1, channel.readInbound());
DateTime receivedTime1 = fakeClock.nowUtc();
DateTime responseTime1 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(11));
// Third request, time = 23
assertThat(channel.writeOutbound(request3)).isTrue();
assertHttpRequestEquivalent(request3, channel.readOutbound());
DateTime sentTime3 = fakeClock.nowUtc();
DateTime requestTime3 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(2));
// Second response, time = 25, latency = 25 - 5 = 20
assertThat(channel.writeInbound(response2)).isTrue();
assertHttpResponseEquivalent(response2, channel.readInbound());
DateTime receivedTime2 = fakeClock.nowUtc();
DateTime responseTime2 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(4));
// Third response, time = 29, latency = 29 - 23 = 6
assertThat(channel.writeInbound(response3)).isTrue();
assertHttpResponseEquivalent(response3, channel.readInbound());
DateTime receivedTime3 = fakeClock.nowUtc();
DateTime responseTime3 = fakeClock.nowUtc();
long latency1 = new Duration(sentTime1, receivedTime1).getMillis();
long latency2 = new Duration(sentTime2, receivedTime2).getMillis();
long latency3 = new Duration(sentTime3, receivedTime3).getMillis();
Duration latency1 = new Duration(requestTime1, responseTime1);
Duration latency2 = new Duration(requestTime2, responseTime2);
Duration latency3 = new Duration(requestTime3, responseTime3);
verify(metrics)
.requestSent(RELAYED_PROTOCOL_NAME, CLIENT_CERT_HASH, request1.content().readableBytes());

View file

@ -0,0 +1,169 @@
// Copyright 2017 The Nomulus Authors. All Rights Reserved.
//
// Licensed under the Apache License, Version 2.0 (the "License");
// you may not use this file except in compliance with the License.
// You may obtain a copy of the License at
//
// http://www.apache.org/licenses/LICENSE-2.0
//
// Unless required by applicable law or agreed to in writing, software
// distributed under the License is distributed on an "AS IS" BASIS,
// WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
// See the License for the specific language governing permissions and
// limitations under the License.
package google.registry.proxy.handler;
import static com.google.common.truth.Truth.assertThat;
import static google.registry.proxy.Protocol.PROTOCOL_KEY;
import static google.registry.proxy.handler.EppServiceHandler.CLIENT_CERTIFICATE_HASH_KEY;
import static google.registry.testing.JUnitBackports.assertThrows;
import static org.mockito.Mockito.mock;
import static org.mockito.Mockito.verify;
import static org.mockito.Mockito.verifyNoMoreInteractions;
import static org.mockito.Mockito.verifyZeroInteractions;
import com.google.common.collect.ImmutableList;
import google.registry.proxy.Protocol;
import google.registry.proxy.Protocol.FrontendProtocol;
import google.registry.proxy.metric.FrontendMetrics;
import google.registry.testing.FakeClock;
import io.netty.channel.ChannelInitializer;
import io.netty.channel.embedded.EmbeddedChannel;
import org.joda.time.DateTime;
import org.joda.time.Duration;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
import org.junit.runners.JUnit4;
/** Unit tests for {@link FrontendMetricsHandler}. */
@RunWith(JUnit4.class)
public class FrontendMetricsHandlerTest {
private static final String CLIENT_CERT_HASH = "blah12345";
private static final String PROTOCOL_NAME = "frontend protocol";
private final FakeClock fakeClock = new FakeClock();
private final FrontendMetrics metrics = mock(FrontendMetrics.class);
private final FrontendMetricsHandler handler = new FrontendMetricsHandler(fakeClock, metrics);
private final FrontendProtocol frontendProtocol =
Protocol.frontendBuilder()
.name(PROTOCOL_NAME)
.port(2)
.hasBackend(false)
.handlerProviders(ImmutableList.of())
.build();
private EmbeddedChannel channel;
@Before
public void setUp() {
channel =
new EmbeddedChannel(
new ChannelInitializer<EmbeddedChannel>() {
@Override
protected void initChannel(EmbeddedChannel ch) throws Exception {
ch.attr(PROTOCOL_KEY).set(frontendProtocol);
ch.attr(CLIENT_CERTIFICATE_HASH_KEY).set(CLIENT_CERT_HASH);
ch.pipeline().addLast(handler);
}
});
}
@Test
public void testSuccess_oneRequest() {
// Inbound message passed to the next handler.
Object request = new Object();
assertThat(channel.writeInbound(request)).isTrue();
assertThat((Object) channel.readInbound()).isEqualTo(request);
verifyZeroInteractions(metrics);
}
@Test
public void testSuccess_oneRequest_oneResponse() {
Object request = new Object();
Object response = new Object();
// Inbound message passed to the next handler.
assertThat(channel.writeInbound(request)).isTrue();
assertThat((Object) channel.readInbound()).isEqualTo(request);
fakeClock.advanceOneMilli();
// Outbound message passed to the next handler.
assertThat(channel.writeOutbound(response)).isTrue();
assertThat((Object) channel.readOutbound()).isEqualTo(response);
// Verify that latency is recorded.
verify(metrics).responseSent(PROTOCOL_NAME, CLIENT_CERT_HASH, Duration.millis(1));
verifyNoMoreInteractions(metrics);
}
@Test
public void testFailure_responseBeforeRequest() {
Object response = new Object();
IllegalStateException e =
assertThrows(IllegalStateException.class, () -> channel.writeOutbound(response));
assertThat(e).hasMessageThat().isEqualTo("Response sent before request is received.");
}
@Test
public void testSuccess_pipelinedResponses() {
Object request1 = new Object();
Object response1 = new Object();
Object request2 = new Object();
Object response2 = new Object();
Object request3 = new Object();
Object response3 = new Object();
// First request, time = 0
assertThat(channel.writeInbound(request1)).isTrue();
assertThat((Object) channel.readInbound()).isEqualTo(request1);
DateTime requestTime1 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(5));
// Second request, time = 5
assertThat(channel.writeInbound(request2)).isTrue();
assertThat((Object) channel.readInbound()).isEqualTo(request2);
DateTime requestTime2 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(7));
// First response, time = 12, latency = 12 - 0 = 12
assertThat(channel.writeOutbound(response1)).isTrue();
assertThat((Object) channel.readOutbound()).isEqualTo(response1);
DateTime responseTime1 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(11));
// Third request, time = 23
assertThat(channel.writeInbound(request3)).isTrue();
assertThat((Object) channel.readInbound()).isEqualTo(request3);
DateTime requestTime3 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(2));
// Second response, time = 25, latency = 25 - 5 = 20
assertThat(channel.writeOutbound(response2)).isTrue();
assertThat((Object) channel.readOutbound()).isEqualTo(response2);
DateTime responseTime2 = fakeClock.nowUtc();
fakeClock.advanceBy(Duration.millis(4));
// Third response, time = 29, latency = 29 - 23 = 6
assertThat(channel.writeOutbound(response3)).isTrue();
assertThat((Object) channel.readOutbound()).isEqualTo(response3);
DateTime responseTime3 = fakeClock.nowUtc();
Duration latency1 = new Duration(requestTime1, responseTime1);
Duration latency2 = new Duration(requestTime2, responseTime2);
Duration latency3 = new Duration(requestTime3, responseTime3);
verify(metrics)
.responseSent(PROTOCOL_NAME, CLIENT_CERT_HASH, latency1);
verify(metrics)
.responseSent(PROTOCOL_NAME, CLIENT_CERT_HASH, latency2);
verify(metrics)
.responseSent(PROTOCOL_NAME, CLIENT_CERT_HASH, latency3);
verifyNoMoreInteractions(metrics);
}
}

View file

@ -23,6 +23,7 @@ import com.google.common.collect.ImmutableSet;
import io.netty.handler.codec.http.FullHttpRequest;
import io.netty.handler.codec.http.FullHttpResponse;
import io.netty.handler.codec.http.HttpResponseStatus;
import org.joda.time.Duration;
import org.junit.Before;
import org.junit.Test;
import org.junit.runner.RunWith;
@ -40,7 +41,7 @@ public class BackendMetricsTest {
@Before
public void setUp() {
metrics.resetMetric();
metrics.resetMetrics();
}
@Test
@ -89,7 +90,7 @@ public class BackendMetricsTest {
public void testSuccess_oneResponse() {
String content = "some response";
FullHttpResponse response = makeHttpResponse(content, HttpResponseStatus.OK);
metrics.responseReceived(protocol, certHash, response, 5);
metrics.responseReceived(protocol, certHash, response, Duration.millis(5));
assertThat(BackendMetrics.requestsCounter).hasNoOtherValues();
assertThat(BackendMetrics.requestBytes).hasNoOtherValues();
@ -115,9 +116,9 @@ public class BackendMetricsTest {
FullHttpResponse response1 = makeHttpResponse(content1, HttpResponseStatus.OK);
FullHttpResponse response2 = makeHttpResponse(content2, HttpResponseStatus.OK);
FullHttpResponse response3 = makeHttpResponse(content3, HttpResponseStatus.BAD_REQUEST);
metrics.responseReceived(protocol, certHash, response1, 5);
metrics.responseReceived(protocol, certHash, response2, 8);
metrics.responseReceived(protocol, certHash, response3, 2);
metrics.responseReceived(protocol, certHash, response1, Duration.millis(5));
metrics.responseReceived(protocol, certHash, response2, Duration.millis(8));
metrics.responseReceived(protocol, certHash, response3, Duration.millis(2));
assertThat(BackendMetrics.requestsCounter).hasNoOtherValues();
assertThat(BackendMetrics.requestBytes).hasNoOtherValues();
@ -147,7 +148,7 @@ public class BackendMetricsTest {
FullHttpRequest request = makeHttpPostRequest(requestContent, host, "/");
FullHttpResponse response = makeHttpResponse(responseContent, HttpResponseStatus.OK);
metrics.requestSent(protocol, certHash, request.content().readableBytes());
metrics.responseReceived(protocol, certHash, response, 10);
metrics.responseReceived(protocol, certHash, response, Duration.millis(10));
assertThat(BackendMetrics.requestsCounter)
.hasValueForLabels(1, protocol, certHash)