diff --git a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java index d21ee86a3fa..75e193a1723 100644 --- a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java +++ b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/ConfigurableDatetimeAccessItem.java @@ -58,7 +58,7 @@ public ConfigurableDatetimeAccessItem() { * @param config the format of configuration is "PATTERN|TIMEZONE|LOCALE" or "PATTERN". It depends on whether the config contains the separator "|" */ public ConfigurableDatetimeAccessItem(String config) { - String[] configArr = null; + String[] configArr; if (config.contains("|")) { configArr = splitConfig(config); } else { @@ -91,10 +91,9 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin @Override public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) { - long milliDuration = (finishEvent.getInvocation().getInvocationStageTrace().getStartSend() - - finishEvent.getInvocation().getInvocationStageTrace().getStart()) / 1000_000; + long milliDuration = finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000; doAppendFormattedItem( - finishEvent.getInvocation().getInvocationStageTrace().getStartTimeMillis() + milliDuration, builder); + finishEvent.getInvocation().getInvocationStageTrace().getStartInMillis() + milliDuration, builder); } private void doAppendFormattedItem(long milliStartTime, StringBuilder builder) { diff --git a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java index e0bde4ad306..49ecda73d94 100644 --- a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java +++ b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondAccessItem.java @@ -31,7 +31,6 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin @Override public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) { - builder.append((finishEvent.getInvocation().getInvocationStageTrace().getFinish() - - finishEvent.getInvocation().getInvocationStageTrace().getStartSend()) / 1000_000); + builder.append(finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000); } } diff --git a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java index 2da34026d5e..68d2ba0d411 100644 --- a/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java +++ b/common/common-access-log/src/main/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondAccessItem.java @@ -33,7 +33,6 @@ public void appendServerFormattedItem(ServerAccessLogEvent accessLogEvent, Strin @Override public void appendClientFormattedItem(InvocationFinishEvent finishEvent, StringBuilder builder) { - builder.append((finishEvent.getInvocation().getInvocationStageTrace().getFinish() - - finishEvent.getInvocation().getInvocationStageTrace().getStartSend()) / 1000_000_000); + builder.append(finishEvent.getInvocation().getInvocationStageTrace().calcTotal() / 1000_000_000); } } diff --git a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java index ee26be04cee..e8c7cf38500 100644 --- a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java +++ b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/AccessLogGeneratorTest.java @@ -81,10 +81,8 @@ public void testClientLog() { InvocationStageTrace stageTrace = Mockito.mock(InvocationStageTrace.class); OperationMeta operationMeta = Mockito.mock(OperationMeta.class); long startMillisecond = 1416863450581L; - when(stageTrace.getStartSend()).thenReturn(0L); - when(stageTrace.getStart()).thenReturn(0L); - when(stageTrace.getFinish()).thenReturn(0L); - when(stageTrace.getStartTimeMillis()).thenReturn(startMillisecond); + when(stageTrace.getStartInMillis()).thenReturn(startMillisecond); + when(stageTrace.calcTotal()).thenReturn(0L); when(invocation.getOperationMeta()).thenReturn(operationMeta); when(invocation.getInvocationStageTrace()).thenReturn(stageTrace); diff --git a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java index 750ebde7e39..8f55eb0006c 100644 --- a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java +++ b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DatetimeConfigurableItemTest.java @@ -30,10 +30,6 @@ import org.junit.jupiter.api.Assertions; import org.junit.jupiter.api.BeforeEach; import org.junit.jupiter.api.Test; -import org.junit.jupiter.api.condition.EnabledOnJre; -import org.junit.jupiter.api.condition.EnabledOnOs; -import org.junit.jupiter.api.condition.JRE; -import org.junit.jupiter.api.condition.OS; import org.mockito.Mockito; public class DatetimeConfigurableItemTest { @@ -58,61 +54,19 @@ public void initStrBuilder() { when(finishEvent.getInvocation()).thenReturn(invocation); when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace); - when(invocationStageTrace.getStartSend()).thenReturn(0L); - when(invocationStageTrace.getStart()).thenReturn(0L); - when(invocationStageTrace.getStartTimeMillis()).thenReturn(START_MILLISECOND); + when(invocationStageTrace.getStartInMillis()).thenReturn(START_MILLISECOND); + when(invocationStageTrace.calcTotal()).thenReturn(0L); accessLogEvent = new ServerAccessLogEvent(); accessLogEvent.setMilliStartTime(START_MILLISECOND); strBuilder = new StringBuilder(); } - @Test - @EnabledOnOs({OS.LINUX, OS.WINDOWS}) - @EnabledOnJre(JRE.JAVA_8) - public void serverFormattedElement() { - ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "EEE, yyyy MMM dd HH:mm:ss zzz|GMT-08|zh-CN"); - element.appendServerFormattedItem(accessLogEvent, strBuilder); - Assertions.assertEquals("星期一, 2014 十一月 24 13:10:50 GMT-08:00", strBuilder.toString()); - } - - @Test - @EnabledOnOs({OS.LINUX, OS.WINDOWS}) - @EnabledOnJre(JRE.JAVA_8) - public void clientFormattedElement() { - ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "EEE, yyyy MMM dd HH:mm:ss zzz|GMT-08|zh-CN"); - element.appendClientFormattedItem(finishEvent, strBuilder); - Assertions.assertEquals("星期一, 2014 十一月 24 13:10:50 GMT-08:00", strBuilder.toString()); - } - - @Test - @EnabledOnOs({OS.LINUX, OS.WINDOWS}) - @EnabledOnJre(JRE.JAVA_8) - public void serverFormattedElementOnNoPattern() { - ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "|GMT+08|zh-CN"); - - element.appendServerFormattedItem(accessLogEvent, strBuilder); - Assertions.assertEquals("星期二, 25 十一月 2014 05:10:50 GMT+08:00", strBuilder.toString()); - } - - @Test - @EnabledOnOs({OS.LINUX, OS.WINDOWS}) - @EnabledOnJre(JRE.JAVA_8) - public void clientFormattedElementOnNoPattern() { - ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "|GMT+08|zh-CN"); - - element.appendClientFormattedItem(finishEvent, strBuilder); - Assertions.assertEquals("星期二, 25 十一月 2014 05:10:50 GMT+08:00", strBuilder.toString()); - } @Test public void getFormattedElementOnNoTimezone() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "yyyy/MM/dd zzz||zh-CN"); + "yyyy/MM/dd zzz||zh-CN"); SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy/MM/dd zzz", Locale.forLanguageTag("zh-CN")); simpleDateFormat.setTimeZone(TimeZone.getDefault()); @@ -123,7 +77,7 @@ public void getFormattedElementOnNoTimezone() { @Test public void clientFormattedElementOnNoTimezone() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "yyyy/MM/dd zzz||zh-CN"); + "yyyy/MM/dd zzz||zh-CN"); SimpleDateFormat simpleDateFormat = new SimpleDateFormat("yyyy/MM/dd zzz", Locale.forLanguageTag("zh-CN")); simpleDateFormat.setTimeZone(TimeZone.getDefault()); @@ -134,7 +88,7 @@ public void clientFormattedElementOnNoTimezone() { @Test public void serverFormattedElementOnNoLocale() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|"); + "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|"); element.appendServerFormattedItem(accessLogEvent, strBuilder); Assertions.assertEquals("Tue, 25 Nov 2014 05:10:50 GMT+08:00", strBuilder.toString()); @@ -143,7 +97,7 @@ public void serverFormattedElementOnNoLocale() { @Test public void clientFormattedElementOnNoLocale() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|"); + "EEE, dd MMM yyyy HH:mm:ss zzz|GMT+08|"); element.appendClientFormattedItem(finishEvent, strBuilder); Assertions.assertEquals("Tue, 25 Nov 2014 05:10:50 GMT+08:00", strBuilder.toString()); @@ -152,9 +106,9 @@ public void clientFormattedElementOnNoLocale() { @Test public void serverFormattedElementOnNoConfig() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "||"); + "||"); SimpleDateFormat simpleDateFormat = new SimpleDateFormat(ConfigurableDatetimeAccessItem.DEFAULT_DATETIME_PATTERN, - Locale.US); + Locale.US); simpleDateFormat.setTimeZone(TimeZone.getDefault()); element.appendServerFormattedItem(accessLogEvent, strBuilder); @@ -164,9 +118,9 @@ public void serverFormattedElementOnNoConfig() { @Test public void clientFormattedElementOnNoConfig() { ConfigurableDatetimeAccessItem element = new ConfigurableDatetimeAccessItem( - "||"); + "||"); SimpleDateFormat simpleDateFormat = new SimpleDateFormat(ConfigurableDatetimeAccessItem.DEFAULT_DATETIME_PATTERN, - Locale.US); + Locale.US); simpleDateFormat.setTimeZone(TimeZone.getDefault()); element.appendClientFormattedItem(finishEvent, strBuilder); diff --git a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java index 7ad32b23f87..1fdd3b4e0d0 100644 --- a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java +++ b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationMillisecondItemTest.java @@ -50,8 +50,7 @@ public void initStrBuilder() { when(finishEvent.getInvocation()).thenReturn(invocation); when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace); - when(invocationStageTrace.getStartSend()).thenReturn(0L); - when(invocationStageTrace.getFinish()).thenReturn(1000_000L); + when(invocationStageTrace.calcTotal()).thenReturn(1000_000L); accessLogEvent = new ServerAccessLogEvent(); accessLogEvent.setMilliStartTime(1L); diff --git a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java index 3081ce51368..9cbe7f28da5 100644 --- a/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java +++ b/common/common-access-log/src/test/java/org/apache/servicecomb/common/accessLog/core/element/impl/DurationSecondItemTest.java @@ -50,7 +50,7 @@ public void initStrBuilder() { when(finishEvent.getInvocation()).thenReturn(invocation); when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace); - when(invocationStageTrace.getStartSend()).thenReturn(1000_000L); + when(invocationStageTrace.calcTotal()).thenReturn(1L); accessLogEvent = new ServerAccessLogEvent(); accessLogEvent.setMilliStartTime(1L); @@ -66,7 +66,7 @@ public void serverFormattedElementOn999ms() { @Test public void clientFormattedElementOn999ms() { - when(invocationStageTrace.getFinish()).thenReturn(1000_000_000L); + when(invocationStageTrace.calcTotal()).thenReturn(0L); ELEMENT.appendClientFormattedItem(finishEvent, strBuilder); Assertions.assertEquals("0", strBuilder.toString()); } @@ -80,7 +80,7 @@ public void serverFormattedElementOn1000ms() { @Test public void clientFormattedElementOn1000ms() { - when(invocationStageTrace.getFinish()).thenReturn(1001_000_000L); + when(invocationStageTrace.calcTotal()).thenReturn(1000_000_000L); ELEMENT.appendClientFormattedItem(finishEvent, strBuilder); Assertions.assertEquals("1", strBuilder.toString()); } @@ -94,7 +94,7 @@ public void serverFormattedElementOn1001ms() { @Test public void clientFormattedElementOn1001ms() { - when(invocationStageTrace.getFinish()).thenReturn(1002_000_000L); + when(invocationStageTrace.calcTotal()).thenReturn(1000_000_000L); ELEMENT.appendClientFormattedItem(finishEvent, strBuilder); Assertions.assertEquals("1", strBuilder.toString()); } diff --git a/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java b/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java index 70c3a5a3a01..c8e32471fad 100644 --- a/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java +++ b/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/RestProducerInvocationFlow.java @@ -53,34 +53,41 @@ protected Invocation sendCreateInvocationException(Throwable throwable) { requestEx.getRequestURI(), e); } - flushResponse("UNKNOWN_OPERATION"); + flushResponse(null); return null; } @Override protected void sendResponse(Invocation invocation, Response response) { + invocation.getInvocationStageTrace().startProviderSendResponse(); if (isDownloadFileResponseType(invocation, response)) { responseEx.sendPart(PartUtils.getSinglePart(null, response.getResult())) - .whenComplete((r, e) -> flushResponse(invocation.getMicroserviceQualifiedName())); + .whenComplete((r, e) -> flushResponse(invocation)); return; } - flushResponse(invocation.getMicroserviceQualifiedName()); + flushResponse(invocation); } - private void flushResponse(String operationName) { + private void flushResponse(Invocation invocation) { try { responseEx.flushBuffer(); } catch (Throwable flushException) { LOGGER.error("Failed to flush rest response, operation:{}, request uri:{}", - operationName, requestEx.getRequestURI(), flushException); + invocation == null ? "NA" : + invocation.getMicroserviceQualifiedName(), requestEx.getRequestURI(), flushException); } try { requestEx.getAsyncContext().complete(); } catch (Throwable completeException) { LOGGER.error("Failed to complete async rest response, operation:{}, request uri:{}", - operationName, requestEx.getRequestURI(), completeException); + invocation == null ? "NA" : + invocation.getMicroserviceQualifiedName(), requestEx.getRequestURI(), completeException); + } + + if (invocation != null) { + invocation.getInvocationStageTrace().finishProviderSendResponse(); } } } diff --git a/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java b/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java index c59815a94b9..f33e0badeba 100644 --- a/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java +++ b/common/common-rest/src/main/java/org/apache/servicecomb/common/rest/codec/param/BodyProcessorCreator.java @@ -62,8 +62,8 @@ import jakarta.ws.rs.core.MediaType; import jakarta.ws.rs.core.Response.Status; -@SuppressWarnings("rawtypes") public class BodyProcessorCreator implements ParamValueProcessorCreator { + private static final Logger LOGGER = LoggerFactory.getLogger(BodyProcessorCreator.class); public static final String REQUEST_BODY_NAME = "X_REQUEST"; @@ -74,12 +74,12 @@ public class BodyProcessorCreator implements ParamValueProcessorCreator invokeNext(Invocation invocation, FilterNo } protected void decodeRequest(Invocation invocation) { + invocation.getInvocationStageTrace().startProviderDecodeRequest(); HttpServletRequestEx requestEx = invocation.getRequestEx(); OperationMeta operationMeta = invocation.getOperationMeta(); RestOperationMeta restOperationMeta = operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION); Map swaggerArguments = RestCodec.restToArgs(requestEx, restOperationMeta); invocation.setSwaggerArguments(swaggerArguments); + invocation.getInvocationStageTrace().finishProviderDecodeRequest(); } protected CompletableFuture encodeResponse(Invocation invocation, Response response) { @@ -113,7 +115,8 @@ protected CompletableFuture encodeResponse(Invocation invocation, Resp HttpServletResponseEx responseEx = transportContext.getResponseEx(); boolean download = isDownloadFileResponseType(invocation, response); - return encodeResponse(response, download, produceProcessor, responseEx); + return encodeResponse(response, download, produceProcessor, responseEx) + .whenComplete((r, e) -> invocation.onEncodeResponseFinish()); } public static CompletableFuture encodeResponse(Response response, boolean download, diff --git a/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java b/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java index 7cae38cd00a..d3769dcb2c5 100644 --- a/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java +++ b/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/codec/param/TestCookieProcessorCreator.java @@ -18,13 +18,24 @@ package org.apache.servicecomb.common.rest.codec.param; import org.apache.servicecomb.common.rest.codec.param.CookieProcessorCreator.CookieProcessor; +import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.BeforeAll; import org.junit.jupiter.api.Test; +import org.mockito.Mockito; +import org.springframework.core.env.Environment; import io.swagger.v3.oas.models.media.Schema; import io.swagger.v3.oas.models.parameters.CookieParameter; public class TestCookieProcessorCreator { + static Environment environment = Mockito.mock(Environment.class); + + @BeforeAll + public static void beforeClass() { + LegacyPropertyFactory.setEnvironment(environment); + } + @Test public void testCreate() { ParamValueProcessorCreator creator = diff --git a/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilterTest.java b/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilterTest.java index 41f4826fca0..559a6af1044 100644 --- a/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilterTest.java +++ b/common/common-rest/src/test/java/org/apache/servicecomb/common/rest/filter/inner/RestServerCodecFilterTest.java @@ -38,6 +38,7 @@ import org.apache.servicecomb.core.definition.MicroserviceMeta; import org.apache.servicecomb.core.definition.OperationMeta; import org.apache.servicecomb.core.definition.SchemaMeta; +import org.apache.servicecomb.core.filter.AbstractFilter; import org.apache.servicecomb.core.filter.FilterNode; import org.apache.servicecomb.core.invocation.InvocationFactory; import org.apache.servicecomb.foundation.test.scaffolding.exception.RuntimeExceptionWithoutStackTrace; @@ -87,10 +88,18 @@ public class RestServerCodecFilterTest { final MultiMap headers = MultiMap.caseInsensitiveMultiMap(); - final FilterNode nextNode = new FilterNode((invocation, next) -> { - Response response = Response.ok("ok"); - response.setHeaders(headers); - return CompletableFuture.completedFuture(response); + final FilterNode nextNode = new FilterNode(new AbstractFilter() { + @Override + public String getName() { + return "f2"; + } + + @Override + public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { + Response response = Response.ok("ok"); + response.setHeaders(headers); + return CompletableFuture.completedFuture(response); + } }); static SCBEngine engine; diff --git a/core/src/main/java/org/apache/servicecomb/core/Invocation.java b/core/src/main/java/org/apache/servicecomb/core/Invocation.java index 6cddd9c934a..fe2f5d6a4fe 100644 --- a/core/src/main/java/org/apache/servicecomb/core/Invocation.java +++ b/core/src/main/java/org/apache/servicecomb/core/Invocation.java @@ -32,13 +32,10 @@ import org.apache.servicecomb.core.definition.OperationMeta; import org.apache.servicecomb.core.definition.SchemaMeta; import org.apache.servicecomb.core.event.InvocationBusinessFinishEvent; -import org.apache.servicecomb.core.event.InvocationBusinessMethodFinishEvent; import org.apache.servicecomb.core.event.InvocationBusinessMethodStartEvent; import org.apache.servicecomb.core.event.InvocationEncodeResponseStartEvent; import org.apache.servicecomb.core.event.InvocationFinishEvent; -import org.apache.servicecomb.core.event.InvocationHandlersStartEvent; import org.apache.servicecomb.core.event.InvocationRunInExecutorFinishEvent; -import org.apache.servicecomb.core.event.InvocationRunInExecutorStartEvent; import org.apache.servicecomb.core.event.InvocationStartEvent; import org.apache.servicecomb.core.event.InvocationStartSendRequestEvent; import org.apache.servicecomb.core.event.InvocationTimeoutCheckEvent; @@ -332,55 +329,41 @@ protected void initTraceId(TraceIdGenerator traceIdGenerator) { addContext(traceIdGenerator.getTraceIdKeyName(), traceIdGenerator.generate()); } - public void onStart(long start) { - invocationStageTrace.start(start); + public void onStart() { initTraceId(); EventManager.post(new InvocationStartEvent(this)); } - public void onStart(HttpServletRequestEx requestEx, long start) { + public void onStart(HttpServletRequestEx requestEx) { this.requestEx = requestEx; - onStart(start); - } - - public void onExecuteStart() { - invocationStageTrace.startExecution(); - EventManager.post(new InvocationRunInExecutorStartEvent(this)); + onStart(); } public void onExecuteFinish() { EventManager.post(new InvocationRunInExecutorFinishEvent(this)); } - public void onStartHandlersRequest() { - invocationStageTrace.startHandlersRequest(); - EventManager.post(new InvocationHandlersStartEvent(this)); - } - public void onStartSendRequest() { - invocationStageTrace.startSend(); EventManager.post(new InvocationStartSendRequestEvent(this)); } - @Override public void onBusinessMethodStart() { - invocationStageTrace.startBusinessMethod(); + invocationStageTrace.startBusinessExecute(); EventManager.post(new InvocationBusinessMethodStartEvent(this)); } - @Override - public void onBusinessMethodFinish() { - EventManager.post(new InvocationBusinessMethodFinishEvent(this)); - } - public void onEncodeResponseStart(Response response) { + invocationStageTrace.startProviderEncodeResponse(); EventManager.post(new InvocationEncodeResponseStartEvent(this, response)); } - @Override + public void onEncodeResponseFinish() { + invocationStageTrace.finishProviderEncodeResponse(); + } + public void onBusinessFinish() { - invocationStageTrace.finishBusiness(); + invocationStageTrace.finishBusinessExecute(); EventManager.post(new InvocationBusinessFinishEvent(this)); } @@ -390,9 +373,9 @@ public void onFinish(Response response) { return; } + finished = true; invocationStageTrace.finish(); EventManager.post(new InvocationFinishEvent(this, response)); - finished = true; } // for retry, reset invocation and try it again diff --git a/core/src/main/java/org/apache/servicecomb/core/event/InvocationFinishEvent.java b/core/src/main/java/org/apache/servicecomb/core/event/InvocationFinishEvent.java index d1d96b4d1b5..21a20226d01 100644 --- a/core/src/main/java/org/apache/servicecomb/core/event/InvocationFinishEvent.java +++ b/core/src/main/java/org/apache/servicecomb/core/event/InvocationFinishEvent.java @@ -20,14 +20,7 @@ import org.apache.servicecomb.swagger.invocation.Response; public class InvocationFinishEvent extends InvocationWithResponseEvent { - private final long nanoCurrent; - public InvocationFinishEvent(Invocation invocation, Response response) { super(invocation, response); - this.nanoCurrent = invocation.getInvocationStageTrace().getFinish(); - } - - public long getNanoCurrent() { - return nanoCurrent; } } diff --git a/core/src/main/java/org/apache/servicecomb/core/event/InvocationHandlersStartEvent.java b/core/src/main/java/org/apache/servicecomb/core/event/InvocationHandlersStartEvent.java deleted file mode 100644 index 55d57001b89..00000000000 --- a/core/src/main/java/org/apache/servicecomb/core/event/InvocationHandlersStartEvent.java +++ /dev/null @@ -1,26 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to You 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 org.apache.servicecomb.core.event; - -import org.apache.servicecomb.core.Invocation; - -public class InvocationHandlersStartEvent extends InvocationBaseEvent { - public InvocationHandlersStartEvent(Invocation invocation) { - super(invocation); - } -} diff --git a/core/src/main/java/org/apache/servicecomb/core/filter/AbstractFilter.java b/core/src/main/java/org/apache/servicecomb/core/filter/AbstractFilter.java index 6f68024f22e..35a01c251be 100644 --- a/core/src/main/java/org/apache/servicecomb/core/filter/AbstractFilter.java +++ b/core/src/main/java/org/apache/servicecomb/core/filter/AbstractFilter.java @@ -26,6 +26,8 @@ public abstract class AbstractFilter implements Filter, EnvironmentAware { protected Environment environment; + private String nameWithOrder; + @Override public void setEnvironment(Environment environment) { this.environment = environment; @@ -50,4 +52,12 @@ public boolean enabledForMicroservice(String application, String serviceName) { } return true; } + + @Override + public String getNameWithOrder() { + if (nameWithOrder == null) { + nameWithOrder = getName() + "(" + getOrder() + ")"; + } + return nameWithOrder; + } } diff --git a/core/src/main/java/org/apache/servicecomb/core/filter/Filter.java b/core/src/main/java/org/apache/servicecomb/core/filter/Filter.java index 38213b12f84..99ed798e686 100644 --- a/core/src/main/java/org/apache/servicecomb/core/filter/Filter.java +++ b/core/src/main/java/org/apache/servicecomb/core/filter/Filter.java @@ -72,6 +72,8 @@ default String getName() { throw new IllegalStateException("must provide unique filter name."); } + String getNameWithOrder(); + /** * * @param invocation invocation diff --git a/core/src/main/java/org/apache/servicecomb/core/filter/FilterNode.java b/core/src/main/java/org/apache/servicecomb/core/filter/FilterNode.java index acfdbb3151d..907ffe82d3a 100644 --- a/core/src/main/java/org/apache/servicecomb/core/filter/FilterNode.java +++ b/core/src/main/java/org/apache/servicecomb/core/filter/FilterNode.java @@ -62,13 +62,15 @@ private void setNextNode(FilterNode nextNode) { } public CompletableFuture onFilter(Invocation invocation) { + invocation.getInvocationStageTrace().recordStageBegin(this.filter.getNameWithOrder()); // When transport name is empty, maybe edge and transport filters need to be executed. // And we can't set Endpoint before load balance in edge. if (invocation.getTransportName() != null && !filter.enabledForTransport(invocation.getTransportName())) { return nextNode.onFilter(invocation); } - return AsyncUtils.tryCatchSupplierFuture(() -> filter.onFilter(invocation, nextNode)) + return AsyncUtils.tryCatchSupplierFuture(() -> filter.onFilter(invocation, nextNode) + .whenComplete((r, e) -> invocation.getInvocationStageTrace().recordStageEnd(this.filter.getNameWithOrder()))) .thenApply(this::rethrowExceptionInResponse); } diff --git a/core/src/main/java/org/apache/servicecomb/core/filter/impl/ProviderOperationFilter.java b/core/src/main/java/org/apache/servicecomb/core/filter/impl/ProviderOperationFilter.java index a45e3d40204..66f95ff76b2 100644 --- a/core/src/main/java/org/apache/servicecomb/core/filter/impl/ProviderOperationFilter.java +++ b/core/src/main/java/org/apache/servicecomb/core/filter/impl/ProviderOperationFilter.java @@ -81,7 +81,6 @@ protected Response convertResultToResponse(Invocation invocation, SwaggerProduce } protected void processMetrics(Invocation invocation) { - invocation.onBusinessMethodFinish(); invocation.onBusinessFinish(); } } diff --git a/core/src/main/java/org/apache/servicecomb/core/filter/impl/ScheduleFilter.java b/core/src/main/java/org/apache/servicecomb/core/filter/impl/ScheduleFilter.java index d8069fe0ace..058ce36007d 100644 --- a/core/src/main/java/org/apache/servicecomb/core/filter/impl/ScheduleFilter.java +++ b/core/src/main/java/org/apache/servicecomb/core/filter/impl/ScheduleFilter.java @@ -20,13 +20,14 @@ import java.util.concurrent.Executor; import org.apache.servicecomb.core.Invocation; -import org.apache.servicecomb.core.exception.Exceptions; import org.apache.servicecomb.core.filter.AbstractFilter; import org.apache.servicecomb.core.filter.Filter; import org.apache.servicecomb.core.filter.FilterNode; import org.apache.servicecomb.core.filter.ProviderFilter; -import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.swagger.invocation.Response; +import org.apache.servicecomb.swagger.invocation.exception.InvocationException; + +import jakarta.ws.rs.core.Response.Status; public class ScheduleFilter extends AbstractFilter implements ProviderFilter { public static final String NAME = "schedule"; @@ -43,24 +44,17 @@ public int getOrder() { @Override public CompletableFuture onFilter(Invocation invocation, FilterNode next) { - invocation.getInvocationStageTrace().startSchedule(); + invocation.getInvocationStageTrace().startProviderQueue(); Executor executor = invocation.getOperationMeta().getExecutor(); return CompletableFuture.completedFuture(null) .thenComposeAsync(response -> runInExecutor(invocation, next), executor); } protected CompletableFuture runInExecutor(Invocation invocation, FilterNode next) { - invocation.onExecuteStart(); - + invocation.getInvocationStageTrace().finishProviderQueue(); try { - InvocationStageTrace trace = invocation.getInvocationStageTrace(); - trace.startServerFiltersRequest(); - invocation.onStartHandlersRequest(); - checkInQueueTimeout(invocation); - - return next.onFilter(invocation) - .whenComplete((response, throwable) -> whenComplete(invocation)); + return next.onFilter(invocation); } finally { invocation.onExecuteFinish(); } @@ -70,13 +64,8 @@ private void checkInQueueTimeout(Invocation invocation) { long nanoTimeout = invocation.getOperationMeta().getConfig() .getNanoRequestWaitInPoolTimeout(invocation.getTransport().getName()); - if (System.nanoTime() - invocation.getInvocationStageTrace().getStart() > nanoTimeout) { - throw Exceptions.genericProducer("Request in the queue timed out."); + if (invocation.getInvocationStageTrace().calcQueue() > nanoTimeout) { + throw new InvocationException(Status.REQUEST_TIMEOUT, "Request in the queue timed out."); } } - - private void whenComplete(Invocation invocation) { - invocation.getInvocationStageTrace().finishHandlersResponse(); - invocation.getInvocationStageTrace().finishServerFiltersResponse(); - } } diff --git a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationStageTrace.java b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationStageTrace.java index 3f06bb8f01a..0c28b99d0f3 100644 --- a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationStageTrace.java +++ b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationStageTrace.java @@ -16,362 +16,336 @@ */ package org.apache.servicecomb.core.invocation; +import java.util.HashMap; +import java.util.Map; + import org.apache.servicecomb.core.Invocation; /** * 
- * important:
- *   all time point is about invocation stage, not java method
- *   all time is nanoTime
- *   not all stage relate to a event, currently, we only have 4 event:
- *     start/finish/startBusiness/finishBusiness
- *
  * for consumer:
- *         (prepare)                      (handlerReq)                                       (clientFilterReq)
- *   start --------> startHandlersRequest -----------> startClientFiltersRequest --------------------------------------
- *                                                        <----------------(sendRequest)----------------->            |
- *                        (receiveResponse)              (writeToBuffer)                   (getConnection)            |
- *    ---finishReceiveResponse <----- finishWriteToBuffer <----------- finishGetConnection <-------------- startSend <-
- *   | (wakeConsumer)            (clientFiltersResponse)               (handlersResponse)
- *   |-----> startClientFiltersResponse -------> finishClientFiltersResponse -------> finishHandlersResponse --> finish
  *
- * for producer:
- *       (prepare)       (threadPoolQueue)                                (serverFiltersRequest)
- *   start ----> startSchedule -----> startExecution -> startServerFiltersRequest -------> startHandlersRequest -------
- *                          (handlersResponse)          <-------------(business)------------->      (handlersRequest) |
- *   -----finishHandlersResponse <------ finishBusiness <------- finishBusinessMethod <------ startBusinessMethod------
- *   | (serverFiltersResponse)     (sendResponse)
- *   |---> finishServerFiltersResponse ------> finish
+ *  1. total: start create invocation -> all filters finished
+ *  2. prepare: start create invocation -> finish create invocation
+ *  3. filters-(filter-name): start call on filter -> on complete
+ *  4. connection: start get connection -> finish get connection
+ *  5. consumer-encode: start encode request -> finish encode request
+ *  6. consumer-decode: start decode response -> finish decode response
+ *  7. consumer-send: start send request -> finish send request
+ *  8. wait: finish send request -> start decode response
+ *
+ * for provider:
+ *  1. total: start create invocation -> all filters finished
+ *  2. prepare: start create invocation -> finish create invocation
+ *  3. filters-(filter-name): start call on filter -> on complete
+ *  4. queue: add in queue -> execute in thread
+ *  5. provider-decode: start decode request -> finish decode request
+ *  6. provider-encode: start encode response -> finish encode response
+ *  7. provider-send: start send response -> finish send response
+ *  8. execute: start business execute -> finish business execute
  *
  * for edge:
- *      (prepare)         (threadPoolQueue)                               (serverFiltersRequest)
- *   start ----> startSchedule -----> startExecution -> startServerFiltersRequest ----> startHandlersRequest ----------
- *                           <----------(sendRequest)---------->                                                      |
- *                       (writeToBuffer)              (getConnection)  (clientFilterReq)            (handlersRequest) |
- *   --- finishWriteToBuffer <------ finishGetConnection <------ startSend <------ startClientFiltersRequest <---------
- *   | (receiveResponse)     (wakeConsumer)                 (clientFiltersResponse)
- *   ---> finishReceiveResponse ------> startClientFiltersResponse ------> finishClientFiltersResponse ----------------
- *                                   (sendResponse)                  (serverFiltersResponse)       (handlersResponse) |
- *                              finish <------ finishServerFiltersResponse <------ finishHandlersResponse <------------
+ *
+ *  *  1. total: start create invocation -> all filters finished
+ *  *  2. prepare: start create invocation -> finish create invocation
+ *  *  3. filters-(filter-name): start call on filter -> on complete
+ *  *  4. connection: start get connection -> finish get connection
+ *  *  5. provider-decode: start decode request -> finish decode request
+ *  *  6. provider-encode: start encode response -> finish encode response
+ *  *  7. consumer-encode: start encode request -> finish encode request
+ *  *  8. consumer-decode: start decode response -> finish decode response
+ *  *  9. consumer-send: start send request -> finish send request
+ *  *  10. provider-send: start send response -> finish send response
+ *  *  11. wait: finish send request -> start decode response
  *
  *
*/ public class InvocationStageTrace { - public static final String PREPARE = "prepare"; + public static class Stage { + private long beginTime; + + private long endTime; + + public long getBeginTime() { + return beginTime; + } - public static final String HANDLERS_REQUEST = "handlers request"; + public long getEndTime() { + return endTime; + } + } - public static final String HANDLERS_RESPONSE = "handlers response"; + public static final String STAGE_TOTAL = "total"; - public static final String CLIENT_FILTERS_REQUEST = "client filters request"; + public static final String STAGE_PREPARE = "prepare"; - public static final String CONSUMER_SEND_REQUEST = "send request"; + public static final String STAGE_PROVIDER_QUEUE = "queue"; - public static final String CONSUMER_GET_CONNECTION = "get connection"; + public static final String STAGE_PROVIDER_DECODE_REQUEST = "provider-decode"; - public static final String CONSUMER_WRITE_TO_BUF = "write to buf"; + public static final String STAGE_PROVIDER_ENCODE_RESPONSE = "provider-encode"; - public static final String CONSUMER_WAIT_RESPONSE = "wait response"; + public static final String STAGE_PROVIDER_SEND = "provider-send"; - public static final String CONSUMER_WAKE_CONSUMER = "wake consumer"; + public static final String STAGE_PROVIDER_BUSINESS = "execute"; - public static final String CLIENT_FILTERS_RESPONSE = "client filters response"; + public static final String STAGE_CONSUMER_CONNECTION = "connection"; - public static final String THREAD_POOL_QUEUE = "threadPoolQueue"; + public static final String STAGE_CONSUMER_ENCODE_REQUEST = "consumer-encode"; - public static final String SERVER_FILTERS_REQUEST = "server filters request"; + public static final String STAGE_CONSUMER_DECODE_RESPONSE = "consumer-decode"; - public static final String SERVER_FILTERS_RESPONSE = "server filters response"; + public static final String STAGE_CONSUMER_SEND = "consumer-send"; - public static final String PRODUCER_SEND_RESPONSE = "send response"; + public static final String STAGE_CONSUMER_WAIT = "wait"; private final Invocation invocation; - // current time for start invocation - private long startTimeMillis; + // invocation start time in millis, for passing strategy use only + private long startInMillis; + // invocation start time in nanos, for passing strategy use only private long start; - private long startHandlersRequest; + private long finish; - private long startClientFiltersRequest; + private long startCreateInvocation; - // only for consumer - private long startSend; + private long finishCreateInvocation; - // only for consumer - private long startGetConnection; + private long startProviderQueue; - // only for consumer - private long finishGetConnection; + private long finishProviderQueue; - // only for consumer - private long finishWriteToBuffer; + private long startConsumerConnection; - // only for consumer - private long finishReceiveResponse; + private long finishConsumerConnection; - private long startClientFiltersResponse; + private long startProviderDecodeRequest; - private long finishClientFiltersResponse; + private long finishProviderDecodeRequest; - private long finishHandlersResponse; + private long startProviderEncodeResponse; - private long finish; + private long finishProviderEncodeResponse; - // only for producer: put producer task to thread pool - private long startSchedule; + private long startConsumerEncodeRequest; - private long startServerFiltersRequest; + private long finishConsumerEncodeRequest; - private long finishServerFiltersResponse; + private long startConsumerDecodeResponse; - // only for producer: start execute in work thread - // for reactive mode, work thread is eventloop - private long startExecution; + private long finishConsumerDecodeResponse; - // only for producer - private long startBusinessMethod; + private long startProviderSendResponse; - // only for producer - private long finishBusiness; + private long finishProviderSendResponse; - public InvocationStageTrace(Invocation invocation) { - this.invocation = invocation; - } + private long startConsumerSendRequest; - public void start(long start) { - // remember the current time to start invocation - this.startTimeMillis = System.currentTimeMillis(); - this.start = start; - } + private long finishConsumerSendRequest; - public long getStart() { - return start; - } + private long startBusinessExecute; - public long getStartTimeMillis() { - return startTimeMillis; - } + private long finishBusinessExecute; - public InvocationStageTrace setStartTimeMillis(long startTimeMillis) { - this.startTimeMillis = startTimeMillis; - return this; - } + private long startWaitResponse; - public long getStartHandlersRequest() { - return startHandlersRequest; - } + private long finishWaitResponse; - public void startHandlersRequest() { - this.startHandlersRequest = System.nanoTime(); - } - - public long getStartClientFiltersRequest() { - return startClientFiltersRequest; - } + // invocation stage can not be used in concurrent access + private final Map stages = new HashMap<>(); - public void startClientFiltersRequest() { - this.startClientFiltersRequest = System.nanoTime(); - } - - public long getStartSchedule() { - return startSchedule; - } - - public void startSchedule() { - this.startSchedule = System.nanoTime(); + public InvocationStageTrace(Invocation invocation) { + this.invocation = invocation; } - public long getStartExecution() { - return startExecution; + public String recordStageBegin(String stageName) { + String realStageName = stageName; + if (stages.get(stageName) != null) { + realStageName = realStageName + "@"; + } + Stage stage = new Stage(); + stage.beginTime = System.nanoTime(); + stages.put(realStageName, stage); + return realStageName; } - public void startExecution() { - this.startExecution = System.nanoTime(); + public void recordStageEnd(String realStageName) { + Stage stage = stages.get(realStageName); + stage.endTime = nanoTime(); } - public long getStartSend() { - return startSend; + public Map getStages() { + return stages; } - public void startSend() { - this.startSend = System.nanoTime(); + public void finish() { + this.finish = nanoTime(); } - public long getFinishGetConnection() { - return finishGetConnection; + public void startCreateInvocation(long nano) { + this.startCreateInvocation = nano; + this.startInMillis = millisTime(); + this.start = nanoTime(); } - public void startGetConnection() { - this.startGetConnection = System.nanoTime(); + public void finishCreateInvocation() { + this.finishCreateInvocation = nanoTime(); } - public void finishGetConnection() { - this.finishGetConnection = System.nanoTime(); + public long calcPrepare() { + return calc(finishCreateInvocation, startCreateInvocation); } - public long getFinishWriteToBuffer() { - return finishWriteToBuffer; + public void startProviderQueue() { + this.startProviderQueue = nanoTime(); } - public void finishWriteToBuffer(long finishWriteToBuffer) { - this.finishWriteToBuffer = finishWriteToBuffer; + public void finishProviderQueue() { + this.finishProviderQueue = nanoTime(); } - public long getFinishReceiveResponse() { - return finishReceiveResponse; + public long calcQueue() { + return calc(finishProviderQueue, startProviderQueue); } - public void finishReceiveResponse() { - this.finishReceiveResponse = System.nanoTime(); + public void startProviderDecodeRequest() { + this.startProviderDecodeRequest = nanoTime(); } - public long getStartClientFiltersResponse() { - return startClientFiltersResponse; + public void finishProviderDecodeRequest() { + this.finishProviderDecodeRequest = nanoTime(); } - public void startClientFiltersResponse() { - this.startClientFiltersResponse = System.nanoTime(); + public long calcProviderDecodeRequest() { + return calc(finishProviderDecodeRequest, startProviderDecodeRequest); } - public long getFinishClientFiltersResponse() { - return finishClientFiltersResponse; + public void startProviderEncodeResponse() { + this.startProviderEncodeResponse = nanoTime(); } - public void finishClientFiltersResponse() { - this.finishClientFiltersResponse = System.nanoTime(); + public void finishProviderEncodeResponse() { + this.finishProviderEncodeResponse = nanoTime(); } - public long getFinishHandlersResponse() { - return finishHandlersResponse; + public long calcProviderEncodeResponse() { + return calc(finishProviderEncodeResponse, startProviderEncodeResponse); } - public void finishHandlersResponse() { - this.finishHandlersResponse = System.nanoTime(); + public void startConsumerEncodeRequest() { + this.startConsumerEncodeRequest = nanoTime(); } - public long getStartServerFiltersRequest() { - return startServerFiltersRequest; + public void finishConsumerEncodeRequest() { + this.finishConsumerEncodeRequest = nanoTime(); } - public void startServerFiltersRequest() { - this.startServerFiltersRequest = System.nanoTime(); + public long calcConsumerEncodeRequest() { + return calc(finishConsumerEncodeRequest, startConsumerEncodeRequest); } - public long getFinishServerFiltersResponse() { - return finishServerFiltersResponse; + public void startConsumerDecodeResponse() { + this.startConsumerDecodeResponse = nanoTime(); } - public void finishServerFiltersResponse() { - this.finishServerFiltersResponse = System.nanoTime(); + public void finishConsumerDecodeResponse() { + this.finishConsumerDecodeResponse = nanoTime(); } - public long getStartBusinessMethod() { - return startBusinessMethod; + public long calcConsumerDecodeResponse() { + return calc(finishConsumerDecodeResponse, startConsumerDecodeResponse); } - public void startBusinessMethod() { - this.startBusinessMethod = System.nanoTime(); + public void startProviderSendResponse() { + this.startProviderSendResponse = nanoTime(); } - public long getFinishBusiness() { - return finishBusiness; + public void finishProviderSendResponse() { + this.finishProviderSendResponse = nanoTime(); } - public void finishBusiness() { - this.finishBusiness = System.nanoTime(); + public long calcProviderSendResponse() { + return calc(finishProviderSendResponse, startProviderSendResponse); } - public long getFinish() { - return finish; + public void startBusinessExecute() { + this.startBusinessExecute = nanoTime(); } - public void finish() { - this.finish = System.nanoTime(); + public void finishBusinessExecute() { + this.finishBusinessExecute = nanoTime(); } - private double calc(long finish, long start) { - if (finish == 0 || start == 0) { - return Double.NaN; - } - - return finish - start; + public long calcBusinessExecute() { + return calc(finishBusinessExecute, startBusinessExecute); } - public double calcTotalTime() { - return calc(finish, start); + public void startConsumerConnection() { + this.startConsumerConnection = nanoTime(); } - public double calcInvocationPrepareTime() { - if (invocation.isConsumer() && !invocation.isEdge()) { - return calc(startHandlersRequest, start); - } - - return calc(startSchedule, start); + public void finishConsumerConnection() { + this.finishConsumerConnection = nanoTime(); } - public double calcHandlersRequestTime() { - if (invocation.isConsumer()) { - return calc(startClientFiltersRequest, startHandlersRequest); - } - - return calc(startBusinessMethod, startHandlersRequest); + public long calcConnection() { + return calc(finishConsumerConnection, startConsumerConnection); } - public double calcClientFiltersRequestTime() { - return calc(startSend, startClientFiltersRequest); + public void startConsumerSendRequest() { + this.startConsumerSendRequest = nanoTime(); } - public double calcServerFiltersRequestTime() { - return calc(startHandlersRequest, startServerFiltersRequest); + public void finishConsumerSendRequest() { + this.finishConsumerSendRequest = nanoTime(); } - public double calcSendRequestTime() { - return calc(finishWriteToBuffer, startSend); + public long calcConsumerSendRequest() { + return calc(finishConsumerSendRequest, startConsumerSendRequest); } - public double calcGetConnectionTime() { - return calc(finishGetConnection, startGetConnection); + public void startWaitResponse() { + this.startWaitResponse = nanoTime(); } - public double calcWriteToBufferTime() { - return calc(finishWriteToBuffer, finishGetConnection); + public void finishWaitResponse() { + this.finishWaitResponse = nanoTime(); } - public double calcReceiveResponseTime() { - return calc(finishReceiveResponse, finishWriteToBuffer); + public long calcWait() { + return calc(finishWaitResponse, startWaitResponse); } - public double calcWakeConsumer() { - return calc(startClientFiltersResponse, finishReceiveResponse); + public long calcTotal() { + return calc(finish, this.startCreateInvocation); } - public double calcClientFiltersResponseTime() { - return calc(finishClientFiltersResponse, startClientFiltersResponse); + public long getStartInMillis() { + return this.startInMillis; } - public double calcServerFiltersResponseTime() { - return calc(finishServerFiltersResponse, finishHandlersResponse); + public long getStart() { + return this.start; } - public double calcHandlersResponseTime() { - if (invocation.isConsumer()) { - return calc(finishHandlersResponse, finishClientFiltersResponse); + public static long calc(long finish, long start) { + if (finish == 0 || start == 0) { + return 0; } - return calc(finishHandlersResponse, finishBusiness); - } - - public double calcThreadPoolQueueTime() { - return calc(startExecution, startSchedule); + return finish - start; } - public double calcBusinessTime() { - return calc(finishBusiness, startBusinessMethod); + /* + * Holder for testing purpose + */ + protected long nanoTime() { + return System.nanoTime(); } - public double calcSendResponseTime() { - return calc(finish, finishServerFiltersResponse); + protected long millisTime() { + return System.currentTimeMillis(); } } diff --git a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutBootListener.java b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutBootListener.java index 93429e3c7e3..e21ed59b279 100644 --- a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutBootListener.java +++ b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutBootListener.java @@ -21,7 +21,6 @@ import org.apache.servicecomb.core.event.InvocationBusinessFinishEvent; import org.apache.servicecomb.core.event.InvocationBusinessMethodStartEvent; -import org.apache.servicecomb.core.event.InvocationHandlersStartEvent; import org.apache.servicecomb.core.event.InvocationRunInExecutorStartEvent; import org.apache.servicecomb.core.event.InvocationStartEvent; import org.apache.servicecomb.core.event.InvocationStartSendRequestEvent; @@ -80,12 +79,6 @@ public void onInvocationRunInExecutorStartEvent(InvocationRunInExecutorStartEven strategy.startRunInExecutor(event.getInvocation()); } - @Subscribe - @EnableExceptionPropagation - public void onInvocationHandlersStartEvent(InvocationHandlersStartEvent event) { - strategy.startHandlers(event.getInvocation()); - } - @Subscribe @EnableExceptionPropagation public void onInvocationBusinessMethodStartEvent(InvocationBusinessMethodStartEvent event) { diff --git a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutStrategy.java b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutStrategy.java index 24b48619d2c..c530acfca29 100644 --- a/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutStrategy.java +++ b/core/src/main/java/org/apache/servicecomb/core/invocation/InvocationTimeoutStrategy.java @@ -37,10 +37,6 @@ default void startRunInExecutor(Invocation invocation) { checkTimeout(invocation); } - default void startHandlers(Invocation invocation) { - checkTimeout(invocation); - } - default void startBusinessMethod(Invocation invocation) { checkTimeout(invocation); } diff --git a/core/src/main/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlow.java b/core/src/main/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlow.java index ba82fb515f1..9ccef3b998d 100644 --- a/core/src/main/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlow.java +++ b/core/src/main/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlow.java @@ -60,8 +60,9 @@ private void tryRunInvocation(Invocation invocation) { if (invocation == null) { return; } - - invocation.onStart(requestEx, startTime); + invocation.getInvocationStageTrace().startCreateInvocation(this.startTime); + invocation.getInvocationStageTrace().finishCreateInvocation(); + invocation.onStart(requestEx); if (invocation.isEdge()) { invocation.getMicroserviceMeta().getEdgeFilterChain() .onFilter(invocation) diff --git a/core/src/main/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategy.java b/core/src/main/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategy.java index 986c085b394..6d55c7a7f51 100644 --- a/core/src/main/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategy.java +++ b/core/src/main/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategy.java @@ -78,7 +78,7 @@ public void start(Invocation invocation) { return; } - long startTimeMillis = invocation.getInvocationStageTrace().getStartTimeMillis(); + long startTimeMillis = invocation.getInvocationStageTrace().getStartInMillis(); String contextChainStartTime = invocation.getContext(CHAIN_START_TIME); if (StringUtils.isEmpty(contextChainStartTime)) { invocation.addContext(CHAIN_START_TIME, String.valueOf(startTimeMillis)); diff --git a/core/src/main/java/org/apache/servicecomb/core/provider/consumer/InvokerUtils.java b/core/src/main/java/org/apache/servicecomb/core/provider/consumer/InvokerUtils.java index 49be3bd4f20..5c2a012ae85 100644 --- a/core/src/main/java/org/apache/servicecomb/core/provider/consumer/InvokerUtils.java +++ b/core/src/main/java/org/apache/servicecomb/core/provider/consumer/InvokerUtils.java @@ -128,6 +128,7 @@ public static void reactiveInvoke(String microserviceName, String schemaId, Stri public static Invocation createInvocation(String microserviceName, String transport, String schemaId, String operationId, Map swaggerArguments, Type responseType) { + long startCreateInvocation = System.nanoTime(); MicroserviceReferenceConfig microserviceReferenceConfig = SCBEngine.getInstance() .getOrCreateReferenceConfig(microserviceName); if (microserviceReferenceConfig == null) { @@ -142,8 +143,11 @@ public static Invocation createInvocation(String microserviceName, String transp ReferenceConfig referenceConfig = microserviceReferenceConfig.createReferenceConfig(transport, operationMeta); InvocationRuntimeType invocationRuntimeType = operationMeta.buildBaseConsumerRuntimeType(); invocationRuntimeType.setSuccessResponseType(responseType); - return InvocationFactory + Invocation result = InvocationFactory .forConsumer(referenceConfig, operationMeta, invocationRuntimeType, swaggerArguments); + result.getInvocationStageTrace().startCreateInvocation(startCreateInvocation); + result.getInvocationStageTrace().finishCreateInvocation(); + return result; } /** @@ -311,9 +315,8 @@ public static CompletableFuture invoke(Invocation invocation) { private static Supplier> invokeImpl(Invocation invocation) { return () -> { - invocation.onStart(null, System.nanoTime()); + invocation.onStart(null); updateRetryStatus(invocation); - invocation.onStartHandlersRequest(); if (invocation.isEdge()) { return invocation.getMicroserviceMeta().getEdgeFilterChain() .onFilter(invocation) @@ -328,7 +331,6 @@ private static Supplier> invokeImpl(Invocation invocat } private static void finishInvocation(Invocation invocation, Response ar) { - invocation.getInvocationStageTrace().finishHandlersResponse(); invocation.onFinish(ar); if (ar.isFailed()) { diff --git a/core/src/test/java/org/apache/servicecomb/core/TestInvocation.java b/core/src/test/java/org/apache/servicecomb/core/TestInvocation.java index 96910a4ca4e..ac1af9b51a6 100644 --- a/core/src/test/java/org/apache/servicecomb/core/TestInvocation.java +++ b/core/src/test/java/org/apache/servicecomb/core/TestInvocation.java @@ -22,7 +22,6 @@ import org.apache.servicecomb.core.definition.InvocationRuntimeType; import org.apache.servicecomb.core.definition.OperationMeta; import org.apache.servicecomb.core.event.InvocationBaseEvent; -import org.apache.servicecomb.core.event.InvocationBusinessMethodFinishEvent; import org.apache.servicecomb.core.event.InvocationBusinessMethodStartEvent; import org.apache.servicecomb.core.event.InvocationFinishEvent; import org.apache.servicecomb.core.event.InvocationStartEvent; @@ -39,6 +38,7 @@ import org.junit.AfterClass; import org.junit.BeforeClass; import org.junit.Test; +import org.junit.jupiter.api.Assertions; import com.google.common.eventbus.EventBus; import com.google.common.eventbus.Subscribe; @@ -48,8 +48,6 @@ import mockit.MockUp; import mockit.Mocked; -import org.junit.jupiter.api.Assertions; - public class TestInvocation { Invocation invocation; @@ -88,8 +86,6 @@ public static void classTeardown() { @Test public void onStart() { - mockNonaTime(); - Holder result = new Holder<>(); Object subscriber = new Object() { @Subscribe @@ -100,24 +96,12 @@ public void onStart(InvocationStartEvent event) { EventManager.register(subscriber); Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - invocation.onStart(nanoTime); + invocation.onStart(); Assertions.assertSame(invocation, result.value); - Assertions.assertEquals(nanoTime, invocation.getInvocationStageTrace().getStart()); - EventManager.unregister(subscriber); } - @Test - public void onStartExecute() { - mockNonaTime(); - - Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - invocation.onExecuteStart(); - - Assertions.assertEquals(nanoTime, invocation.getInvocationStageTrace().getStartExecution()); - } - @Test public void onFinish() { mockNonaTime(); @@ -136,7 +120,6 @@ public void onStart(InvocationFinishEvent event) { Response response = Response.succResp(null); invocation.onFinish(response); - Assertions.assertEquals(nanoTime, result.value.getNanoCurrent()); Assertions.assertSame(invocation, result.value.getInvocation()); Assertions.assertSame(response, result.value.getResponse()); Assertions.assertTrue(invocation.isFinished()); @@ -175,7 +158,7 @@ public void traceId_fromContext(@Mocked ReferenceConfig referenceConfig) { Invocation invocation = new Invocation(referenceConfig, operationMeta, invocationRuntimeType, arguments); invocation.addContext(CoreConst.TRACE_ID_NAME, "abc"); - invocation.onStart(0); + invocation.onStart(); Assertions.assertEquals("abc", invocation.getTraceId()); Assertions.assertEquals("abc", invocation.getTraceId(CoreConst.TRACE_ID_NAME)); @@ -192,7 +175,7 @@ public void traceId_consumerCreateTraceId(@Mocked ReferenceConfig referenceConfi }; Invocation invocation = new Invocation(referenceConfig, operationMeta, invocationRuntimeType, arguments); - invocation.onStart(0); + invocation.onStart(); Assertions.assertEquals("abc", invocation.getTraceId()); Assertions.assertEquals("abc", invocation.getTraceId(CoreConst.TRACE_ID_NAME)); @@ -208,7 +191,7 @@ public void traceId_fromRequest(@Mocked Endpoint endpoint, @Mocked HttpServletRe }; Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - invocation.onStart(requestEx, 0); + invocation.onStart(requestEx); Assertions.assertEquals("abc", invocation.getTraceId()); Assertions.assertEquals("abc", invocation.getTraceId(CoreConst.TRACE_ID_NAME)); @@ -225,7 +208,7 @@ public void traceId_producerCreateTraceId(@Mocked Endpoint endpoint, @Mocked Htt }; Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - invocation.onStart(requestEx, 0); + invocation.onStart(requestEx); Assertions.assertEquals("abc", invocation.getTraceId()); Assertions.assertEquals("abc", invocation.getTraceId(CoreConst.TRACE_ID_NAME)); @@ -259,7 +242,7 @@ public void traceIdGeneratorInit(@Mocked TraceIdGenerator gen1, @Mocked TraceIdG InvocationBaseEvent invocationBaseEvent; @Test - public void onBusinessMethodStart() { + public void test_business_execute_time_correct() { Object listener = new Object() { @Subscribe public void onBusinessMethodStart(InvocationBusinessMethodStartEvent event) { @@ -273,32 +256,9 @@ public void onBusinessMethodStart(InvocationBusinessMethodStartEvent event) { EventManager.getEventBus().unregister(listener); Assertions.assertSame(invocation, invocationBaseEvent.getInvocation()); - Assertions.assertEquals(nanoTime, invocation.getInvocationStageTrace().getStartBusinessMethod()); - } - - @Test - public void onBusinessMethodFinish() { - Object listener = new Object() { - @Subscribe - public void onBusinessMethodStart(InvocationBusinessMethodFinishEvent event) { - invocationBaseEvent = event; - } - }; - EventManager.getEventBus().register(listener); - Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - invocation.onBusinessMethodFinish(); - EventManager.getEventBus().unregister(listener); - - Assertions.assertSame(invocation, invocationBaseEvent.getInvocation()); - } - - @Test - public void onBusinessFinish() { - Invocation invocation = new Invocation(endpoint, operationMeta, arguments); - mockNonaTime(); + nanoTime++; invocation.onBusinessFinish(); - - Assertions.assertEquals(nanoTime, invocation.getInvocationStageTrace().getFinishBusiness()); + Assertions.assertEquals(1, invocation.getInvocationStageTrace().calcBusinessExecute()); } @Test @@ -307,12 +267,12 @@ public void marker(@Mocked ReferenceConfig referenceConfig) { Invocation invocation = new Invocation(referenceConfig, operationMeta, invocationRuntimeType, arguments); invocation.addContext(CoreConst.TRACE_ID_NAME, "abc"); - invocation.onStart(0); + invocation.onStart(); Assertions.assertEquals("abc-0", invocation.getTraceIdLogger().getName()); invocation = new Invocation(referenceConfig, operationMeta, invocationRuntimeType, arguments); invocation.addContext(CoreConst.TRACE_ID_NAME, "abc"); - invocation.onStart(0); + invocation.onStart(); Assertions.assertEquals("abc-1", invocation.getTraceIdLogger().getName()); } } diff --git a/core/src/test/java/org/apache/servicecomb/core/event/TestInvocationFinishEvent.java b/core/src/test/java/org/apache/servicecomb/core/event/TestInvocationFinishEvent.java deleted file mode 100644 index 63380368d4a..00000000000 --- a/core/src/test/java/org/apache/servicecomb/core/event/TestInvocationFinishEvent.java +++ /dev/null @@ -1,57 +0,0 @@ -/* - * Licensed to the Apache Software Foundation (ASF) under one or more - * contributor license agreements. See the NOTICE file distributed with - * this work for additional information regarding copyright ownership. - * The ASF licenses this file to You 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 org.apache.servicecomb.core.event; - -import org.apache.servicecomb.core.Invocation; -import org.apache.servicecomb.core.invocation.InvocationStageTrace; -import org.apache.servicecomb.swagger.invocation.Response; -import org.junit.Test; - -import mockit.Expectations; -import mockit.Mock; -import mockit.MockUp; -import mockit.Mocked; -import org.junit.jupiter.api.Assertions; - -public class TestInvocationFinishEvent { - InvocationFinishEvent event; - - @Test - public void construct(@Mocked Invocation invocation, @Mocked Response response) { - InvocationStageTrace stageTrace = new InvocationStageTrace(invocation); - long time = 123; - new MockUp() { - @Mock - long nanoTime() { - return time; - } - }; - new Expectations() { - { - invocation.getInvocationStageTrace(); - result = stageTrace; - } - }; - stageTrace.finish(); - - event = new InvocationFinishEvent(invocation, response); - - Assertions.assertEquals(time, event.getNanoCurrent()); - Assertions.assertSame(invocation, event.getInvocation()); - Assertions.assertSame(response, event.getResponse()); - } -} diff --git a/core/src/test/java/org/apache/servicecomb/core/filter/FilterChainTest.java b/core/src/test/java/org/apache/servicecomb/core/filter/FilterChainTest.java index db4d2b15c32..5a5dc1cb05e 100644 --- a/core/src/test/java/org/apache/servicecomb/core/filter/FilterChainTest.java +++ b/core/src/test/java/org/apache/servicecomb/core/filter/FilterChainTest.java @@ -55,19 +55,35 @@ public class FilterChainTest { List msg = new Vector<>(); - Filter recordThreadFilter = (invocation, nextNode) -> { - msg.add(Thread.currentThread().getName()); - if (nextNode == null) { - return CompletableFuture.completedFuture(Response.ok(null)); + Filter recordThreadFilter = new AbstractFilter() { + @Override + public String getName() { + return "f2"; } - return nextNode.onFilter(invocation); + @Override + public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { + msg.add(Thread.currentThread().getName()); + if (nextNode == null) { + return CompletableFuture.completedFuture(Response.ok(null)); + } + + return nextNode.onFilter(invocation); + } }; Filter scheduler = new ScheduleFilter(); - Filter exceptionFilter = (invocation, nextNode) -> { - throw new IllegalStateException("e1"); + Filter exceptionFilter = new AbstractFilter() { + @Override + public String getName() { + return "f1"; + } + + @Override + public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { + throw new IllegalStateException("e1"); + } }; @BeforeClass diff --git a/core/src/test/java/org/apache/servicecomb/core/filter/impl/ProducerOperationFilterTest.java b/core/src/test/java/org/apache/servicecomb/core/filter/impl/ProducerOperationFilterTest.java index 4a072a2bad3..4531895e9b2 100644 --- a/core/src/test/java/org/apache/servicecomb/core/filter/impl/ProducerOperationFilterTest.java +++ b/core/src/test/java/org/apache/servicecomb/core/filter/impl/ProducerOperationFilterTest.java @@ -83,9 +83,6 @@ public void should_record_invocation_trace_time() throws NoSuchMethodException { invocation.onBusinessMethodStart(); times = 1; - invocation.onBusinessMethodFinish(); - times = 1; - invocation.onBusinessFinish(); times = 1; } @@ -139,11 +136,11 @@ public void should_catch_sync_business_exception() throws NoSuchMethodException CompletableFuture future = filter.onFilter(invocation, FilterNode.EMPTY); assertThat(future) - .failsWithin(Duration.ofSeconds(1)) - .withThrowableOfType(ExecutionException.class) - .withCauseExactlyInstanceOf(RuntimeExceptionWithoutStackTrace.class) - .withMessage("org.apache.servicecomb.foundation.test.scaffolding.exception" + - ".RuntimeExceptionWithoutStackTrace: syncException"); + .failsWithin(Duration.ofSeconds(1)) + .withThrowableOfType(ExecutionException.class) + .withCauseExactlyInstanceOf(RuntimeExceptionWithoutStackTrace.class) + .withMessage("org.apache.servicecomb.foundation.test.scaffolding.exception" + + ".RuntimeExceptionWithoutStackTrace: syncException"); } @Test @@ -171,11 +168,11 @@ public void should_catch_async_business_exception() throws NoSuchMethodException CompletableFuture future = filter.onFilter(invocation, FilterNode.EMPTY); assertThat(future) - .failsWithin(Duration.ofSeconds(1)) - .withThrowableOfType(ExecutionException.class) - .withCauseExactlyInstanceOf(RuntimeExceptionWithoutStackTrace.class) - .withMessage("org.apache.servicecomb.foundation.test.scaffolding" + - ".exception.RuntimeExceptionWithoutStackTrace: asyncException"); + .failsWithin(Duration.ofSeconds(1)) + .withThrowableOfType(ExecutionException.class) + .withCauseExactlyInstanceOf(RuntimeExceptionWithoutStackTrace.class) + .withMessage("org.apache.servicecomb.foundation.test.scaffolding" + + ".exception.RuntimeExceptionWithoutStackTrace: asyncException"); } @Test @@ -190,10 +187,10 @@ public void should_unify_IllegalArgumentException_message_when_convert_exception CompletableFuture future = filter.onFilter(invocation, FilterNode.EMPTY); assertThat(future) - .failsWithin(Duration.ofSeconds(1)) - .withThrowableOfType(ExecutionException.class) - .withCauseExactlyInstanceOf(IllegalArgumentException.class) - .withMessage("java.lang.IllegalArgumentException: wrong number of arguments"); + .failsWithin(Duration.ofSeconds(1)) + .withThrowableOfType(ExecutionException.class) + .withCauseExactlyInstanceOf(IllegalArgumentException.class) + .withMessage("java.lang.IllegalArgumentException: wrong number of arguments"); InvocationException throwable = Exceptions .convert(invocation, catchThrowable(future::get), INTERNAL_SERVER_ERROR); diff --git a/core/src/test/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlowTest.java b/core/src/test/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlowTest.java index 559bedb7b40..7bba26f4da5 100644 --- a/core/src/test/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlowTest.java +++ b/core/src/test/java/org/apache/servicecomb/core/invocation/ProducerInvocationFlowTest.java @@ -20,9 +20,12 @@ import static java.util.concurrent.CompletableFuture.completedFuture; import static org.assertj.core.api.Assertions.assertThat; +import java.util.concurrent.CompletableFuture; + import org.apache.servicecomb.core.Invocation; import org.apache.servicecomb.core.definition.MicroserviceMeta; import org.apache.servicecomb.core.exception.Exceptions; +import org.apache.servicecomb.core.filter.AbstractFilter; import org.apache.servicecomb.core.filter.FilterNode; import org.apache.servicecomb.foundation.test.scaffolding.exception.RuntimeExceptionWithoutStackTrace; import org.apache.servicecomb.foundation.vertx.http.HttpServletRequestEx; @@ -94,7 +97,7 @@ public void should_start_invocation_when_succeed_to_create_invocation() { new Verifications() { { - invocation.onStart((HttpServletRequestEx) any, anyLong); + invocation.onStart((HttpServletRequestEx) any); times = 1; } }; @@ -126,8 +129,16 @@ public void should_finish_invocation_when_invocation_success() { } private void mockInvocationFailed() { - filterNode = new FilterNode((_invocation, _node) -> { - throw new RuntimeExceptionWithoutStackTrace(); + filterNode = new FilterNode(new AbstractFilter() { + @Override + public String getName() { + return "test"; + } + + @Override + public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { + throw new RuntimeExceptionWithoutStackTrace(); + } }); mockFilterChain(); } diff --git a/core/src/test/java/org/apache/servicecomb/core/invocation/TestInvocationStageTrace.java b/core/src/test/java/org/apache/servicecomb/core/invocation/TestInvocationStageTrace.java index 5d81bfe06ca..62f0dc0fa38 100644 --- a/core/src/test/java/org/apache/servicecomb/core/invocation/TestInvocationStageTrace.java +++ b/core/src/test/java/org/apache/servicecomb/core/invocation/TestInvocationStageTrace.java @@ -26,11 +26,11 @@ import org.apache.servicecomb.core.provider.consumer.ReferenceConfig; import org.junit.BeforeClass; import org.junit.Test; +import org.junit.jupiter.api.Assertions; import mockit.Mock; import mockit.MockUp; import mockit.Mocked; -import org.junit.jupiter.api.Assertions; public class TestInvocationStageTrace { Invocation invocation; @@ -68,51 +68,34 @@ public void consumer() { invocation = new Invocation(referenceConfig, operationMeta, invocationRuntimeType, args); stageTrace = new InvocationStageTrace(invocation); - stageTrace.start(1); + stageTrace.startCreateInvocation(1); nanoTime = 2; - stageTrace.startHandlersRequest(); + stageTrace.finishCreateInvocation(); + stageTrace.startConsumerConnection(); nanoTime = 3; - stageTrace.startClientFiltersRequest(); + stageTrace.finishConsumerConnection(); + stageTrace.startConsumerEncodeRequest(); nanoTime = 4; - stageTrace.startGetConnection(); - stageTrace.startSend(); + stageTrace.finishConsumerEncodeRequest(); + stageTrace.startConsumerSendRequest(); nanoTime = 5; - stageTrace.finishGetConnection(); - stageTrace.finishWriteToBuffer(6); + stageTrace.finishConsumerSendRequest(); + stageTrace.startWaitResponse(); + nanoTime = 6; + stageTrace.finishWaitResponse(); + stageTrace.startConsumerDecodeResponse(); nanoTime = 7; - stageTrace.finishReceiveResponse(); - nanoTime = 8; - stageTrace.startClientFiltersResponse(); - nanoTime = 9; - stageTrace.finishClientFiltersResponse(); - nanoTime = 10; - stageTrace.finishHandlersResponse(); - nanoTime = 11; + stageTrace.finishConsumerDecodeResponse(); + stageTrace.finish(); - Assertions.assertEquals(1, stageTrace.getStart()); - Assertions.assertEquals(2, stageTrace.getStartHandlersRequest()); - Assertions.assertEquals(3, stageTrace.getStartClientFiltersRequest()); - Assertions.assertEquals(4, stageTrace.getStartSend()); - Assertions.assertEquals(5, stageTrace.getFinishGetConnection()); - Assertions.assertEquals(6, stageTrace.getFinishWriteToBuffer()); - Assertions.assertEquals(7, stageTrace.getFinishReceiveResponse()); - Assertions.assertEquals(8, stageTrace.getStartClientFiltersResponse()); - Assertions.assertEquals(9, stageTrace.getFinishClientFiltersResponse()); - Assertions.assertEquals(10, stageTrace.getFinishHandlersResponse()); - Assertions.assertEquals(11, stageTrace.getFinish()); - - Assertions.assertEquals(1f, stageTrace.calcInvocationPrepareTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcHandlersRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcClientFiltersRequestTime(), 0.1f); - Assertions.assertEquals(2f, stageTrace.calcSendRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcGetConnectionTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcWriteToBufferTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcReceiveResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcWakeConsumer(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcClientFiltersResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcHandlersResponseTime(), 0.1f); - Assertions.assertEquals(10f, stageTrace.calcTotalTime(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcPrepare(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConnection(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConsumerEncodeRequest(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConsumerSendRequest(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcWait(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConsumerDecodeResponse(), 0.1f); + Assertions.assertEquals(6f, stageTrace.calcTotal(), 0.1f); } @Test @@ -120,46 +103,34 @@ public void producer() { invocation = new Invocation(endpoint, operationMeta, args); stageTrace = new InvocationStageTrace(invocation); - stageTrace.start(1); + stageTrace.startCreateInvocation(1); nanoTime = 2; - stageTrace.startSchedule(); + stageTrace.finishCreateInvocation(); + stageTrace.startProviderDecodeRequest(); nanoTime = 3; - stageTrace.startExecution(); + stageTrace.finishProviderDecodeRequest(); + stageTrace.startProviderQueue(); nanoTime = 4; - stageTrace.startServerFiltersRequest(); + stageTrace.finishProviderQueue(); + stageTrace.startBusinessExecute(); nanoTime = 5; - stageTrace.startHandlersRequest(); + stageTrace.finishBusinessExecute(); + stageTrace.startProviderEncodeResponse(); nanoTime = 6; - stageTrace.startBusinessMethod(); + stageTrace.finishProviderEncodeResponse(); + stageTrace.startProviderSendResponse(); nanoTime = 7; - stageTrace.finishBusiness(); - nanoTime = 8; - stageTrace.finishHandlersResponse(); - nanoTime = 9; - stageTrace.finishServerFiltersResponse(); - nanoTime = 10; + stageTrace.finishProviderSendResponse(); + stageTrace.finish(); - Assertions.assertEquals(1, stageTrace.getStart()); - Assertions.assertEquals(2, stageTrace.getStartSchedule()); - Assertions.assertEquals(3, stageTrace.getStartExecution()); - Assertions.assertEquals(4, stageTrace.getStartServerFiltersRequest()); - Assertions.assertEquals(5, stageTrace.getStartHandlersRequest()); - Assertions.assertEquals(6, stageTrace.getStartBusinessMethod()); - Assertions.assertEquals(7, stageTrace.getFinishBusiness()); - Assertions.assertEquals(8, stageTrace.getFinishHandlersResponse()); - Assertions.assertEquals(9, stageTrace.getFinishServerFiltersResponse()); - Assertions.assertEquals(10, stageTrace.getFinish()); - - Assertions.assertEquals(1f, stageTrace.calcInvocationPrepareTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcThreadPoolQueueTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcServerFiltersRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcHandlersRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcBusinessTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcHandlersResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcServerFiltersResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcSendResponseTime(), 0.1f); - Assertions.assertEquals(9f, stageTrace.calcTotalTime(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcPrepare(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcQueue(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcProviderDecodeRequest(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcProviderEncodeResponse(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcBusinessExecute(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcProviderSendResponse(), 0.1f); + Assertions.assertEquals(6f, stageTrace.calcTotal(), 0.1f); } @Test @@ -168,68 +139,45 @@ public void edge() { stageTrace = new InvocationStageTrace(invocation); invocation.setEdge(true); - stageTrace.start(1); + stageTrace.startCreateInvocation(1); nanoTime = 2; - stageTrace.startSchedule(); + stageTrace.finishCreateInvocation(); + stageTrace.startProviderDecodeRequest(); nanoTime = 3; - stageTrace.startExecution(); + stageTrace.finishProviderDecodeRequest(); + stageTrace.startConsumerConnection(); nanoTime = 4; - stageTrace.startServerFiltersRequest(); + stageTrace.finishConsumerConnection(); + stageTrace.startConsumerEncodeRequest(); nanoTime = 5; - stageTrace.startHandlersRequest(); + stageTrace.finishConsumerEncodeRequest(); + stageTrace.startConsumerSendRequest(); nanoTime = 6; - stageTrace.startClientFiltersRequest(); + stageTrace.finishConsumerSendRequest(); + stageTrace.startWaitResponse(); nanoTime = 7; - stageTrace.startGetConnection(); - stageTrace.startSend(); + stageTrace.finishWaitResponse(); + stageTrace.startConsumerDecodeResponse(); nanoTime = 8; - stageTrace.finishGetConnection(); - stageTrace.finishWriteToBuffer(9); + stageTrace.finishConsumerDecodeResponse(); + stageTrace.startProviderEncodeResponse(); nanoTime = 10; - stageTrace.finishReceiveResponse(); + stageTrace.finishProviderEncodeResponse(); + stageTrace.startProviderSendResponse(); nanoTime = 11; - stageTrace.startClientFiltersResponse(); - nanoTime = 12; - stageTrace.finishClientFiltersResponse(); - nanoTime = 13; - stageTrace.finishHandlersResponse(); - nanoTime = 14; - stageTrace.finishServerFiltersResponse(); - nanoTime = 15; + stageTrace.finishProviderSendResponse(); stageTrace.finish(); - Assertions.assertEquals(1, stageTrace.getStart()); - Assertions.assertEquals(2, stageTrace.getStartSchedule()); - Assertions.assertEquals(3, stageTrace.getStartExecution()); - Assertions.assertEquals(4, stageTrace.getStartServerFiltersRequest()); - Assertions.assertEquals(5, stageTrace.getStartHandlersRequest()); - Assertions.assertEquals(6, stageTrace.getStartClientFiltersRequest()); - Assertions.assertEquals(7, stageTrace.getStartSend()); - Assertions.assertEquals(8, stageTrace.getFinishGetConnection()); - Assertions.assertEquals(9, stageTrace.getFinishWriteToBuffer()); - Assertions.assertEquals(10, stageTrace.getFinishReceiveResponse()); - Assertions.assertEquals(11, stageTrace.getStartClientFiltersResponse()); - Assertions.assertEquals(12, stageTrace.getFinishClientFiltersResponse()); - Assertions.assertEquals(13, stageTrace.getFinishHandlersResponse()); - Assertions.assertEquals(14, stageTrace.getFinishServerFiltersResponse()); - Assertions.assertEquals(15, stageTrace.getFinish()); - - Assertions.assertEquals(1f, stageTrace.calcInvocationPrepareTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcThreadPoolQueueTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcServerFiltersRequestTime(), 0.1f); - - Assertions.assertEquals(1f, stageTrace.calcHandlersRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcClientFiltersRequestTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcGetConnectionTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcWriteToBufferTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcReceiveResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcWakeConsumer(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcClientFiltersResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcHandlersResponseTime(), 0.1f); - - Assertions.assertEquals(1f, stageTrace.calcServerFiltersResponseTime(), 0.1f); - Assertions.assertEquals(1f, stageTrace.calcSendResponseTime(), 0.1f); - - Assertions.assertEquals(14f, stageTrace.calcTotalTime(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcPrepare(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConnection(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConsumerEncodeRequest(), 0.1f); + + Assertions.assertEquals(1f, stageTrace.calcConsumerSendRequest(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcWait(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcConsumerDecodeResponse(), 0.1f); + Assertions.assertEquals(2f, stageTrace.calcProviderEncodeResponse(), 0.1f); + Assertions.assertEquals(1f, stageTrace.calcProviderSendResponse(), 0.1f); + + Assertions.assertEquals(10f, stageTrace.calcTotal(), 0.1f); } } diff --git a/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategyTest.java b/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategyTest.java index 9481fd19e38..58de7e9d2a0 100644 --- a/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategyTest.java +++ b/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/PassingTimeStrategyTest.java @@ -32,17 +32,6 @@ class PassingTimeStrategyTest { PassingTimeStrategy strategy = new PassingTimeStrategy(); - @Test - void should_init_when_start_as_first_chain_node() { - Invocation invocation = new Invocation(); - invocation.getInvocationStageTrace().setStartTimeMillis(10); - - strategy.start(invocation); - - assertThat(invocation.getContext(CHAIN_START_TIME)).isEqualTo("10"); - assertThat(invocation.getLocalContext(CHAIN_START_TIME)).isEqualTo(10L); - } - @Test void should_init_when_start_as_first_node_of_a_process_but_not_first_of_a_chain() { Invocation invocation = new Invocation(); diff --git a/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/ProcessingTimeStrategyTest.java b/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/ProcessingTimeStrategyTest.java index 07d84e5b3e4..05d744e15db 100644 --- a/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/ProcessingTimeStrategyTest.java +++ b/core/src/test/java/org/apache/servicecomb/core/invocation/timeout/ProcessingTimeStrategyTest.java @@ -31,17 +31,6 @@ class ProcessingTimeStrategyTest { ProcessingTimeStrategy strategy = new ProcessingTimeStrategy(); - @Test - void should_init_when_start_as_first_chain_node() { - Invocation invocation = new Invocation(); - invocation.getInvocationStageTrace().start(10); - - strategy.start(invocation); - - assertThat(invocation.getLocalContext(CHAIN_START_TIME)).isEqualTo(10L); - assertThat(invocation.getLocalContext(CHAIN_PROCESSING)).isEqualTo(0L); - } - @Test void should_do_nothing_when_not_first_node_of_a_process() { Invocation invocation = new Invocation(); diff --git a/core/src/test/java/org/apache/servicecomb/core/provider/consumer/TestInvokerUtils.java b/core/src/test/java/org/apache/servicecomb/core/provider/consumer/TestInvokerUtils.java index 9eba671f305..d526219c5ff 100644 --- a/core/src/test/java/org/apache/servicecomb/core/provider/consumer/TestInvokerUtils.java +++ b/core/src/test/java/org/apache/servicecomb/core/provider/consumer/TestInvokerUtils.java @@ -19,8 +19,8 @@ import org.apache.servicecomb.swagger.invocation.Response; import org.apache.servicecomb.swagger.invocation.exception.InvocationException; -import org.junit.Test; import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.Test; public class TestInvokerUtils { @Test diff --git a/foundations/foundation-config/src/test/java/org/apache/servicecomb/config/inject/TestPlaceholderResolver.java b/foundations/foundation-config/src/test/java/org/apache/servicecomb/config/inject/TestPlaceholderResolver.java index 2f7020628f4..d6407785f65 100644 --- a/foundations/foundation-config/src/test/java/org/apache/servicecomb/config/inject/TestPlaceholderResolver.java +++ b/foundations/foundation-config/src/test/java/org/apache/servicecomb/config/inject/TestPlaceholderResolver.java @@ -20,18 +20,22 @@ import java.util.HashMap; import java.util.Map; +import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; import org.hamcrest.MatcherAssert; import org.hamcrest.Matchers; -import org.junit.BeforeClass; -import org.junit.Test; +import org.junit.jupiter.api.BeforeAll; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; +import org.springframework.core.env.Environment; public class TestPlaceholderResolver { static Map parameters = new HashMap<>(); static PlaceholderResolver resolver = new PlaceholderResolver(); - @BeforeClass - public static void setup() { + @BeforeAll + public static void setupClass() { parameters.put("key", "value"); parameters.put("varOfVar", Arrays.asList("${key}")); @@ -42,6 +46,14 @@ public static void setup() { parameters.put("high-list", Arrays.asList("high-1", "high-2")); } + protected Environment environment; + + @BeforeEach + public void setup() { + environment = Mockito.mock(Environment.class); + LegacyPropertyFactory.setEnvironment(environment); + } + @Test public void unknown() { MatcherAssert.assertThat(resolver.replace("prefix${xxx}suffix", parameters), @@ -106,7 +118,8 @@ public void nested() { @Test public void mixed() { - MatcherAssert.assertThat(resolver.replace("prefix.${${priority}-list}.${key}.${high-list}.suffix ${xxx}", parameters), + MatcherAssert.assertThat( + resolver.replace("prefix.${${priority}-list}.${key}.${high-list}.suffix ${xxx}", parameters), Matchers.contains( "prefix.low-1.value.high-1.suffix ${xxx}", "prefix.low-2.value.high-1.suffix ${xxx}", diff --git a/foundations/foundation-vertx/src/test/java/org/apache/servicecomb/foundation/vertx/server/TestTcpServer.java b/foundations/foundation-vertx/src/test/java/org/apache/servicecomb/foundation/vertx/server/TestTcpServer.java index 2e1446c9e73..489a21d8a1e 100644 --- a/foundations/foundation-vertx/src/test/java/org/apache/servicecomb/foundation/vertx/server/TestTcpServer.java +++ b/foundations/foundation-vertx/src/test/java/org/apache/servicecomb/foundation/vertx/server/TestTcpServer.java @@ -17,25 +17,28 @@ package org.apache.servicecomb.foundation.vertx.server; +import static org.mockito.ArgumentMatchers.any; + import java.net.InetSocketAddress; +import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; import org.apache.servicecomb.foundation.common.net.URIEndpointObject; import org.apache.servicecomb.foundation.vertx.AsyncResultCallback; import org.apache.servicecomb.foundation.vertx.metrics.DefaultTcpServerMetrics; import org.apache.servicecomb.foundation.vertx.metrics.metric.DefaultServerEndpointMetric; -import org.junit.Test; +import org.junit.jupiter.api.Assertions; +import org.junit.jupiter.api.BeforeEach; +import org.junit.jupiter.api.Test; +import org.mockito.Mockito; +import org.mockito.stubbing.Answer; +import org.springframework.core.env.Environment; import io.vertx.core.Handler; import io.vertx.core.Vertx; import io.vertx.core.net.NetServer; -import io.vertx.core.net.NetServerOptions; import io.vertx.core.net.NetSocket; +import io.vertx.core.net.SocketAddress; import io.vertx.core.net.impl.NetSocketImpl; -import mockit.Expectations; -import mockit.Mock; -import mockit.MockUp; -import mockit.Mocked; -import org.junit.jupiter.api.Assertions; public class TestTcpServer { static class TcpServerForTest extends TcpServer { @@ -54,37 +57,23 @@ public void init(NetSocket netSocket) { } } - @SuppressWarnings({"rawtypes", "unchecked"}) - @Test - public void testTcpServerNonSSL(@Mocked Vertx vertx, @Mocked AsyncResultCallback callback, - @Mocked NetServer netServer) { - new Expectations() { - { - vertx.createNetServer(); - result = netServer; - netServer.connectHandler((Handler) any); - netServer.listen(anyInt, anyString, (Handler) any); - } - }; - URIEndpointObject endpointObject = new URIEndpointObject("highway://127.0.0.1:6663"); - TcpServer server = new TcpServerForTest(endpointObject); - // assert done in Expectations - server.init(vertx, "", callback); + protected Environment environment; + + @BeforeEach + public void setup() { + environment = Mockito.mock(Environment.class); + LegacyPropertyFactory.setEnvironment(environment); } @SuppressWarnings({"rawtypes", "unchecked"}) @Test - public void testTcpServerSSL(@Mocked Vertx vertx, @Mocked AsyncResultCallback callback, - @Mocked NetServer netServer) { - new Expectations() { - { - vertx.createNetServer((NetServerOptions) any); - result = netServer; - netServer.connectHandler((Handler) any); - netServer.listen(anyInt, anyString, (Handler) any); - } - }; - URIEndpointObject endpointObject = new URIEndpointObject("highway://127.0.0.1:6663?sslEnabled=true"); + public void testTcpServerNonSSL() { + Vertx vertx = Mockito.mock(Vertx.class); + AsyncResultCallback callback = Mockito.mock(AsyncResultCallback.class); + NetServer netServer = Mockito.mock(NetServer.class); + Mockito.when(vertx.createNetServer()).thenReturn(netServer); + + URIEndpointObject endpointObject = new URIEndpointObject("highway://127.0.0.1:6663"); TcpServer server = new TcpServerForTest(endpointObject); // assert done in Expectations server.init(vertx, "", callback); @@ -96,33 +85,30 @@ public void testTcpServerSSL(@Mocked Vertx vertx, @Mocked AsyncResultCallback callback, - @Mocked NetServer netServer, @Mocked NetSocketImpl netSocket) { + public void testConnectionLimit() { + Vertx vertx = Mockito.mock(Vertx.class); + AsyncResultCallback callback = Mockito.mock(AsyncResultCallback.class); + NetServer netServer = Mockito.mock(NetServer.class); + NetSocketImpl netSocket = Mockito.mock(NetSocketImpl.class); + Mockito.when(vertx.createNetServer(any())).thenReturn(netServer); + DefaultServerEndpointMetric endpointMetric = new DefaultServerEndpointMetric(null); DefaultTcpServerMetrics tcpServerMetrics = new DefaultTcpServerMetrics(endpointMetric); - new MockUp(netServer) { - @Mock - NetServer connectHandler(Handler handler) { - connectHandler = handler; - return netServer; - } - }; - new MockUp(netSocket) { - @Mock - void close() { - netSocketClosed = true; - } - }; - new Expectations() { - { - vertx.createNetServer((NetServerOptions) any); - result = netServer; - netServer.listen(anyInt, anyString, (Handler) any); - netSocket.metrics(); - result = tcpServerMetrics; - } - }; + Mockito.doAnswer((Answer) invocationOnMock -> { + connectHandler = invocationOnMock.getArgument(0); + return netServer; + }).when(netServer).connectHandler(any()); + + Mockito.doAnswer((Answer) invocationOnMock -> { + netSocketClosed = true; + return null; + }).when(netSocket).close(); + Mockito.when(netSocket.metrics()).thenReturn(tcpServerMetrics); + SocketAddress socketAddress = Mockito.mock(SocketAddress.class); + Mockito.when(netSocket.remoteAddress()).thenReturn(socketAddress); + Mockito.when(socketAddress.toString()).thenReturn("127.0.0.1:6663"); + URIEndpointObject endpointObject = new URIEndpointObject("highway://127.0.0.1:6663?sslEnabled=true"); TcpServer server = new TcpServerForTest(endpointObject) { @Override diff --git a/handlers/handler-tracing-zipkin/src/main/java/org/apache/servicecomb/tracing/zipkin/ZipkinTracingFilter.java b/handlers/handler-tracing-zipkin/src/main/java/org/apache/servicecomb/tracing/zipkin/ZipkinTracingFilter.java index b7c62e44223..9f162f6489b 100644 --- a/handlers/handler-tracing-zipkin/src/main/java/org/apache/servicecomb/tracing/zipkin/ZipkinTracingFilter.java +++ b/handlers/handler-tracing-zipkin/src/main/java/org/apache/servicecomb/tracing/zipkin/ZipkinTracingFilter.java @@ -23,8 +23,10 @@ import org.apache.servicecomb.core.Invocation; import org.apache.servicecomb.core.exception.Exceptions; -import org.apache.servicecomb.core.filter.Filter; +import org.apache.servicecomb.core.filter.AbstractFilter; +import org.apache.servicecomb.core.filter.ConsumerFilter; import org.apache.servicecomb.core.filter.FilterNode; +import org.apache.servicecomb.core.filter.ProviderFilter; import org.apache.servicecomb.swagger.invocation.Response; import org.springframework.beans.factory.annotation.Autowired; @@ -32,7 +34,7 @@ import brave.Tracer.SpanInScope; import brave.http.HttpTracing; -public class ZipkinTracingFilter implements Filter { +public class ZipkinTracingFilter extends AbstractFilter implements ConsumerFilter, ProviderFilter { public static final String NAME = "zipkin"; private ZipkinConsumerDelegate consumer; diff --git a/huawei-cloud/dashboard/src/main/java/org/apache/servicecomb/huaweicloud/dashboard/monitor/MetricsMonitorDataProvider.java b/huawei-cloud/dashboard/src/main/java/org/apache/servicecomb/huaweicloud/dashboard/monitor/MetricsMonitorDataProvider.java index 5379c668429..b56c5c2a2ce 100644 --- a/huawei-cloud/dashboard/src/main/java/org/apache/servicecomb/huaweicloud/dashboard/monitor/MetricsMonitorDataProvider.java +++ b/huawei-cloud/dashboard/src/main/java/org/apache/servicecomb/huaweicloud/dashboard/monitor/MetricsMonitorDataProvider.java @@ -20,13 +20,13 @@ import java.util.List; import java.util.Map; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.dashboard.client.model.InterfaceInfo; import org.apache.servicecomb.dashboard.client.model.MonitorData; import org.apache.servicecomb.foundation.common.event.EventManager; import org.apache.servicecomb.foundation.metrics.PolledEvent; import org.apache.servicecomb.huaweicloud.dashboard.monitor.data.MonitorConstant; import org.apache.servicecomb.huaweicloud.dashboard.monitor.model.MonitorDataProvider; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.metrics.core.publish.PublishModelFactory; import org.apache.servicecomb.metrics.core.publish.model.DefaultPublishModel; import org.apache.servicecomb.metrics.core.publish.model.invocation.OperationPerf; @@ -129,7 +129,7 @@ private void extractProviderInfo(DefaultPublishModel model, Map { @@ -165,7 +165,7 @@ private void extractEdgeInfo(DefaultPublishModel model, Map { @@ -201,7 +201,7 @@ private void extractConsumerInfo(DefaultPublishModel model, Map { diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/AbstractInvocationMeter.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/AbstractInvocationMeter.java index 1807575f06d..362ae1dfb25 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/AbstractInvocationMeter.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/AbstractInvocationMeter.java @@ -37,12 +37,6 @@ public abstract class AbstractInvocationMeter extends AbstractPeriodMeter { // prepare time private final SimpleTimer prepareTimer; - // handler request - private final SimpleTimer handlersRequestTimer; - - // handler response - private final SimpleTimer handlersResponseTimer; - // latency distribution private final LatencyDistributionMeter latencyDistributionMeter; @@ -52,10 +46,8 @@ public AbstractInvocationMeter(Id id, MetricsBootstrapConfig metricsBootstrapCon this.id = id; this.metricsBootstrapConfig = metricsBootstrapConfig; latencyDistributionMeter = createLatencyDistribution(MeterInvocationConst.TAG_LATENCY_DISTRIBUTION); - totalTimer = createStageTimer(MeterInvocationConst.STAGE_TOTAL); - prepareTimer = createStageTimer(MeterInvocationConst.STAGE_PREPARE); - handlersRequestTimer = createStageTimer(MeterInvocationConst.STAGE_HANDLERS_REQUEST); - handlersResponseTimer = createStageTimer(MeterInvocationConst.STAGE_HANDLERS_RESPONSE); + totalTimer = createStageTimer(InvocationStageTrace.STAGE_TOTAL); + prepareTimer = createStageTimer(InvocationStageTrace.STAGE_PREPARE); } protected LatencyDistributionMeter createLatencyDistribution(String tagValue) { @@ -78,11 +70,9 @@ protected SimpleTimer createTimer(Id timerId) { public void onInvocationFinish(InvocationFinishEvent event) { InvocationStageTrace stageTrace = event.getInvocation().getInvocationStageTrace(); - latencyDistributionMeter.record((long) stageTrace.calcTotalTime()); - totalTimer.record((long) stageTrace.calcTotalTime()); - handlersRequestTimer.record((long) stageTrace.calcHandlersRequestTime()); - handlersResponseTimer.record((long) stageTrace.calcHandlersResponseTime()); - prepareTimer.record((long) stageTrace.calcInvocationPrepareTime()); + latencyDistributionMeter.record(stageTrace.calcTotal()); + totalTimer.record(stageTrace.calcTotal()); + prepareTimer.record(stageTrace.calcPrepare()); } @Override @@ -96,8 +86,6 @@ public void calcMeasurements(long msNow, long secondInterval) { public void calcMeasurements(List measurements, long msNow, long secondInterval) { latencyDistributionMeter.calcMeasurements(measurements, msNow, secondInterval); totalTimer.calcMeasurements(measurements, msNow, secondInterval); - handlersRequestTimer.calcMeasurements(measurements, msNow, secondInterval); - handlersResponseTimer.calcMeasurements(measurements, msNow, secondInterval); prepareTimer.calcMeasurements(measurements, msNow, secondInterval); } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ConsumerInvocationMeter.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ConsumerInvocationMeter.java index 5701899f6fa..cc575ad3c40 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ConsumerInvocationMeter.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ConsumerInvocationMeter.java @@ -27,29 +27,23 @@ import com.netflix.spectator.api.Measurement; public class ConsumerInvocationMeter extends AbstractInvocationMeter { - private final SimpleTimer clientFiltersRequestTimer; + private final SimpleTimer consumerEncodeRequestTimer; - private final SimpleTimer consumerSendRequestTimer; + private final SimpleTimer consumerDecodeResponseTimer; private final SimpleTimer consumerGetConnectionTimer; - private final SimpleTimer consumerWriteToBufTimer; + private final SimpleTimer consumerSendRequestTimer; private final SimpleTimer consumerWaitResponseTimer; - private final SimpleTimer consumerWakeConsumerTimer; - - private final SimpleTimer clientFiltersResponseTimer; - public ConsumerInvocationMeter(Id id, MetricsBootstrapConfig metricsBootstrapConfig) { super(id, metricsBootstrapConfig); - clientFiltersRequestTimer = createStageTimer(MeterInvocationConst.STAGE_CLIENT_FILTERS_REQUEST); - consumerSendRequestTimer = createStageTimer(MeterInvocationConst.STAGE_CONSUMER_SEND_REQUEST); - consumerGetConnectionTimer = createStageTimer(MeterInvocationConst.STAGE_CONSUMER_GET_CONNECTION); - consumerWriteToBufTimer = createStageTimer(MeterInvocationConst.STAGE_CONSUMER_WRITE_TO_BUF); - consumerWakeConsumerTimer = createStageTimer(MeterInvocationConst.STAGE_CONSUMER_WAKE_CONSUMER); - clientFiltersResponseTimer = createStageTimer(MeterInvocationConst.STAGE_CLIENT_FILTERS_RESPONSE); - consumerWaitResponseTimer = createStageTimer(MeterInvocationConst.STAGE_CONSUMER_WAIT_RESPONSE); + consumerSendRequestTimer = createStageTimer(InvocationStageTrace.STAGE_CONSUMER_SEND); + consumerGetConnectionTimer = createStageTimer(InvocationStageTrace.STAGE_CONSUMER_CONNECTION); + consumerEncodeRequestTimer = createStageTimer(InvocationStageTrace.STAGE_CONSUMER_ENCODE_REQUEST); + consumerDecodeResponseTimer = createStageTimer(InvocationStageTrace.STAGE_CONSUMER_DECODE_RESPONSE); + consumerWaitResponseTimer = createStageTimer(InvocationStageTrace.STAGE_CONSUMER_WAIT); } @Override @@ -57,25 +51,21 @@ public void onInvocationFinish(InvocationFinishEvent event) { super.onInvocationFinish(event); InvocationStageTrace invocationStageTrace = event.getInvocation().getInvocationStageTrace(); - clientFiltersRequestTimer.record((long) invocationStageTrace.calcClientFiltersRequestTime()); - consumerSendRequestTimer.record((long) invocationStageTrace.calcSendRequestTime()); - consumerGetConnectionTimer.record((long) invocationStageTrace.calcGetConnectionTime()); - consumerWriteToBufTimer.record((long) invocationStageTrace.calcWriteToBufferTime()); - consumerWaitResponseTimer.record((long) invocationStageTrace.calcReceiveResponseTime()); - consumerWakeConsumerTimer.record((long) invocationStageTrace.calcWakeConsumer()); - clientFiltersResponseTimer.record((long) invocationStageTrace.calcClientFiltersResponseTime()); + consumerEncodeRequestTimer.record(invocationStageTrace.calcConsumerEncodeRequest()); + consumerSendRequestTimer.record(invocationStageTrace.calcConsumerSendRequest()); + consumerGetConnectionTimer.record(invocationStageTrace.calcConnection()); + consumerWaitResponseTimer.record(invocationStageTrace.calcWait()); + consumerDecodeResponseTimer.record(invocationStageTrace.calcConsumerDecodeResponse()); } @Override public void calcMeasurements(List measurements, long msNow, long secondInterval) { super.calcMeasurements(measurements, msNow, secondInterval); - clientFiltersRequestTimer.calcMeasurements(measurements, msNow, secondInterval); consumerSendRequestTimer.calcMeasurements(measurements, msNow, secondInterval); consumerGetConnectionTimer.calcMeasurements(measurements, msNow, secondInterval); - consumerWriteToBufTimer.calcMeasurements(measurements, msNow, secondInterval); + consumerEncodeRequestTimer.calcMeasurements(measurements, msNow, secondInterval); consumerWaitResponseTimer.calcMeasurements(measurements, msNow, secondInterval); - consumerWakeConsumerTimer.calcMeasurements(measurements, msNow, secondInterval); - clientFiltersResponseTimer.calcMeasurements(measurements, msNow, secondInterval); + consumerDecodeResponseTimer.calcMeasurements(measurements, msNow, secondInterval); } } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/EdgeInvocationMeter.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/EdgeInvocationMeter.java index af168a0fdb5..89284ecd8d0 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/EdgeInvocationMeter.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/EdgeInvocationMeter.java @@ -28,20 +28,17 @@ import com.netflix.spectator.api.Measurement; public class EdgeInvocationMeter extends ConsumerInvocationMeter { - private final SimpleTimer executorQueueTimer; + private final SimpleTimer providerDecodeRequestTimer; - private final SimpleTimer serverFiltersRequestTimer; - - private final SimpleTimer serverFiltersResponseTimer; + private final SimpleTimer providerEncodeResponseTimer; private final SimpleTimer sendResponseTimer; public EdgeInvocationMeter(Id id, MetricsBootstrapConfig metricsBootstrapConfig) { super(id, metricsBootstrapConfig); - executorQueueTimer = createStageTimer(MeterInvocationConst.STAGE_EXECUTOR_QUEUE); - serverFiltersRequestTimer = createStageTimer(MeterInvocationConst.STAGE_SERVER_FILTERS_REQUEST); - serverFiltersResponseTimer = createStageTimer(MeterInvocationConst.STAGE_SERVER_FILTERS_RESPONSE); - sendResponseTimer = createStageTimer(MeterInvocationConst.STAGE_PRODUCER_SEND_RESPONSE); + providerDecodeRequestTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST); + providerEncodeResponseTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE); + sendResponseTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_SEND); } @Override @@ -49,19 +46,17 @@ public void onInvocationFinish(InvocationFinishEvent event) { super.onInvocationFinish(event); InvocationStageTrace invocationStageTrace = event.getInvocation().getInvocationStageTrace(); - executorQueueTimer.record((long) invocationStageTrace.calcThreadPoolQueueTime()); - serverFiltersRequestTimer.record((long) invocationStageTrace.calcServerFiltersRequestTime()); - serverFiltersResponseTimer.record((long) invocationStageTrace.calcServerFiltersResponseTime()); - sendResponseTimer.record((long) invocationStageTrace.calcSendResponseTime()); + providerDecodeRequestTimer.record(invocationStageTrace.calcProviderDecodeRequest()); + providerEncodeResponseTimer.record(invocationStageTrace.calcProviderEncodeResponse()); + sendResponseTimer.record(invocationStageTrace.calcProviderSendResponse()); } @Override public void calcMeasurements(List measurements, long msNow, long secondInterval) { super.calcMeasurements(measurements, msNow, secondInterval); - executorQueueTimer.calcMeasurements(measurements, msNow, secondInterval); - serverFiltersRequestTimer.calcMeasurements(measurements, msNow, secondInterval); - serverFiltersResponseTimer.calcMeasurements(measurements, msNow, secondInterval); + providerDecodeRequestTimer.calcMeasurements(measurements, msNow, secondInterval); + providerEncodeResponseTimer.calcMeasurements(measurements, msNow, secondInterval); sendResponseTimer.calcMeasurements(measurements, msNow, secondInterval); } } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/MeterInvocationConst.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/MeterInvocationConst.java index 94cec809a73..ab0ab0b34f0 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/MeterInvocationConst.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/MeterInvocationConst.java @@ -38,40 +38,5 @@ public interface MeterInvocationConst { String TAG_STATISTIC = Statistic.count.key(); - String STAGE_TOTAL = "total"; - - String STAGE_PREPARE = "prepare"; - - String STAGE_EXECUTOR_QUEUE = "queue"; - - String STAGE_EXECUTION = "execution"; - String EDGE_INVOCATION_NAME = "EDGE"; - - String STAGE_HANDLERS_REQUEST = "handlers_request"; - - String STAGE_HANDLERS_RESPONSE = "handlers_response"; - - // producer only - String STAGE_SERVER_FILTERS_REQUEST = "server_filters_request"; - - String STAGE_SERVER_FILTERS_RESPONSE = "server_filters_response"; - - String STAGE_PRODUCER_SEND_RESPONSE = "producer_send_response"; - - //consumer only - - String STAGE_CLIENT_FILTERS_REQUEST = "client_filters_request"; - - String STAGE_CONSUMER_SEND_REQUEST = "consumer_send_request"; - - String STAGE_CONSUMER_GET_CONNECTION = "consumer_get_connection"; - - String STAGE_CONSUMER_WRITE_TO_BUF = "consumer_write_to_buf"; - - String STAGE_CONSUMER_WAIT_RESPONSE = "consumer_wait_response"; - - String STAGE_CONSUMER_WAKE_CONSUMER = "consumer_wake_consumer"; - - String STAGE_CLIENT_FILTERS_RESPONSE = "client_filters_response"; } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ProducerInvocationMeter.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ProducerInvocationMeter.java index 1decb98d0ba..f5727613d5e 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ProducerInvocationMeter.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/meter/invocation/ProducerInvocationMeter.java @@ -31,20 +31,20 @@ public class ProducerInvocationMeter extends AbstractInvocationMeter { private final SimpleTimer executionTimer; - private final SimpleTimer serverFiltersRequestTimer; + private final SimpleTimer providerDecodeRequestTimer; - private final SimpleTimer serverFiltersResponseTimer; + private final SimpleTimer providerEncodeResponseTimer; private final SimpleTimer sendResponseTimer; public ProducerInvocationMeter(Id id, MetricsBootstrapConfig metricsBootstrapConfig) { super(id, metricsBootstrapConfig); - executorQueueTimer = createStageTimer(MeterInvocationConst.STAGE_EXECUTOR_QUEUE); - executionTimer = createStageTimer(MeterInvocationConst.STAGE_EXECUTION); - serverFiltersRequestTimer = createStageTimer(MeterInvocationConst.STAGE_SERVER_FILTERS_REQUEST); - serverFiltersResponseTimer = createStageTimer(MeterInvocationConst.STAGE_SERVER_FILTERS_RESPONSE); - sendResponseTimer = createStageTimer(MeterInvocationConst.STAGE_PRODUCER_SEND_RESPONSE); + executorQueueTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_QUEUE); + executionTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_BUSINESS); + providerDecodeRequestTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST); + providerEncodeResponseTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE); + sendResponseTimer = createStageTimer(InvocationStageTrace.STAGE_PROVIDER_SEND); } @Override @@ -52,11 +52,11 @@ public void onInvocationFinish(InvocationFinishEvent event) { super.onInvocationFinish(event); InvocationStageTrace invocationStageTrace = event.getInvocation().getInvocationStageTrace(); - executorQueueTimer.record((long) invocationStageTrace.calcThreadPoolQueueTime()); - executionTimer.record((long) invocationStageTrace.calcBusinessTime()); - serverFiltersRequestTimer.record((long) invocationStageTrace.calcServerFiltersRequestTime()); - serverFiltersResponseTimer.record((long) invocationStageTrace.calcServerFiltersResponseTime()); - sendResponseTimer.record((long) invocationStageTrace.calcSendResponseTime()); + executorQueueTimer.record(invocationStageTrace.calcQueue()); + executionTimer.record(invocationStageTrace.calcBusinessExecute()); + providerDecodeRequestTimer.record(invocationStageTrace.calcProviderDecodeRequest()); + providerEncodeResponseTimer.record(invocationStageTrace.calcProviderEncodeResponse()); + sendResponseTimer.record(invocationStageTrace.calcProviderSendResponse()); } @Override @@ -65,8 +65,8 @@ public void calcMeasurements(List measurements, long msNow, long se executorQueueTimer.calcMeasurements(measurements, msNow, secondInterval); executionTimer.calcMeasurements(measurements, msNow, secondInterval); - serverFiltersRequestTimer.calcMeasurements(measurements, msNow, secondInterval); - serverFiltersResponseTimer.calcMeasurements(measurements, msNow, secondInterval); + providerDecodeRequestTimer.calcMeasurements(measurements, msNow, secondInterval); + providerEncodeResponseTimer.calcMeasurements(measurements, msNow, secondInterval); sendResponseTimer.calcMeasurements(measurements, msNow, secondInterval); } } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/DefaultLogPublisher.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/DefaultLogPublisher.java index 47a3a7aefd6..b9d20995bce 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/DefaultLogPublisher.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/DefaultLogPublisher.java @@ -22,6 +22,7 @@ import java.util.Map; import java.util.Map.Entry; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.foundation.common.net.NetUtils; import org.apache.servicecomb.foundation.metrics.MetricsBootstrapConfig; import org.apache.servicecomb.foundation.metrics.MetricsInitializer; @@ -33,7 +34,6 @@ import org.apache.servicecomb.foundation.metrics.registry.GlobalRegistry; import org.apache.servicecomb.foundation.vertx.VertxUtils; import org.apache.servicecomb.metrics.core.VertxMetersInitializer; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.metrics.core.meter.os.NetMeter; import org.apache.servicecomb.metrics.core.meter.os.OsMeter; import org.apache.servicecomb.metrics.core.publish.model.DefaultPublishModel; @@ -55,7 +55,7 @@ import io.vertx.core.Vertx; public class DefaultLogPublisher implements MetricsInitializer { - private static final Logger LOGGER = LoggerFactory.getLogger(DefaultLogPublisher.class); + private static final Logger LOGGER = LoggerFactory.getLogger("scb-metrics"); public static final String ENABLED = "servicecomb.metrics.publisher.defaultLog.enabled"; @@ -68,19 +68,17 @@ public class DefaultLogPublisher implements MetricsInitializer { //details private static final String PRODUCER_DETAILS_FORMAT = "" - + " prepare: %-18s queue : %-18s filtersReq : %-18s handlersReq: %s\n" - + " execute: %-18s handlersResp: %-18s filtersResp: %-18s sendResp : %s\n"; + + " prepare: %-18s decode-request : %-18s queue : %-18s business-execute: %s\n" + + " encode-response: %-18s send: %-18s\n"; private static final String CONSUMER_DETAILS_FORMAT = "" - + " prepare : %-18s handlersReq : %-18s cFiltersReq: %-18s sendReq : %s\n" - + " getConnect : %-18s writeBuf : %-18s waitResp : %-18s wakeConsumer: %s\n" - + " cFiltersResp: %-18s handlersResp: %s\n"; + + " prepare : %-18s connection : %-18s encode-request: %-18s send : %s\n" + + " wait : %-18s decode-response : %-18s\n"; private static final String EDGE_DETAILS_FORMAT = "" - + " prepare : %-18s queue : %-18s sFiltersReq : %-18s handlersReq : %s\n" - + " cFiltersReq : %-18s sendReq : %-18s getConnect : %-18s writeBuf : %s\n" - + " waitResp : %-18s wakeConsumer: %-18s cFiltersResp: %-18s handlersResp: %s\n" - + " sFiltersResp: %-18s sendResp : %s\n"; + + " prepare : %-18s provider-decode : %-18s connection : %-18s consumer-encode : %s\n" + + " consumer-send : %-18s wait : %-18s consumer-decode : %-18s provider-encode : %s\n" + + " provider-send : %-18s\n"; private LatencyDistributionConfig latencyDistributionConfig; @@ -316,7 +314,7 @@ private StringBuilder printSamplePerf(OperationPerfGroup perfGroup) { boolean firstLine = true; for (int i = 0; i < perfGroup.getOperationPerfs().size(); i++) { OperationPerf operationPerf = perfGroup.getOperationPerfs().get(i); - PerfInfo stageTotal = operationPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo stageTotal = operationPerf.findStage(InvocationStageTrace.STAGE_TOTAL); if (Double.compare(0D, stageTotal.getTps()) == 0) { continue; } @@ -336,7 +334,7 @@ private StringBuilder printSamplePerf(OperationPerfGroup perfGroup) { } } OperationPerf summaryOperation = perfGroup.getSummary(); - PerfInfo stageSummaryTotal = summaryOperation.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo stageSummaryTotal = summaryOperation.findStage(InvocationStageTrace.STAGE_TOTAL); //print summary sb.append(String.format(SIMPLE_FORMAT, stageSummaryTotal.getTps(), getDetailsFromPerf(stageSummaryTotal), @@ -357,32 +355,28 @@ private StringBuilder printProducerDetailsPerf(OperationPerfGroup perfGroup) { .append(".") .append(perfGroup.getStatus()) .append(":\n"); - PerfInfo prepare, queue, filtersReq, handlersReq, execute, handlersResp, filtersResp, sendResp; + PerfInfo prepare, queue, providerDecode, providerEncode, execute, sendResp; for (OperationPerf operationPerf : perfGroup.getOperationPerfs()) { - PerfInfo stageTotal = operationPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo stageTotal = operationPerf.findStage(InvocationStageTrace.STAGE_TOTAL); if (Double.compare(0D, stageTotal.getTps()) == 0) { continue; } - prepare = operationPerf.findStage(MeterInvocationConst.STAGE_PREPARE); - queue = operationPerf.findStage(MeterInvocationConst.STAGE_EXECUTOR_QUEUE); - filtersReq = operationPerf.findStage(MeterInvocationConst.STAGE_SERVER_FILTERS_REQUEST); - handlersReq = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_REQUEST); - execute = operationPerf.findStage(MeterInvocationConst.STAGE_EXECUTION); - handlersResp = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_RESPONSE); - filtersResp = operationPerf.findStage(MeterInvocationConst.STAGE_SERVER_FILTERS_RESPONSE); - sendResp = operationPerf.findStage(MeterInvocationConst.STAGE_PRODUCER_SEND_RESPONSE); + prepare = operationPerf.findStage(InvocationStageTrace.STAGE_PREPARE); + queue = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_QUEUE); + providerDecode = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST); + providerEncode = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE); + execute = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_BUSINESS); + sendResp = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_SEND); sb.append(" ") .append(operationPerf.getOperation()) .append(":\n") .append(String.format(PRODUCER_DETAILS_FORMAT, getDetailsFromPerf(prepare), + getDetailsFromPerf(providerDecode), getDetailsFromPerf(queue), - getDetailsFromPerf(filtersReq), - getDetailsFromPerf(handlersReq), getDetailsFromPerf(execute), - getDetailsFromPerf(handlersResp), - getDetailsFromPerf(filtersResp), + getDetailsFromPerf(providerEncode), getDetailsFromPerf(sendResp) )); } @@ -399,38 +393,30 @@ private StringBuilder printConsumerDetailsPerf(OperationPerfGroup perfGroup) { .append(perfGroup.getStatus()) .append(":\n"); - PerfInfo prepare, handlersReq, clientFiltersReq, sendReq, getConnect, writeBuf, - waitResp, wakeConsumer, clientFiltersResp, handlersResp; + PerfInfo prepare, encodeRequest, decodeResponse, sendReq, getConnect, + waitResp; for (OperationPerf operationPerf : perfGroup.getOperationPerfs()) { - PerfInfo stageTotal = operationPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo stageTotal = operationPerf.findStage(InvocationStageTrace.STAGE_TOTAL); if (Double.compare(0D, stageTotal.getTps()) == 0) { continue; } - prepare = operationPerf.findStage(MeterInvocationConst.STAGE_PREPARE); - handlersReq = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_REQUEST); - clientFiltersReq = operationPerf.findStage(MeterInvocationConst.STAGE_CLIENT_FILTERS_REQUEST); - sendReq = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_SEND_REQUEST); - getConnect = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_GET_CONNECTION); - writeBuf = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WRITE_TO_BUF); - waitResp = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WAIT_RESPONSE); - wakeConsumer = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WAKE_CONSUMER); - clientFiltersResp = operationPerf.findStage(MeterInvocationConst.STAGE_CLIENT_FILTERS_RESPONSE); - handlersResp = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_RESPONSE); + prepare = operationPerf.findStage(InvocationStageTrace.STAGE_PREPARE); + encodeRequest = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_ENCODE_REQUEST); + decodeResponse = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_DECODE_RESPONSE); + sendReq = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_SEND); + getConnect = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_CONNECTION); + waitResp = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_WAIT); sb.append(" ") .append(operationPerf.getOperation()) .append(":\n") .append(String.format(CONSUMER_DETAILS_FORMAT, getDetailsFromPerf(prepare), - getDetailsFromPerf(handlersReq), - getDetailsFromPerf(clientFiltersReq), - getDetailsFromPerf(sendReq), getDetailsFromPerf(getConnect), - getDetailsFromPerf(writeBuf), + getDetailsFromPerf(encodeRequest), + getDetailsFromPerf(sendReq), getDetailsFromPerf(waitResp), - getDetailsFromPerf(wakeConsumer), - getDetailsFromPerf(clientFiltersResp), - getDetailsFromPerf(handlersResp) + getDetailsFromPerf(decodeResponse) )); } @@ -446,45 +432,36 @@ private StringBuilder printEdgeDetailsPerf(OperationPerfGroup perfGroup) { .append(perfGroup.getStatus()) .append(":\n"); - PerfInfo prepare, queue, serverFiltersReq, handlersReq, clientFiltersReq, sendReq, getConnect, writeBuf, - waitResp, wakeConsumer, clientFiltersResp, handlersResp, serverFiltersResp, sendResp; + PerfInfo prepare, connection, decodeProviderRequest, encodeProviderResponse, + encodeConsumerRequest, decodeConsumerResponse, sendReq, getConnect, + waitResp, sendResp; for (OperationPerf operationPerf : perfGroup.getOperationPerfs()) { - PerfInfo stageTotal = operationPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo stageTotal = operationPerf.findStage(InvocationStageTrace.STAGE_TOTAL); if (Double.compare(0D, stageTotal.getTps()) == 0) { continue; } - prepare = operationPerf.findStage(MeterInvocationConst.STAGE_PREPARE); - queue = operationPerf.findStage(MeterInvocationConst.STAGE_EXECUTOR_QUEUE); - serverFiltersReq = operationPerf.findStage(MeterInvocationConst.STAGE_SERVER_FILTERS_REQUEST); - handlersReq = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_REQUEST); - clientFiltersReq = operationPerf.findStage(MeterInvocationConst.STAGE_CLIENT_FILTERS_REQUEST); - sendReq = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_SEND_REQUEST); - getConnect = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_GET_CONNECTION); - writeBuf = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WRITE_TO_BUF); - waitResp = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WAIT_RESPONSE); - wakeConsumer = operationPerf.findStage(MeterInvocationConst.STAGE_CONSUMER_WAKE_CONSUMER); - clientFiltersResp = operationPerf.findStage(MeterInvocationConst.STAGE_CLIENT_FILTERS_RESPONSE); - handlersResp = operationPerf.findStage(MeterInvocationConst.STAGE_HANDLERS_RESPONSE); - serverFiltersResp = operationPerf.findStage(MeterInvocationConst.STAGE_SERVER_FILTERS_RESPONSE); - sendResp = operationPerf.findStage(MeterInvocationConst.STAGE_PRODUCER_SEND_RESPONSE); + prepare = operationPerf.findStage(InvocationStageTrace.STAGE_PREPARE); + connection = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_CONNECTION); + decodeProviderRequest = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST); + encodeProviderResponse = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE); + encodeConsumerRequest = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_ENCODE_REQUEST); + sendReq = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_SEND); + decodeConsumerResponse = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_DECODE_RESPONSE); + waitResp = operationPerf.findStage(InvocationStageTrace.STAGE_CONSUMER_WAIT); + sendResp = operationPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_SEND); sb.append(" ") .append(operationPerf.getOperation()) .append(":\n") .append(String.format(EDGE_DETAILS_FORMAT, getDetailsFromPerf(prepare), - getDetailsFromPerf(queue), - getDetailsFromPerf(serverFiltersReq), - getDetailsFromPerf(handlersReq), - getDetailsFromPerf(clientFiltersReq), + getDetailsFromPerf(decodeProviderRequest), + getDetailsFromPerf(connection), + getDetailsFromPerf(encodeConsumerRequest), getDetailsFromPerf(sendReq), - getDetailsFromPerf(getConnect), - getDetailsFromPerf(writeBuf), getDetailsFromPerf(waitResp), - getDetailsFromPerf(wakeConsumer), - getDetailsFromPerf(clientFiltersResp), - getDetailsFromPerf(handlersResp), - getDetailsFromPerf(serverFiltersResp), + getDetailsFromPerf(decodeConsumerResponse), + getDetailsFromPerf(encodeProviderResponse), getDetailsFromPerf(sendResp) )); } diff --git a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java index a72f56250a2..679e544575e 100644 --- a/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java +++ b/metrics/metrics-core/src/main/java/org/apache/servicecomb/metrics/core/publish/SlowInvocationLogger.java @@ -16,6 +16,20 @@ */ package org.apache.servicecomb.metrics.core.publish; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_CONSUMER_CONNECTION; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_CONSUMER_DECODE_RESPONSE; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_CONSUMER_ENCODE_REQUEST; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_CONSUMER_SEND; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_CONSUMER_WAIT; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PREPARE; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PROVIDER_BUSINESS; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PROVIDER_QUEUE; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_PROVIDER_SEND; +import static org.apache.servicecomb.core.invocation.InvocationStageTrace.STAGE_TOTAL; + +import java.util.Map.Entry; import java.util.concurrent.TimeUnit; import org.apache.servicecomb.common.rest.RestConst; @@ -26,6 +40,7 @@ import org.apache.servicecomb.core.definition.OperationConfig; import org.apache.servicecomb.core.event.InvocationFinishEvent; import org.apache.servicecomb.core.invocation.InvocationStageTrace; +import org.apache.servicecomb.core.invocation.InvocationStageTrace.Stage; import org.apache.servicecomb.foundation.vertx.http.HttpServletRequestEx; import org.apache.servicecomb.swagger.invocation.Response; import org.slf4j.Logger; @@ -35,7 +50,7 @@ import com.google.common.eventbus.Subscribe; public class SlowInvocationLogger { - private static final Logger LOGGER = LoggerFactory.getLogger(SlowInvocationLogger.class); + private static final Logger LOGGER = LoggerFactory.getLogger("scb-slow"); public SlowInvocationLogger(SCBEngine scbEngine) { scbEngine.getEventBus().register(this); @@ -47,12 +62,12 @@ public void onInvocationFinish(InvocationFinishEvent event) { Invocation invocation = event.getInvocation(); OperationConfig operationConfig = invocation.getOperationMeta().getConfig(); if (!operationConfig.isSlowInvocationEnabled() || - invocation.getInvocationStageTrace().calcTotalTime() < operationConfig.getNanoSlowInvocation()) { + invocation.getInvocationStageTrace().calcTotal() < operationConfig.getNanoSlowInvocation()) { return; } if (!invocation.isConsumer()) { - logSlowProducer(invocation, event.getResponse(), operationConfig); + logSlowProvider(invocation, event.getResponse(), operationConfig); return; } @@ -64,142 +79,115 @@ public void onInvocationFinish(InvocationFinishEvent event) { logSlowConsumer(invocation, event.getResponse(), operationConfig); } - private String collectClientAddress(Invocation invocation) { + private static String collectClientAddress(Invocation invocation) { HttpServletRequestEx requestEx = invocation.getRequestEx(); return requestEx == null ? "unknown" : requestEx.getRemoteAddr() + ":" + requestEx.getRemotePort(); } - private String collectTargetAddress(Invocation invocation) { + private static String collectTargetAddress(Invocation invocation) { Endpoint endpoint = invocation.getEndpoint(); return endpoint == null ? "unknown" : endpoint.getEndpoint(); } - private String formatTime(double doubleNano) { - long micros = TimeUnit.NANOSECONDS.toMicros((long) doubleNano); + private static String formatTime(long doubleNano) { + long micros = TimeUnit.NANOSECONDS.toMicros(doubleNano); return micros / 1000 + "." + micros % 1000; } - private void logSlowProducer(Invocation invocation, Response response, OperationConfig operationConfig) { + private static void logSlowProvider(Invocation invocation, Response response, OperationConfig operationConfig) { RestOperationMeta restOperationMeta = invocation.getOperationMeta().getExtData(RestConst.SWAGGER_REST_OPERATION); InvocationStageTrace stageTrace = invocation.getInvocationStageTrace(); - invocation.getTraceIdLogger().warn(LOGGER, "" - + "slow({} ms) invocation, {}:\n" - + " http method: {}\n" - + " url : {}\n" - + " client : {}\n" - + " status code: {}\n" - + " total : {} ms\n" - + " prepare : {} ms\n" - + " threadPoolQueue : {} ms\n" - + " server filters request : {} ms\n" - + " handlers request : {} ms\n" - + " business execute : {} ms\n" - + " handlers response : {} ms\n" - + " server filters response: {} ms\n" - + " send response : {} ms", - operationConfig.getMsSlowInvocation(), - invocation.getInvocationQualifiedName(), - restOperationMeta.getHttpMethod(), - restOperationMeta.getAbsolutePath(), - collectClientAddress(invocation), - response.getStatusCode(), - formatTime(stageTrace.calcTotalTime()), - formatTime(stageTrace.calcInvocationPrepareTime()), - formatTime(stageTrace.calcThreadPoolQueueTime()), - formatTime(stageTrace.calcServerFiltersRequestTime()), - formatTime(stageTrace.calcHandlersRequestTime()), - formatTime(stageTrace.calcBusinessTime()), - formatTime(stageTrace.calcHandlersResponseTime()), - formatTime(stageTrace.calcServerFiltersResponseTime()), - formatTime(stageTrace.calcSendResponseTime()) - ); + StringBuilder sb = new StringBuilder(); + sb.append("Slow Provider invocation [").append(invocation.getInvocationQualifiedName()) + .append("](").append(operationConfig.getMsSlowInvocation()).append(" ms") + .append(")[").append(invocation.getTraceId()).append("]\n") + .append(formatPair(" ", "http method", restOperationMeta.getHttpMethod())) + .append(formatPair(" ", "url", restOperationMeta.getAbsolutePath())) + .append(formatPair(" ", "endpoint", collectClientAddress(invocation))) + .append(formatPair(" ", "status code", response.getStatusCode())) + + .append(formatPair(" ", STAGE_TOTAL, stageTrace.calcTotal())) + .append(formatPair(" ", STAGE_PREPARE, stageTrace.calcPrepare())) + .append(formatPair(" ", STAGE_PROVIDER_DECODE_REQUEST, stageTrace.calcProviderDecodeRequest())) + .append(formatPair(" ", STAGE_PROVIDER_QUEUE, stageTrace.calcQueue())) + .append(formatPair(" ", STAGE_PROVIDER_BUSINESS, stageTrace.calcBusinessExecute())) + .append(formatPair(" ", STAGE_PROVIDER_ENCODE_RESPONSE, stageTrace.calcProviderEncodeResponse())) + .append(formatPair(" ", STAGE_PROVIDER_SEND, stageTrace.calcProviderSendResponse())); + + for (Entry stage : stageTrace.getStages().entrySet()) { + sb.append(formatPair(" ", "Filter-" + stage.getKey(), + InvocationStageTrace.calc(stage.getValue().getEndTime(), + stage.getValue().getBeginTime()))); + } + + LOGGER.warn(sb.toString()); + } + + protected static String formatPair(String padding, String name, String value) { + return String.format("%-20s: %20s\n", padding + name, value); } - private void logSlowConsumer(Invocation invocation, Response response, OperationConfig operationConfig) { + protected static String formatPair(String padding, String name, long time) { + return String.format("%-20s: %8sms\n", padding + name, formatTime(time)); + } + + private static void logSlowConsumer(Invocation invocation, Response response, OperationConfig operationConfig) { RestOperationMeta restOperationMeta = invocation.getOperationMeta().getExtData(RestConst.SWAGGER_REST_OPERATION); InvocationStageTrace stageTrace = invocation.getInvocationStageTrace(); - invocation.getTraceIdLogger().warn(LOGGER, "" - + "slow({} ms) invocation, {}:\n" - + " http method: {}\n" - + " url : {}\n" - + " server : {}\n" - + " status code: {}\n" - + " total : {} ms\n" - + " prepare : {} ms\n" - + " handlers request : {} ms\n" - + " client filters request : {} ms\n" - + " send request : {} ms\n" - + " get connection : {} ms\n" - + " write to buf : {} ms\n" - + " wait response : {} ms\n" - + " wake consumer : {} ms\n" - + " client filters response: {} ms\n" - + " handlers response : {} ms", - operationConfig.getMsSlowInvocation(), - invocation.getInvocationQualifiedName(), - restOperationMeta.getHttpMethod(), - restOperationMeta.getAbsolutePath(), - collectTargetAddress(invocation), - response.getStatusCode(), - formatTime(stageTrace.calcTotalTime()), - formatTime(stageTrace.calcInvocationPrepareTime()), - formatTime(stageTrace.calcHandlersRequestTime()), - formatTime(stageTrace.calcClientFiltersRequestTime()), - formatTime(stageTrace.calcSendRequestTime()), - formatTime(stageTrace.calcGetConnectionTime()), - formatTime(stageTrace.calcWriteToBufferTime()), - formatTime(stageTrace.calcReceiveResponseTime()), - formatTime(stageTrace.calcWakeConsumer()), - formatTime(stageTrace.calcClientFiltersResponseTime()), - formatTime(stageTrace.calcHandlersResponseTime()) - ); + StringBuilder sb = new StringBuilder(); + sb.append("Slow Consumer invocation [").append(invocation.getInvocationQualifiedName()) + .append("](").append(operationConfig.getMsSlowInvocation()).append(" ms") + .append(")[").append(invocation.getTraceId()).append("]\n") + .append(formatPair(" ", "http method", restOperationMeta.getHttpMethod())) + .append(formatPair(" ", "url", restOperationMeta.getAbsolutePath())) + .append(formatPair(" ", "endpoint", collectTargetAddress(invocation))) + .append(formatPair(" ", "status code", response.getStatusCode())) + .append(formatPair(" ", STAGE_TOTAL, stageTrace.calcTotal())) + .append(formatPair(" ", STAGE_PREPARE, stageTrace.calcPrepare())) + .append(formatPair(" ", STAGE_CONSUMER_CONNECTION, stageTrace.calcConnection())) + .append(formatPair(" ", STAGE_CONSUMER_ENCODE_REQUEST, stageTrace.calcConsumerEncodeRequest())) + .append(formatPair(" ", STAGE_CONSUMER_SEND, stageTrace.calcConsumerSendRequest())) + .append(formatPair(" ", STAGE_CONSUMER_WAIT, stageTrace.calcWait())) + .append(formatPair(" ", STAGE_CONSUMER_DECODE_RESPONSE, stageTrace.calcConsumerDecodeResponse())); + + for (Entry stage : stageTrace.getStages().entrySet()) { + sb.append(formatPair(" ", "Filter-" + stage.getKey(), + InvocationStageTrace.calc(stage.getValue().getEndTime(), + stage.getValue().getBeginTime()))); + } + + LOGGER.warn(sb.toString()); } - private void logSlowEdge(Invocation invocation, Response response, OperationConfig operationConfig) { + private static void logSlowEdge(Invocation invocation, Response response, OperationConfig operationConfig) { RestOperationMeta restOperationMeta = invocation.getOperationMeta().getExtData(RestConst.SWAGGER_REST_OPERATION); InvocationStageTrace stageTrace = invocation.getInvocationStageTrace(); - invocation.getTraceIdLogger().warn(LOGGER, "" - + "slow({} ms) invocation, {}:\n" - + " http method: {}\n" - + " url : {}\n" - + " server : {}\n" - + " status code: {}\n" - + " total : {} ms\n" - + " prepare : {} ms\n" - + " threadPoolQueue : {} ms\n" - + " server filters request : {} ms\n" - + " handlers request : {} ms\n" - + " client filters request : {} ms\n" - + " send request : {} ms\n" - + " get connection : {} ms\n" - + " write to buf : {} ms\n" - + " wait response : {} ms\n" - + " wake consumer : {} ms\n" - + " client filters response: {} ms\n" - + " handlers response : {} ms\n" - + " server filters response: {} ms\n" - + " send response : {} ms", - operationConfig.getMsSlowInvocation(), - invocation.getInvocationQualifiedName(), - restOperationMeta.getHttpMethod(), - restOperationMeta.getAbsolutePath(), - collectTargetAddress(invocation), - response.getStatusCode(), - formatTime(stageTrace.calcTotalTime()), - formatTime(stageTrace.calcInvocationPrepareTime()), - formatTime(stageTrace.calcThreadPoolQueueTime()), - formatTime(stageTrace.calcServerFiltersRequestTime()), - formatTime(stageTrace.calcHandlersRequestTime()), - formatTime(stageTrace.calcClientFiltersRequestTime()), - formatTime(stageTrace.calcSendRequestTime()), - formatTime(stageTrace.calcGetConnectionTime()), - formatTime(stageTrace.calcWriteToBufferTime()), - formatTime(stageTrace.calcReceiveResponseTime()), - formatTime(stageTrace.calcWakeConsumer()), - formatTime(stageTrace.calcClientFiltersResponseTime()), - formatTime(stageTrace.calcHandlersResponseTime()), - formatTime(stageTrace.calcServerFiltersResponseTime()), - formatTime(stageTrace.calcSendResponseTime()) - ); + StringBuilder sb = new StringBuilder(); + sb.append("Slow Edge invocation [").append(invocation.getInvocationQualifiedName()) + .append("](").append(operationConfig.getMsSlowInvocation()).append(" ms") + .append(")[").append(invocation.getTraceId()).append("]\n") + .append(formatPair(" ", "http method", restOperationMeta.getHttpMethod())) + .append(formatPair(" ", "url", restOperationMeta.getAbsolutePath())) + .append(formatPair(" ", "endpoint", collectTargetAddress(invocation))) + .append(formatPair(" ", "status code", response.getStatusCode())) + .append(formatPair(" ", STAGE_TOTAL, stageTrace.calcTotal())) + .append(formatPair(" ", STAGE_PREPARE, stageTrace.calcPrepare())) + .append(formatPair(" ", STAGE_PROVIDER_DECODE_REQUEST, stageTrace.calcProviderDecodeRequest())) + .append(formatPair(" ", STAGE_CONSUMER_CONNECTION, stageTrace.calcConnection())) + .append(formatPair(" ", STAGE_CONSUMER_ENCODE_REQUEST, stageTrace.calcConsumerEncodeRequest())) + .append(formatPair(" ", STAGE_CONSUMER_SEND, stageTrace.calcConsumerSendRequest())) + .append(formatPair(" ", STAGE_CONSUMER_WAIT, stageTrace.calcWait())) + .append(formatPair(" ", STAGE_CONSUMER_DECODE_RESPONSE, stageTrace.calcConsumerDecodeResponse())) + .append(formatPair(" ", STAGE_PROVIDER_ENCODE_RESPONSE, stageTrace.calcProviderEncodeResponse())) + .append(formatPair(" ", STAGE_PROVIDER_SEND, stageTrace.calcProviderSendResponse())) + ; + + for (Entry stage : stageTrace.getStages().entrySet()) { + sb.append(formatPair(" ", "Filter-" + stage.getKey(), + InvocationStageTrace.calc(stage.getValue().getEndTime(), + stage.getValue().getBeginTime()))); + } + + LOGGER.warn(sb.toString()); } } diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/TestInvocationMetersInitializer.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/TestInvocationMetersInitializer.java index 54f491242bc..c2548774617 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/TestInvocationMetersInitializer.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/TestInvocationMetersInitializer.java @@ -31,6 +31,7 @@ import org.apache.servicecomb.foundation.metrics.registry.GlobalRegistry; import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.swagger.invocation.InvocationType; +import org.junit.Assert; import org.junit.Before; import org.junit.Test; import org.mockito.Mockito; @@ -82,27 +83,19 @@ public void consumerInvocation(@Mocked InvocationFinishEvent event) { result = CoreConst.RESTFUL; invocation.getMicroserviceQualifiedName(); result = "m.s.o"; - invocation.getInvocationStageTrace().calcTotalTime(); + invocation.getInvocationStageTrace().calcTotal(); result = 9; - invocation.getInvocationStageTrace().calcClientFiltersRequestTime(); + invocation.getInvocationStageTrace().calcPrepare(); result = 9; - invocation.getInvocationStageTrace().calcSendRequestTime(); + invocation.getInvocationStageTrace().calcConnection(); result = 9; - invocation.getInvocationStageTrace().calcGetConnectionTime(); + invocation.getInvocationStageTrace().calcConsumerEncodeRequest(); result = 4; - invocation.getInvocationStageTrace().calcWriteToBufferTime(); + invocation.getInvocationStageTrace().calcConsumerSendRequest(); result = 5; - invocation.getInvocationStageTrace().calcWakeConsumer(); + invocation.getInvocationStageTrace().calcWait(); result = 9; - invocation.getInvocationStageTrace().calcReceiveResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcClientFiltersResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcInvocationPrepareTime(); - result = 9; - invocation.getInvocationStageTrace().calcHandlersRequestTime(); - result = 9; - invocation.getInvocationStageTrace().calcHandlersResponseTime(); + invocation.getInvocationStageTrace().calcConsumerDecodeResponse(); result = 9; event.getInvocation(); @@ -118,6 +111,7 @@ public void consumerInvocation(@Mocked InvocationFinishEvent event) { MeasurementTree tree = new MeasurementTree(); tree.from(registry.iterator(), new MeasurementGroupConfig(MeterInvocationConst.INVOCATION_NAME)); List measurements = tree.findChild(MeterInvocationConst.INVOCATION_NAME).getMeasurements(); + Assert.assertEquals(21, measurements.size()); AssertUtil.assertMeasure(measurements, 0, "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=total:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 1, @@ -125,65 +119,41 @@ public void consumerInvocation(@Mocked InvocationFinishEvent event) { AssertUtil.assertMeasure(measurements, 2, "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=total:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, 3, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 4, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, 5, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, 6, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-send:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 7, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-send:statistic=totalTime:status=0:transport=rest:type=stage,0,1.0E-8"); AssertUtil.assertMeasure(measurements, 8, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=handlers_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-send:statistic=max:status=0:transport=rest:type=stage,0,5.0E-9"); AssertUtil.assertMeasure(measurements, 9, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=connection:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 10, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=connection:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, 11, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=prepare:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=connection:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, 12, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-encode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 13, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-encode:statistic=totalTime:status=0:transport=rest:type=stage,0,8.0E-9"); AssertUtil.assertMeasure(measurements, 14, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-encode:statistic=max:status=0:transport=rest:type=stage,0,4.0E-9"); AssertUtil.assertMeasure(measurements, 15, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_send_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=wait:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 16, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_send_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=wait:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, 17, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_send_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=wait:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, 18, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_get_connection:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-decode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, 19, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_get_connection:statistic=totalTime:status=0:transport=rest:type=stage,0,8.0E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-decode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, 20, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_get_connection:statistic=max:status=0:transport=rest:type=stage,0,4.0E-9"); - AssertUtil.assertMeasure(measurements, 21, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_write_to_buf:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, 22, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_write_to_buf:statistic=totalTime:status=0:transport=rest:type=stage,0,1.0E-8"); - AssertUtil.assertMeasure(measurements, 23, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_write_to_buf:statistic=max:status=0:transport=rest:type=stage,0,5.0E-9"); - AssertUtil.assertMeasure(measurements, 24, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wait_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, 25, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wait_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, 26, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wait_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, 27, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wake_consumer:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, 28, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wake_consumer:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, 29, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer_wake_consumer:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, 30, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, 31, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, 32, - "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=client_filters_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=CONSUMER:stage=consumer-decode:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); } @Test @@ -198,35 +168,25 @@ public void edgeInvocation(@Mocked InvocationFinishEvent event) { result = CoreConst.RESTFUL; invocation.getMicroserviceQualifiedName(); result = "m.s.o"; - invocation.getInvocationStageTrace().calcTotalTime(); + invocation.getInvocationStageTrace().calcTotal(); result = 9; - invocation.getInvocationStageTrace().calcThreadPoolQueueTime(); + invocation.getInvocationStageTrace().calcPrepare(); result = 9; - invocation.getInvocationStageTrace().calcClientFiltersRequestTime(); + invocation.getInvocationStageTrace().calcProviderDecodeRequest(); result = 9; - invocation.getInvocationStageTrace().calcSendRequestTime(); + invocation.getInvocationStageTrace().calcConnection(); result = 9; - invocation.getInvocationStageTrace().calcGetConnectionTime(); + invocation.getInvocationStageTrace().calcConsumerEncodeRequest(); result = 4; - invocation.getInvocationStageTrace().calcWriteToBufferTime(); + invocation.getInvocationStageTrace().calcConsumerSendRequest(); result = 5; - invocation.getInvocationStageTrace().calcWakeConsumer(); + invocation.getInvocationStageTrace().calcConsumerDecodeResponse(); + result = 8; + invocation.getInvocationStageTrace().calcWait(); result = 9; - invocation.getInvocationStageTrace().calcReceiveResponseTime(); + invocation.getInvocationStageTrace().calcProviderEncodeResponse(); result = 9; - invocation.getInvocationStageTrace().calcClientFiltersResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcInvocationPrepareTime(); - result = 9; - invocation.getInvocationStageTrace().calcHandlersRequestTime(); - result = 9; - invocation.getInvocationStageTrace().calcHandlersResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcSendResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcServerFiltersRequestTime(); - result = 9; - invocation.getInvocationStageTrace().calcServerFiltersResponseTime(); + invocation.getInvocationStageTrace().calcProviderSendResponse(); result = 9; event.getInvocation(); result = invocation; @@ -241,6 +201,7 @@ public void edgeInvocation(@Mocked InvocationFinishEvent event) { MeasurementTree tree = new MeasurementTree(); tree.from(registry.iterator(), new MeasurementGroupConfig(MeterInvocationConst.INVOCATION_NAME)); List measurements = tree.findChild(MeterInvocationConst.INVOCATION_NAME).getMeasurements(); + Assert.assertEquals(30, measurements.size()); int i = 0; AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=total:statistic=count:status=0:transport=rest:type=stage,0,2.0"); @@ -248,18 +209,6 @@ public void edgeInvocation(@Mocked InvocationFinishEvent event) { "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=total:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=total:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=handlers_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=prepare:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, @@ -267,71 +216,53 @@ public void edgeInvocation(@Mocked InvocationFinishEvent event) { AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=prepare:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_send_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_send_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_send_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_get_connection:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_get_connection:statistic=totalTime:status=0:transport=rest:type=stage,0,8.0E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_get_connection:statistic=max:status=0:transport=rest:type=stage,0,4.0E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-send:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_write_to_buf:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-send:statistic=totalTime:status=0:transport=rest:type=stage,0,1.0E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_write_to_buf:statistic=totalTime:status=0:transport=rest:type=stage,0,1.0E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-send:statistic=max:status=0:transport=rest:type=stage,0,5.0E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_write_to_buf:statistic=max:status=0:transport=rest:type=stage,0,5.0E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=connection:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wait_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=connection:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wait_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=connection:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wait_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-encode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wake_consumer:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-encode:statistic=totalTime:status=0:transport=rest:type=stage,0,8.0E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wake_consumer:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-encode:statistic=max:status=0:transport=rest:type=stage,0,4.0E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer_wake_consumer:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=wait:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=wait:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=wait:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=client_filters_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-decode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=queue:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-decode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.6E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=queue:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=consumer-decode:statistic=max:status=0:transport=rest:type=stage,0,8.0E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=queue:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-decode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-decode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-decode:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-encode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-encode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-encode:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=server_filters_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-send:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=producer_send_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-send:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=producer_send_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i, - "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=producer_send_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=EDGE:stage=provider-send:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); } @Test @@ -346,23 +277,19 @@ public void producerInvocation(@Mocked InvocationFinishEvent event) { result = CoreConst.RESTFUL; invocation.getMicroserviceQualifiedName(); result = "m.s.o"; - invocation.getInvocationStageTrace().calcTotalTime(); + invocation.getInvocationStageTrace().calcTotal(); result = 9; - invocation.getInvocationStageTrace().calcInvocationPrepareTime(); + invocation.getInvocationStageTrace().calcPrepare(); result = 9; - invocation.getInvocationStageTrace().calcHandlersRequestTime(); + invocation.getInvocationStageTrace().calcProviderDecodeRequest(); result = 9; - invocation.getInvocationStageTrace().calcHandlersResponseTime(); + invocation.getInvocationStageTrace().calcQueue(); result = 9; - invocation.getInvocationStageTrace().calcThreadPoolQueueTime(); + invocation.getInvocationStageTrace().calcBusinessExecute(); result = 9; - invocation.getInvocationStageTrace().calcBusinessTime(); + invocation.getInvocationStageTrace().calcProviderEncodeResponse(); result = 9; - invocation.getInvocationStageTrace().calcServerFiltersRequestTime(); - result = 9; - invocation.getInvocationStageTrace().calcServerFiltersResponseTime(); - result = 9; - invocation.getInvocationStageTrace().calcSendResponseTime(); + invocation.getInvocationStageTrace().calcProviderSendResponse(); result = 9; event.getInvocation(); result = invocation; @@ -377,6 +304,7 @@ public void producerInvocation(@Mocked InvocationFinishEvent event) { MeasurementTree tree = new MeasurementTree(); tree.from(registry.iterator(), new MeasurementGroupConfig(MeterInvocationConst.INVOCATION_NAME)); List measurements = tree.findChild(MeterInvocationConst.INVOCATION_NAME).getMeasurements(); + Assert.assertEquals(21, measurements.size()); int i = 0; AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=total:statistic=count:status=0:transport=rest:type=stage,0,2.0"); @@ -384,18 +312,6 @@ public void producerInvocation(@Mocked InvocationFinishEvent event) { "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=total:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=total:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=handlers_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=prepare:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, @@ -409,28 +325,28 @@ public void producerInvocation(@Mocked InvocationFinishEvent event) { AssertUtil.assertMeasure(measurements, i++, "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=queue:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execution:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execute:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + AssertUtil.assertMeasure(measurements, i++, + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execute:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execution:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execute:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=execution:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-decode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_request:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-decode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_request:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-decode:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_request:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-encode:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-encode:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-encode:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=server_filters_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-send:statistic=count:status=0:transport=rest:type=stage,0,2.0"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=producer_send_response:statistic=count:status=0:transport=rest:type=stage,0,2.0"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-send:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); AssertUtil.assertMeasure(measurements, i++, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=producer_send_response:statistic=totalTime:status=0:transport=rest:type=stage,0,1.8000000000000002E-8"); - AssertUtil.assertMeasure(measurements, i, - "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=producer_send_response:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); + "servicecomb.invocation:operation=m.s.o:role=PROVIDER:stage=provider-send:statistic=max:status=0:transport=rest:type=stage,0,9.000000000000001E-9"); } } diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestDefaultLogPublisher.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestDefaultLogPublisher.java index 2b136e7b5ae..90cf30e4c99 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestDefaultLogPublisher.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestDefaultLogPublisher.java @@ -26,6 +26,7 @@ import org.apache.logging.log4j.core.LogEvent; import org.apache.servicecomb.core.CoreConst; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.foundation.common.Holder; import org.apache.servicecomb.foundation.metrics.MetricsBootstrapConfig; import org.apache.servicecomb.foundation.metrics.PolledEvent; @@ -34,7 +35,6 @@ import org.apache.servicecomb.foundation.metrics.registry.GlobalRegistry; import org.apache.servicecomb.foundation.test.scaffolding.log.LogCollector; import org.apache.servicecomb.foundation.vertx.VertxUtils; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.metrics.core.meter.os.OsMeter; import org.apache.servicecomb.metrics.core.publish.model.DefaultPublishModel; import org.apache.servicecomb.metrics.core.publish.model.ThreadPoolPublishModel; @@ -164,22 +164,18 @@ public void onPolledEvent(@Injectable VertxImpl vertxImpl, @Injectable Measureme OperationPerf operationPerf = new OperationPerf(); operationPerf.setOperation("op"); operationPerf.setLatencyDistribution(new Integer[] {12, 120, 1200}); - operationPerf.getStages().put(MeterInvocationConst.STAGE_TOTAL, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_EXECUTOR_QUEUE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_EXECUTION, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_PREPARE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_HANDLERS_REQUEST, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_HANDLERS_RESPONSE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CLIENT_FILTERS_REQUEST, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CLIENT_FILTERS_RESPONSE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CONSUMER_SEND_REQUEST, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_PRODUCER_SEND_RESPONSE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CONSUMER_GET_CONNECTION, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CONSUMER_WRITE_TO_BUF, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CONSUMER_WAIT_RESPONSE, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_CONSUMER_WAKE_CONSUMER, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_SERVER_FILTERS_REQUEST, perfTotal); - operationPerf.getStages().put(MeterInvocationConst.STAGE_SERVER_FILTERS_RESPONSE, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_TOTAL, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PROVIDER_QUEUE, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_CONSUMER_ENCODE_REQUEST, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_CONSUMER_DECODE_RESPONSE, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PROVIDER_DECODE_REQUEST, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PROVIDER_ENCODE_RESPONSE, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PROVIDER_BUSINESS, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PREPARE, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_CONSUMER_WAIT, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_CONSUMER_SEND, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_PROVIDER_SEND, perfTotal); + operationPerf.getStages().put(InvocationStageTrace.STAGE_CONSUMER_CONNECTION, perfTotal); OperationPerfGroup operationPerfGroup = new OperationPerfGroup(CoreConst.RESTFUL, Status.OK.name()); operationPerfGroup.addOperationPerf(operationPerf); @@ -244,56 +240,55 @@ MeasurementTree getTree() { }; publisher.onPolledEvent(new PolledEvent(Collections.emptyList(), Collections.emptyList())); List events = collector.getEvents().stream() - .filter(e -> DefaultLogPublisher.class.getName().equals(e.getLoggerName())).toList(); + .filter(e -> "scb-metrics".equals(e.getLoggerName())).toList(); LogEvent event = events.get(0); - Assertions.assertEquals("\n" - + "os:\n" - + " cpu:\n" - + " all usage: 100.00% all idle: 0.00% process: 100.00%\n" - + " net:\n" - + " send(Bps) recv(Bps) send(pps) recv(pps) interface\n" - + " 1 1 1 1 eth0\n" - + "vertx:\n" - + " instances:\n" - + " name eventLoopContext-created\n" - + " v 0\n" - + "threadPool:\n" - + " coreSize maxThreads poolSize currentBusy rejected queueSize taskCount taskFinished name\n" - + " 0 0 0 0 NaN 0 0.0 0.0 test\n" - + "consumer:\n" - + " simple:\n" - + " status tps latency [0,1) [1,100) [100,) operation\n" - + " rest.OK 100000.0 3000.000/30000.000 12 120 1200 op\n" - + " 100000.0 3000.000/30000.000 12 120 1200 (summary)\n" - + " details:\n" - + " rest.OK:\n" - + " op:\n" - + " prepare : 3000.000/30000.000 handlersReq : 3000.000/30000.000 cFiltersReq: 3000.000/30000.000 sendReq : 3000.000/30000.000\n" - + " getConnect : 3000.000/30000.000 writeBuf : 3000.000/30000.000 waitResp : 3000.000/30000.000 wakeConsumer: 3000.000/30000.000\n" - + " cFiltersResp: 3000.000/30000.000 handlersResp: 3000.000/30000.000\n" - + "producer:\n" - + " simple:\n" - + " status tps latency [0,1) [1,100) [100,) operation\n" - + " rest.OK 100000.0 3000.000/30000.000 12 120 1200 op\n" - + " 100000.0 3000.000/30000.000 12 120 1200 (summary)\n" - + " details:\n" - + " rest.OK:\n" - + " op:\n" - + " prepare: 3000.000/30000.000 queue : 3000.000/30000.000 filtersReq : 3000.000/30000.000 handlersReq: 3000.000/30000.000\n" - + " execute: 3000.000/30000.000 handlersResp: 3000.000/30000.000 filtersResp: 3000.000/30000.000 sendResp : 3000.000/30000.000\n" - + "edge:\n" - + " simple:\n" - + " status tps latency [0,1) [1,100) [100,) operation\n" - + " rest.OK 100000.0 3000.000/30000.000 12 120 1200 op\n" - + " 100000.0 3000.000/30000.000 12 120 1200 (summary)\n" - + " details:\n" - + " rest.OK:\n" - + " op:\n" - + " prepare : 3000.000/30000.000 queue : 3000.000/30000.000 sFiltersReq : 3000.000/30000.000 handlersReq : 3000.000/30000.000\n" - + " cFiltersReq : 3000.000/30000.000 sendReq : 3000.000/30000.000 getConnect : 3000.000/30000.000 writeBuf : 3000.000/30000.000\n" - + " waitResp : 3000.000/30000.000 wakeConsumer: 3000.000/30000.000 cFiltersResp: 3000.000/30000.000 handlersResp: 3000.000/30000.000\n" - + " sFiltersResp: 3000.000/30000.000 sendResp : 3000.000/30000.000\n", - event.getMessage().getFormattedMessage()); + Assertions.assertEquals(""" + os: + cpu: + all usage: 100.00% all idle: 0.00% process: 100.00% + net: + send(Bps) recv(Bps) send(pps) recv(pps) interface + 1 1 1 1 eth0 + vertx: + instances: + name eventLoopContext-created + v 0 + threadPool: + coreSize maxThreads poolSize currentBusy rejected queueSize taskCount taskFinished name + 0 0 0 0 NaN 0 0.0 0.0 test + consumer: + simple: + status tps latency [0,1) [1,100) [100,) operation + rest.OK 100000.0 3000.000/30000.000 12 120 1200 op + 100000.0 3000.000/30000.000 12 120 1200 (summary) + details: + rest.OK: + op: + prepare : 3000.000/30000.000 connection : 3000.000/30000.000 encode-request: 3000.000/30000.000 send : 3000.000/30000.000 + wait : 3000.000/30000.000 decode-response : 3000.000/30000.000 + producer: + simple: + status tps latency [0,1) [1,100) [100,) operation + rest.OK 100000.0 3000.000/30000.000 12 120 1200 op + 100000.0 3000.000/30000.000 12 120 1200 (summary) + details: + rest.OK: + op: + prepare: 3000.000/30000.000 decode-request : 3000.000/30000.000 queue : 3000.000/30000.000 business-execute: 3000.000/30000.000 + encode-response: 3000.000/30000.000 send: 3000.000/30000.000 + edge: + simple: + status tps latency [0,1) [1,100) [100,) operation + rest.OK 100000.0 3000.000/30000.000 12 120 1200 op + 100000.0 3000.000/30000.000 12 120 1200 (summary) + details: + rest.OK: + op: + prepare : 3000.000/30000.000 provider-decode : 3000.000/30000.000 connection : 3000.000/30000.000 consumer-encode : 3000.000/30000.000 + consumer-send : 3000.000/30000.000 wait : 3000.000/30000.000 consumer-decode : 3000.000/30000.000 provider-encode : 3000.000/30000.000 + provider-send : 3000.000/30000.000 + """.trim(), + event.getMessage().getFormattedMessage().trim()); } catch (Exception e) { e.printStackTrace(); Assertions.fail("unexpected error happen. " + e.getMessage()); diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestInvocationPublishModelFactory.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestInvocationPublishModelFactory.java index b0d22f7fe24..6480928f98e 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestInvocationPublishModelFactory.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestInvocationPublishModelFactory.java @@ -43,11 +43,6 @@ import com.netflix.spectator.api.Registry; import io.vertx.core.json.Json; -import mockit.Deencapsulation; -import mockit.Expectations; -import mockit.Mock; -import mockit.MockUp; -import mockit.Mocked; public class TestInvocationPublishModelFactory { EventBus eventBus = new EventBus(); @@ -58,13 +53,11 @@ public class TestInvocationPublishModelFactory { InvocationMetersInitializer invocationMetersInitializer = new InvocationMetersInitializer(); - @Mocked - Invocation invocation; + Invocation invocation = Mockito.mock(Invocation.class); - InvocationStageTrace invocationStageTrace = new InvocationStageTrace(invocation); + InvocationStageTrace invocationStageTrace = Mockito.mock(InvocationStageTrace.class); - @Mocked - Response response; + Response response = Mockito.mock(Response.class); InvocationType invocationType; @@ -86,321 +79,228 @@ public void createDefaultPublishModel() { PublishModelFactory factory = new PublishModelFactory(Lists.newArrayList(registry.iterator())); DefaultPublishModel model = factory.createDefaultPublishModel(); - String expect = "{\n" - + " \"operationPerfGroups\" : {\n" - + " \"groups\" : {\n" - + " \"rest\" : {\n" - + " \"200\" : {\n" - + " \"transport\" : \"rest\",\n" - + " \"status\" : \"200\",\n" - + " \"operationPerfs\" : [ {\n" - + " \"operation\" : \"m.s.o\",\n" - + " \"stages\" : {\n" - + " \"prepare\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"client_filters_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"total\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.4000000000000001E-5,\n" - + " \"msMaxLatency\" : 1.4000000000000001E-5\n" - + " },\n" - + " \"consumer_send_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 2.0000000000000003E-6,\n" - + " \"msMaxLatency\" : 2.0000000000000003E-6\n" - + " },\n" - + " \"handlers_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"handlers_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 3.0000000000000005E-6,\n" - + " \"msMaxLatency\" : 3.0000000000000005E-6\n" - + " },\n" - + " \"consumer_wait_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"client_filters_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_get_connection\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_write_to_buf\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_wake_consumer\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " }\n" - + " },\n" - + " \"latencyDistribution\" : [ 1, 0, 0 ]\n" - + " } ],\n" - + " \"summary\" : {\n" - + " \"operation\" : \"\",\n" - + " \"stages\" : {\n" - + " \"client_filters_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"prepare\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_send_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 2.0000000000000003E-6,\n" - + " \"msMaxLatency\" : 2.0000000000000003E-6\n" - + " },\n" - + " \"total\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.4000000000000001E-5,\n" - + " \"msMaxLatency\" : 1.4000000000000001E-5\n" - + " },\n" - + " \"handlers_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"client_filters_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_wait_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"handlers_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 3.0000000000000005E-6,\n" - + " \"msMaxLatency\" : 3.0000000000000005E-6\n" - + " },\n" - + " \"consumer_get_connection\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_wake_consumer\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"consumer_write_to_buf\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " }\n" - + " },\n" - + " \"latencyDistribution\" : [ 1, 0, 0 ]\n" - + " }\n" - + " }\n" - + " }\n" - + " }\n" - + " }\n" - + "}"; + String expect = """ + { + "operationPerfGroups" : { + "groups" : { + "rest" : { + "200" : { + "transport" : "rest", + "status" : "200", + "operationPerfs" : [ { + "operation" : "m.s.o", + "stages" : { + "consumer-encode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "prepare" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "total" : { + "tps" : 1.0, + "msTotalTime" : 1.4000000000000001E-5, + "msMaxLatency" : 1.4000000000000001E-5 + }, + "wait" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-send" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "connection" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-decode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + } + }, + "latencyDistribution" : [ 1, 0, 0 ] + } ], + "summary" : { + "operation" : "", + "stages" : { + "consumer-encode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "prepare" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "wait" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "total" : { + "tps" : 1.0, + "msTotalTime" : 1.4000000000000001E-5, + "msMaxLatency" : 1.4000000000000001E-5 + }, + "consumer-send" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "connection" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-decode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + } + }, + "latencyDistribution" : [ 1, 0, 0 ] + } + } + } + } + } + } + """; Assertions.assertEquals(Json.encodePrettily(Json.decodeValue(expect, Object.class)), Json.encodePrettily(model.getConsumer())); - expect = "{\n" - + " \"operationPerfGroups\" : {\n" - + " \"groups\" : {\n" - + " \"rest\" : {\n" - + " \"200\" : {\n" - + " \"transport\" : \"rest\",\n" - + " \"status\" : \"200\",\n" - + " \"operationPerfs\" : [ {\n" - + " \"operation\" : \"m.s.o\",\n" - + " \"stages\" : {\n" - + " \"server_filters_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 0.0,\n" - + " \"msMaxLatency\" : 0.0\n" - + " },\n" - + " \"prepare\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 5.0E-6,\n" - + " \"msMaxLatency\" : 5.0E-6\n" - + " },\n" - + " \"execution\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 3.0000000000000005E-6,\n" - + " \"msMaxLatency\" : 3.0000000000000005E-6\n" - + " },\n" - + " \"total\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.4000000000000001E-5,\n" - + " \"msMaxLatency\" : 1.4000000000000001E-5\n" - + " },\n" - + " \"producer_send_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 2.0000000000000003E-6,\n" - + " \"msMaxLatency\" : 2.0000000000000003E-6\n" - + " },\n" - + " \"handlers_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 6.000000000000001E-6,\n" - + " \"msMaxLatency\" : 6.000000000000001E-6\n" - + " },\n" - + " \"handlers_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"queue\" : {\n" - + " \"tps\" : 0.0,\n" - + " \"msTotalTime\" : 0.0,\n" - + " \"msMaxLatency\" : 0.0\n" - + " },\n" - + " \"server_filters_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " }\n" - + " },\n" - + " \"latencyDistribution\" : [ 1, 0, 0 ]\n" - + " } ],\n" - + " \"summary\" : {\n" - + " \"operation\" : \"\",\n" - + " \"stages\" : {\n" - + " \"server_filters_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 0.0,\n" - + " \"msMaxLatency\" : 0.0\n" - + " },\n" - + " \"execution\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 3.0000000000000005E-6,\n" - + " \"msMaxLatency\" : 3.0000000000000005E-6\n" - + " },\n" - + " \"prepare\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 5.0E-6,\n" - + " \"msMaxLatency\" : 5.0E-6\n" - + " },\n" - + " \"producer_send_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 2.0000000000000003E-6,\n" - + " \"msMaxLatency\" : 2.0000000000000003E-6\n" - + " },\n" - + " \"total\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.4000000000000001E-5,\n" - + " \"msMaxLatency\" : 1.4000000000000001E-5\n" - + " },\n" - + " \"handlers_request\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 6.000000000000001E-6,\n" - + " \"msMaxLatency\" : 6.000000000000001E-6\n" - + " },\n" - + " \"handlers_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " },\n" - + " \"queue\" : {\n" - + " \"tps\" : 0.0,\n" - + " \"msTotalTime\" : 0.0,\n" - + " \"msMaxLatency\" : 0.0\n" - + " },\n" - + " \"server_filters_response\" : {\n" - + " \"tps\" : 1.0,\n" - + " \"msTotalTime\" : 1.0000000000000002E-6,\n" - + " \"msMaxLatency\" : 1.0000000000000002E-6\n" - + " }\n" - + " },\n" - + " \"latencyDistribution\" : [ 1, 0, 0 ]\n" - + " }\n" - + " }\n" - + " }\n" - + " }\n" - + " }\n" - + "}"; + expect = """ + { + "operationPerfGroups" : { + "groups" : { + "rest" : { + "200" : { + "transport" : "rest", + "status" : "200", + "operationPerfs" : [ { + "operation" : "m.s.o", + "stages" : { + "consumer-encode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "prepare" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "total" : { + "tps" : 1.0, + "msTotalTime" : 1.4000000000000001E-5, + "msMaxLatency" : 1.4000000000000001E-5 + }, + "wait" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-send" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "connection" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-decode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + } + }, + "latencyDistribution" : [ 1, 0, 0 ] + } ], + "summary" : { + "operation" : "", + "stages" : { + "consumer-encode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "prepare" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "wait" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "total" : { + "tps" : 1.0, + "msTotalTime" : 1.4000000000000001E-5, + "msMaxLatency" : 1.4000000000000001E-5 + }, + "consumer-send" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "connection" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + }, + "consumer-decode" : { + "tps" : 1.0, + "msTotalTime" : 1.0000000000000002E-6, + "msMaxLatency" : 1.0000000000000002E-6 + } + }, + "latencyDistribution" : [ 1, 0, 0 ] + } + } + } + } + } + } + """; Assertions.assertEquals(Json.encodePrettily(Json.decodeValue(expect, Object.class)), Json.encodePrettily(model.getProducer())); } protected void prepareInvocation() { - - Deencapsulation.setField(invocationStageTrace, "start", 1L); - Deencapsulation.setField(invocationStageTrace, "startHandlersRequest", 2L); - Deencapsulation.setField(invocationStageTrace, "startClientFiltersRequest", 3L); - Deencapsulation.setField(invocationStageTrace, "startSend", 4L); - Deencapsulation.setField(invocationStageTrace, "startGetConnection", 4L); - Deencapsulation.setField(invocationStageTrace, "finishGetConnection", 5L); - Deencapsulation.setField(invocationStageTrace, "finishWriteToBuffer", 6L); - Deencapsulation.setField(invocationStageTrace, "finishReceiveResponse", 7L); - Deencapsulation.setField(invocationStageTrace, "startClientFiltersResponse", 8L); - Deencapsulation.setField(invocationStageTrace, "finishClientFiltersResponse", 9L); - Deencapsulation.setField(invocationStageTrace, "finishHandlersResponse", 14L); - Deencapsulation.setField(invocationStageTrace, "finish", 15L); - Deencapsulation.setField(invocationStageTrace, "startExecution", 5L); - Deencapsulation.setField(invocationStageTrace, "startSchedule", 6L); - Deencapsulation.setField(invocationStageTrace, "startBusinessMethod", 8L); - Deencapsulation.setField(invocationStageTrace, "finishBusiness", 11L); - Deencapsulation.setField(invocationStageTrace, "finishHandlersResponse", 12L); - Deencapsulation.setField(invocationStageTrace, "finishServerFiltersResponse", 13L); - Deencapsulation.setField(invocationStageTrace, "invocation", invocation); + Mockito.when(invocationStageTrace.calcTotal()).thenReturn(14L); + Mockito.when(invocationStageTrace.calcPrepare()).thenReturn(1L); + Mockito.when(invocationStageTrace.calcConnection()).thenReturn(1L); + Mockito.when(invocationStageTrace.calcConsumerEncodeRequest()).thenReturn(1L); + Mockito.when(invocationStageTrace.calcConsumerSendRequest()).thenReturn(1L); + Mockito.when(invocationStageTrace.calcWait()).thenReturn(1L); + Mockito.when(invocationStageTrace.calcConsumerDecodeResponse()).thenReturn(1L); invocationType = InvocationType.CONSUMER; - new MockUp() { - @Mock - InvocationType getInvocationType() { - return invocationType; - } - - @Mock - boolean isConsumer() { - return InvocationType.CONSUMER.equals(invocationType); - } - - @Mock - String getRealTransportName() { - return CoreConst.RESTFUL; - } - - @Mock - String getMicroserviceQualifiedName() { - return "m.s.o"; - } - @Mock - InvocationStageTrace getInvocationStageTrace() { - return invocationStageTrace; - } - }; + Mockito.when(invocation.getInvocationType()).thenReturn(invocationType); + Mockito.when(invocation.isConsumer()).thenReturn(InvocationType.CONSUMER.equals(invocationType)); + Mockito.when(invocation.getRealTransportName()).thenReturn(CoreConst.RESTFUL); + Mockito.when(invocation.getMicroserviceQualifiedName()).thenReturn("m.s.o"); + Mockito.when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace); + Mockito.when(response.getStatusCode()).thenReturn(200); - new Expectations() { - { - response.getStatusCode(); - result = 200; - } - }; InvocationFinishEvent finishEvent = new InvocationFinishEvent(invocation, response); eventBus.post(finishEvent); invocationType = InvocationType.PROVIDER; + Mockito.when(invocation.getInvocationType()).thenReturn(invocationType); eventBus.post(finishEvent); } } diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestPublishUtils.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestPublishUtils.java index 78ada56f9c2..66a451aef57 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestPublishUtils.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestPublishUtils.java @@ -19,12 +19,10 @@ import java.util.HashMap; import java.util.Map; -import jakarta.ws.rs.core.Response.Status; - import org.apache.servicecomb.core.CoreConst; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.foundation.metrics.publish.spectator.MeasurementNode; import org.apache.servicecomb.foundation.metrics.publish.spectator.MeasurementTree; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.metrics.core.publish.model.ThreadPoolPublishModel; import org.apache.servicecomb.metrics.core.publish.model.invocation.OperationPerf; import org.apache.servicecomb.metrics.core.publish.model.invocation.OperationPerfGroup; @@ -32,16 +30,18 @@ import org.apache.servicecomb.metrics.core.publish.model.invocation.PerfInfo; import org.apache.servicecomb.metrics.core.publish.model.invocation.Utils; import org.junit.Test; +import org.junit.jupiter.api.Assertions; import com.netflix.spectator.api.patterns.ThreadPoolMonitorPublishModelFactory; -import org.junit.jupiter.api.Assertions; + +import jakarta.ws.rs.core.Response.Status; public class TestPublishUtils { String op = "op"; @Test public void createPerfInfo() { - MeasurementNode stageNode = Utils.createStageNode(MeterInvocationConst.STAGE_TOTAL, 10, 10, 100); + MeasurementNode stageNode = Utils.createStageNode(InvocationStageTrace.STAGE_TOTAL, 10, 10, 100); PerfInfo perf = PublishUtils.createPerfInfo(stageNode); @@ -54,7 +54,7 @@ public void createPerfInfo() { public void createOperationPerf() { OperationPerf opPerf = Utils.createOperationPerf(op); - PerfInfo perfInfo = opPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo perfInfo = opPerf.findStage(InvocationStageTrace.STAGE_TOTAL); Integer[] latencyDistribution = opPerf.getLatencyDistribution(); Assertions.assertEquals(10, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); @@ -75,7 +75,7 @@ public void addOperationPerfGroups() { Map statusMap = groups.getGroups().get(CoreConst.RESTFUL); OperationPerfGroup group = statusMap.get(Status.OK.name()); - PerfInfo perfInfo = group.getSummary().findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo perfInfo = group.getSummary().findStage(InvocationStageTrace.STAGE_TOTAL); Integer[] latencyDistribution = group.getSummary().getLatencyDistribution(); Assertions.assertEquals(10, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java index dad92b73711..6d172118d92 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/TestSlowInvocationLogger.java @@ -25,7 +25,6 @@ import org.apache.servicecomb.core.definition.OperationMeta; import org.apache.servicecomb.core.event.InvocationFinishEvent; import org.apache.servicecomb.core.invocation.InvocationStageTrace; -import org.apache.servicecomb.core.tracing.TraceIdLogger; import org.apache.servicecomb.foundation.test.scaffolding.log.LogCollector; import org.apache.servicecomb.foundation.vertx.http.HttpServletRequestEx; import org.apache.servicecomb.swagger.invocation.Response; @@ -92,7 +91,7 @@ public void enableButNotSlow() { result = true; operationConfig.getNanoSlowInvocation(); result = 2; - stageTrace.calcTotalTime(); + stageTrace.calcTotal(); result = 1; } }; @@ -111,37 +110,32 @@ public void consumerSlow(@Mocked Endpoint endpoint) { result = "rest://1.1.1.1:1234"; invocation.isConsumer(); result = true; - invocation.getTraceIdLogger(); - result = new TraceIdLogger(invocation); operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION); result = restOperationMeta; operationConfig.isSlowInvocationEnabled(); result = true; operationConfig.getNanoSlowInvocation(); result = 1; - stageTrace.calcTotalTime(); + stageTrace.calcTotal(); result = 1; } }; logger.onInvocationFinish(event); - Assertions.assertEquals("" - + "slow(0 ms) invocation, null:\n" - + " http method: null\n" - + " url : null\n" - + " server : rest://1.1.1.1:1234\n" - + " status code: 0\n" - + " total : 0.0 ms\n" - + " prepare : 0.0 ms\n" - + " handlers request : 0.0 ms\n" - + " client filters request : 0.0 ms\n" - + " send request : 0.0 ms\n" - + " get connection : 0.0 ms\n" - + " write to buf : 0.0 ms\n" - + " wait response : 0.0 ms\n" - + " wake consumer : 0.0 ms\n" - + " client filters response: 0.0 ms\n" - + " handlers response : 0.0 ms", + Assertions.assertEquals(""" + Slow Consumer invocation [null](0 ms)[null] + http method : null + url : null + endpoint : rest://1.1.1.1:1234 + status code : 0.0ms + total : 0.0ms + prepare : 0.0ms + connection : 0.0ms + consumer-encode : 0.0ms + consumer-send : 0.0ms + wait : 0.0ms + consumer-decode : 0.0ms + """, logCollector.getEvent(0).getMessage().getFormattedMessage()); } @@ -155,8 +149,6 @@ public void edgeSlow(@Mocked Endpoint endpoint) { result = "rest://1.1.1.1:1234"; invocation.isConsumer(); result = true; - invocation.getTraceIdLogger(); - result = new TraceIdLogger(invocation); invocation.isEdge(); result = true; operationMeta.getExtData(RestConst.SWAGGER_REST_OPERATION); @@ -165,33 +157,29 @@ public void edgeSlow(@Mocked Endpoint endpoint) { result = true; operationConfig.getNanoSlowInvocation(); result = 1; - stageTrace.calcTotalTime(); + stageTrace.calcTotal(); result = 1; } }; logger.onInvocationFinish(event); - Assertions.assertEquals("" - + "slow(0 ms) invocation, null:\n" - + " http method: null\n" - + " url : null\n" - + " server : rest://1.1.1.1:1234\n" - + " status code: 0\n" - + " total : 0.0 ms\n" - + " prepare : 0.0 ms\n" - + " threadPoolQueue : 0.0 ms\n" - + " server filters request : 0.0 ms\n" - + " handlers request : 0.0 ms\n" - + " client filters request : 0.0 ms\n" - + " send request : 0.0 ms\n" - + " get connection : 0.0 ms\n" - + " write to buf : 0.0 ms\n" - + " wait response : 0.0 ms\n" - + " wake consumer : 0.0 ms\n" - + " client filters response: 0.0 ms\n" - + " handlers response : 0.0 ms\n" - + " server filters response: 0.0 ms\n" - + " send response : 0.0 ms", + Assertions.assertEquals(""" + Slow Edge invocation [null](0 ms)[null] + http method : null + url : null + endpoint : rest://1.1.1.1:1234 + status code : 0.0ms + total : 0.0ms + prepare : 0.0ms + provider-decode : 0.0ms + connection : 0.0ms + consumer-encode : 0.0ms + consumer-send : 0.0ms + wait : 0.0ms + consumer-decode : 0.0ms + provider-encode : 0.0ms + provider-send : 0.0ms + """, logCollector.getEvent(0).getMessage().getFormattedMessage()); } @@ -201,8 +189,6 @@ public void producerSlow(@Mocked HttpServletRequestEx requestEx) { { invocation.getRequestEx(); result = requestEx; - invocation.getTraceIdLogger(); - result = new TraceIdLogger(invocation); requestEx.getRemoteAddr(); result = "1.1.1.1"; requestEx.getRemotePort(); @@ -215,27 +201,26 @@ public void producerSlow(@Mocked HttpServletRequestEx requestEx) { result = true; operationConfig.getNanoSlowInvocation(); result = 1; - stageTrace.calcTotalTime(); + stageTrace.calcTotal(); result = 1; } }; logger.onInvocationFinish(event); - Assertions.assertEquals("" - + "slow(0 ms) invocation, null:\n" - + " http method: null\n" - + " url : null\n" - + " client : 1.1.1.1:1234\n" - + " status code: 0\n" - + " total : 0.0 ms\n" - + " prepare : 0.0 ms\n" - + " threadPoolQueue : 0.0 ms\n" - + " server filters request : 0.0 ms\n" - + " handlers request : 0.0 ms\n" - + " business execute : 0.0 ms\n" - + " handlers response : 0.0 ms\n" - + " server filters response: 0.0 ms\n" - + " send response : 0.0 ms", + Assertions.assertEquals(""" + Slow Provider invocation [null](0 ms)[null] + http method : null + url : null + endpoint : 1.1.1.1:1234 + status code : 0.0ms + total : 0.0ms + prepare : 0.0ms + provider-decode : 0.0ms + queue : 0.0ms + execute : 0.0ms + provider-encode : 0.0ms + provider-send : 0.0ms + """, logCollector.getEvent(0).getMessage().getFormattedMessage()); } } diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerf.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerf.java index f0fa8349185..bc4016165cf 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerf.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerf.java @@ -16,7 +16,7 @@ */ package org.apache.servicecomb.metrics.core.publish.model.invocation; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.junit.Test; import org.junit.jupiter.api.Assertions; @@ -34,12 +34,12 @@ public void add() { Assertions.assertEquals(op, otherOpPerf.getOperation()); - PerfInfo perfInfo = opPerf.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo perfInfo = opPerf.findStage(InvocationStageTrace.STAGE_TOTAL); Assertions.assertEquals(10, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); Assertions.assertEquals(100000, perfInfo.getMsMaxLatency(), 0); - perfInfo = opPerf.findStage(MeterInvocationConst.STAGE_EXECUTION); + perfInfo = opPerf.findStage(InvocationStageTrace.STAGE_PROVIDER_BUSINESS); Assertions.assertEquals(10, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); Assertions.assertEquals(100000, perfInfo.getMsMaxLatency(), 0); diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerfGroup.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerfGroup.java index 2306ea9dfb8..ae3ed7a292d 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerfGroup.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/TestOperationPerfGroup.java @@ -16,13 +16,13 @@ */ package org.apache.servicecomb.metrics.core.publish.model.invocation; -import jakarta.ws.rs.core.Response.Status; - import org.apache.servicecomb.core.CoreConst; -import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.junit.Test; import org.junit.jupiter.api.Assertions; +import jakarta.ws.rs.core.Response.Status; + public class TestOperationPerfGroup { String op = "op"; @@ -46,12 +46,12 @@ public void addOperationPerf() { OperationPerf summary = group.getSummary(); - PerfInfo perfInfo = summary.findStage(MeterInvocationConst.STAGE_TOTAL); + PerfInfo perfInfo = summary.findStage(InvocationStageTrace.STAGE_TOTAL); Assertions.assertEquals(20, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); Assertions.assertEquals(100000, perfInfo.getMsMaxLatency(), 0); - perfInfo = summary.findStage(MeterInvocationConst.STAGE_EXECUTION); + perfInfo = summary.findStage(InvocationStageTrace.STAGE_PROVIDER_BUSINESS); Assertions.assertEquals(20, perfInfo.getTps(), 0); Assertions.assertEquals(1000, perfInfo.calcMsLatency(), 0); Assertions.assertEquals(100000, perfInfo.getMsMaxLatency(), 0); diff --git a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/Utils.java b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/Utils.java index f8dcd649c77..9c65ee24a73 100644 --- a/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/Utils.java +++ b/metrics/metrics-core/src/test/java/org/apache/servicecomb/metrics/core/publish/model/invocation/Utils.java @@ -19,8 +19,7 @@ import java.util.HashMap; import java.util.List; -import jakarta.ws.rs.core.Response.Status; - +import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.foundation.metrics.publish.spectator.MeasurementNode; import org.apache.servicecomb.metrics.core.meter.invocation.MeterInvocationConst; import org.apache.servicecomb.metrics.core.publish.PublishUtils; @@ -31,13 +30,15 @@ import com.netflix.spectator.api.Registry; import com.netflix.spectator.api.Statistic; +import jakarta.ws.rs.core.Response.Status; + public class Utils { static Registry registry = new DefaultRegistry(); - public static MeasurementNode totalStageNode = Utils.createStageNode(MeterInvocationConst.STAGE_TOTAL, 10, 10, 100); + public static MeasurementNode totalStageNode = Utils.createStageNode(InvocationStageTrace.STAGE_TOTAL, 10, 10, 100); public static MeasurementNode executeStageNode = - Utils.createStageNode(MeterInvocationConst.STAGE_EXECUTION, 10, 10, 100); + Utils.createStageNode(InvocationStageTrace.STAGE_PROVIDER_BUSINESS, 10, 10, 100); public static MeasurementNode createStageNode(String stage, double count, diff --git a/pom.xml b/pom.xml index b9f6d13d12c..ecefe57fb5d 100644 --- a/pom.xml +++ b/pom.xml @@ -68,7 +68,7 @@ 3.2.1 4.7.3.5 3.1.3 - 3.0.0-M9 + 3.2.2 @@ -306,8 +306,9 @@ ${excludesFile} - 1 - true + 5 + 2 + false alphabetical diff --git a/providers/provider-pojo/src/main/java/org/apache/servicecomb/provider/pojo/PojoInvocationCreator.java b/providers/provider-pojo/src/main/java/org/apache/servicecomb/provider/pojo/PojoInvocationCreator.java index 7f34b4b1c83..54dd320fe68 100644 --- a/providers/provider-pojo/src/main/java/org/apache/servicecomb/provider/pojo/PojoInvocationCreator.java +++ b/providers/provider-pojo/src/main/java/org/apache/servicecomb/provider/pojo/PojoInvocationCreator.java @@ -24,6 +24,7 @@ public class PojoInvocationCreator { public PojoInvocation create(Method method, PojoConsumerMetaRefresher metaRefresher, Object[] args) { + long startCreateInvocation = System.nanoTime(); PojoConsumerMeta pojoConsumerMeta = metaRefresher.getLatestMeta(); PojoConsumerOperationMeta consumerOperationMeta = pojoConsumerMeta.ensureFindOperationMeta(method); @@ -31,7 +32,8 @@ public PojoInvocation create(Method method, PojoConsumerMetaRefresher metaRefres invocation.setSuccessResponseType(consumerOperationMeta.getResponsesType()); invocation.setInvocationArguments(consumerOperationMeta.getSwaggerConsumerOperation().toInvocationArguments(args)); invocation.setSync(consumerOperationMeta.isSync()); - + invocation.getInvocationStageTrace().startCreateInvocation(startCreateInvocation); + invocation.getInvocationStageTrace().finishCreateInvocation(); return invocation; } diff --git a/swagger/swagger-invocation/invocation-core/src/main/java/org/apache/servicecomb/swagger/invocation/SwaggerInvocation.java b/swagger/swagger-invocation/invocation-core/src/main/java/org/apache/servicecomb/swagger/invocation/SwaggerInvocation.java index a6df86d3c4c..52386716189 100644 --- a/swagger/swagger-invocation/invocation-core/src/main/java/org/apache/servicecomb/swagger/invocation/SwaggerInvocation.java +++ b/swagger/swagger-invocation/invocation-core/src/main/java/org/apache/servicecomb/swagger/invocation/SwaggerInvocation.java @@ -45,13 +45,4 @@ public InvocationType getInvocationType() { public String getInvocationQualifiedName() { return invocationType.name(); } - - public void onBusinessMethodStart() { - } - - public void onBusinessMethodFinish() { - } - - public void onBusinessFinish() { - } } diff --git a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClient.java b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClient.java index 8d94333c278..218f62e628b 100644 --- a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClient.java +++ b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClient.java @@ -17,12 +17,9 @@ package org.apache.servicecomb.transport.highway; -import java.util.concurrent.TimeoutException; - import org.apache.servicecomb.codec.protobuf.definition.OperationProtobuf; -import org.apache.servicecomb.codec.protobuf.definition.ProtobufManager; -import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; import org.apache.servicecomb.core.Invocation; +import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; import org.apache.servicecomb.foundation.ssl.SSLCustom; import org.apache.servicecomb.foundation.ssl.SSLOption; import org.apache.servicecomb.foundation.ssl.SSLOptionFactory; @@ -31,22 +28,13 @@ import org.apache.servicecomb.foundation.vertx.client.ClientPoolManager; import org.apache.servicecomb.foundation.vertx.client.ClientVerticle; import org.apache.servicecomb.foundation.vertx.client.tcp.TcpClientConfig; -import org.apache.servicecomb.swagger.invocation.AsyncResponse; -import org.apache.servicecomb.swagger.invocation.Response; -import org.apache.servicecomb.swagger.invocation.exception.CommonExceptionData; -import org.apache.servicecomb.swagger.invocation.exception.InvocationException; -import org.slf4j.Logger; -import org.slf4j.LoggerFactory; import com.google.common.annotations.VisibleForTesting; import io.vertx.core.DeploymentOptions; import io.vertx.core.Vertx; -import jakarta.ws.rs.core.Response.Status; public class HighwayClient { - private static final Logger LOGGER = LoggerFactory.getLogger(HighwayClient.class); - private static final String SSL_KEY = "highway.consumer"; private ClientPoolManager clientMgr; @@ -86,65 +74,13 @@ TcpClientConfig createTcpClientConfig() { return tcpClientConfig; } - public void send(Invocation invocation, AsyncResponse asyncResp) throws Exception { - invocation.getInvocationStageTrace().startGetConnection(); - HighwayClientConnection tcpClient = findClientPool(invocation); - - invocation.getInvocationStageTrace().startClientFiltersRequest(); - OperationProtobuf operationProtobuf = ProtobufManager.getOrCreateOperation(invocation); - HighwayClientPackage clientPackage = createClientPackage(invocation, operationProtobuf); - - invocation.onStartSendRequest(); - tcpClient.send(clientPackage, ar -> { - invocation.getInvocationStageTrace().finishWriteToBuffer(clientPackage.getFinishWriteToBuffer()); - invocation.getInvocationStageTrace().finishReceiveResponse(); - // 此时是在网络线程中，转换线程 - invocation.getResponseExecutor().execute(() -> { - invocation.getInvocationStageTrace().startClientFiltersResponse(); - if (ar.failed()) { - // 只会是本地异常 - invocation.getInvocationStageTrace().finishClientFiltersResponse(); - if (ar.cause() instanceof TimeoutException) { - // give an accurate cause for timeout exception - // The timeout period of 30000ms has been exceeded while executing GET /xxx for server 1.1.1.1:8080 - // should not copy the message to invocationException to avoid leak server ip address - LOGGER.info("Request timeout, Details: {}.", ar.cause().getMessage()); - - asyncResp.consumerFail(new InvocationException(Status.REQUEST_TIMEOUT, - new CommonExceptionData("Request Timeout."))); - return; - } - asyncResp.consumerFail(ar.cause()); - return; - } - - // 处理应答 - try { - Response response = - HighwayCodec.decodeResponse(invocation, - operationProtobuf, - ar.result()); - invocation.getInvocationStageTrace().finishClientFiltersResponse(); - asyncResp.complete(response); - } catch (Throwable e) { - invocation.getInvocationStageTrace().finishClientFiltersResponse(); - asyncResp.consumerFail(e); - } - }); - }); - } - public HighwayClientPackage createClientPackage(Invocation invocation, OperationProtobuf operationProtobuf) { long msRequestTimeout = invocation.getOperationMeta().getConfig().getMsRequestTimeout(); return new HighwayClientPackage(invocation, operationProtobuf, msRequestTimeout); } public HighwayClientConnection findClientPool(Invocation invocation) { - HighwayClientConnection tcpClient = clientMgr.findClientPool(invocation.isSync()) + return clientMgr.findClientPool(invocation.isSync()) .findOrCreateClient(invocation.getEndpoint().getEndpoint()); - - invocation.getInvocationStageTrace().finishGetConnection(); - - return tcpClient; } } diff --git a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClientFilter.java b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClientFilter.java index 8fe679d8e67..3d657bb9d53 100644 --- a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClientFilter.java +++ b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayClientFilter.java @@ -64,33 +64,30 @@ public CompletableFuture onFilter(Invocation invocation, FilterNode ne OperationProtobuf operationProtobuf = ProtobufManager.getOrCreateOperation(invocation); return send(invocation, operationProtobuf) .thenApply(tcpData -> convertToResponse(invocation, operationProtobuf, tcpData)) - .thenApply(this::convertFailedResponseToException) - .whenComplete((response, throwable) -> invocation.getInvocationStageTrace().finishClientFiltersResponse()); + .thenApply(this::convertFailedResponseToException); } protected CompletableFuture send(Invocation invocation, OperationProtobuf operationProtobuf) { - invocation.getInvocationStageTrace().startGetConnection(); + invocation.getInvocationStageTrace().startConsumerConnection(); HighwayClient highwayClient = ((HighwayTransport) invocation.getTransport()).getHighwayClient(); HighwayClientPackage clientPackage = highwayClient.createClientPackage(invocation, operationProtobuf); HighwayClientConnection clientConnection = highwayClient.findClientPool(invocation); - invocation.getInvocationStageTrace().startClientFiltersRequest(); + invocation.getInvocationStageTrace().finishConsumerConnection(); invocation.onStartSendRequest(); + invocation.getInvocationStageTrace().startConsumerSendRequest(); CompletableFuture sendFuture = clientConnection - .send(clientPackage) - .whenComplete((tcpData, throwable) -> afterSend(invocation, clientPackage)); + .send(clientPackage).whenComplete((r, e) -> invocation.getInvocationStageTrace().finishWaitResponse()); + invocation.getInvocationStageTrace().finishConsumerSendRequest(); + invocation.getInvocationStageTrace().startWaitResponse(); return invocation.optimizeSyncConsumerThread(sendFuture); } - protected void afterSend(Invocation invocation, HighwayClientPackage clientPackage) { - invocation.getInvocationStageTrace().finishWriteToBuffer(clientPackage.getFinishWriteToBuffer()); - invocation.getInvocationStageTrace().finishReceiveResponse(); - - invocation.getInvocationStageTrace().startClientFiltersResponse(); - } - protected Response convertToResponse(Invocation invocation, OperationProtobuf operationProtobuf, TcpData tcpData) { try { - return HighwayCodec.decodeResponse(invocation, operationProtobuf, tcpData); + invocation.getInvocationStageTrace().startConsumerDecodeResponse(); + Response result = HighwayCodec.decodeResponse(invocation, operationProtobuf, tcpData); + invocation.getInvocationStageTrace().finishConsumerDecodeResponse(); + return result; } catch (Exception e) { throw AsyncUtils.rethrow(e); } diff --git a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilter.java b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilter.java index aee833925a8..819fc639958 100644 --- a/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilter.java +++ b/transports/transport-highway/src/main/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilter.java @@ -65,10 +65,12 @@ public CompletableFuture onFilter(Invocation invocation, FilterNode ne protected CompletableFuture decodeRequest(Invocation invocation) { HighwayTransportContext transportContext = invocation.getTransportContext(); try { + invocation.getInvocationStageTrace().startProviderDecodeRequest(); HighwayCodec.decodeRequest(invocation, transportContext.getHeader(), transportContext.getOperationProtobuf(), transportContext.getBodyBuffer()); + invocation.getInvocationStageTrace().finishProviderDecodeRequest(); return CompletableFuture.completedFuture(invocation); } catch (Exception e) { return AsyncUtils.completeExceptionally(e); @@ -94,6 +96,7 @@ protected CompletableFuture encodeResponse(Invocation invocation, Resp msgId, header, bodySchema, response.getResult()); transportContext.setResponseBuffer(respBuffer); + invocation.onEncodeResponseFinish(); return CompletableFuture.completedFuture(response); } catch (Exception e) { // keep highway performance and simple, this encoding/decoding error not need handle by client diff --git a/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilterTest.java b/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilterTest.java index 8856cb79b76..60cbf01543a 100644 --- a/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilterTest.java +++ b/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/HighwayServerCodecFilterTest.java @@ -32,6 +32,7 @@ import org.apache.servicecomb.core.SCBStatus; import org.apache.servicecomb.core.bootstrap.SCBBootstrap; import org.apache.servicecomb.core.definition.OperationMeta; +import org.apache.servicecomb.core.filter.AbstractFilter; import org.apache.servicecomb.core.filter.FilterNode; import org.apache.servicecomb.core.invocation.InvocationFactory; import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; @@ -69,10 +70,18 @@ public class HighwayServerCodecFilterTest { MultiMap headers = MultiMap.caseInsensitiveMultiMap(); - FilterNode nextNode = new FilterNode((invocation, next) -> { - Response response = Response.ok("ok"); - response.setHeaders(headers); - return CompletableFuture.completedFuture(response); + FilterNode nextNode = new FilterNode(new AbstractFilter() { + @Override + public String getName() { + return "test"; + } + + @Override + public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { + Response response = Response.ok("ok"); + response.setHeaders(headers); + return CompletableFuture.completedFuture(response); + } }); static SCBEngine engine; diff --git a/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/TestHighwayClient.java b/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/TestHighwayClient.java index 24a9cfa50ab..014aaa48aba 100644 --- a/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/TestHighwayClient.java +++ b/transports/transport-highway/src/test/java/org/apache/servicecomb/transport/highway/TestHighwayClient.java @@ -17,24 +17,10 @@ package org.apache.servicecomb.transport.highway; -import org.apache.servicecomb.codec.protobuf.definition.OperationProtobuf; -import org.apache.servicecomb.codec.protobuf.definition.ProtobufManager; import org.apache.servicecomb.foundation.common.LegacyPropertyFactory; -import org.apache.servicecomb.core.Endpoint; -import org.apache.servicecomb.core.Invocation; -import org.apache.servicecomb.core.definition.OperationConfig; -import org.apache.servicecomb.core.definition.OperationMeta; -import org.apache.servicecomb.core.executor.ReactiveExecutor; -import org.apache.servicecomb.core.invocation.InvocationStageTrace; -import org.apache.servicecomb.foundation.common.Holder; import org.apache.servicecomb.foundation.vertx.VertxUtils; import org.apache.servicecomb.foundation.vertx.client.ClientPoolManager; -import org.apache.servicecomb.foundation.vertx.client.tcp.AbstractTcpClientPackage; import org.apache.servicecomb.foundation.vertx.client.tcp.TcpClientConfig; -import org.apache.servicecomb.foundation.vertx.client.tcp.TcpData; -import org.apache.servicecomb.foundation.vertx.client.tcp.TcpResponseCallback; -import org.apache.servicecomb.swagger.invocation.Response; -import org.apache.servicecomb.swagger.invocation.exception.InvocationException; import org.junit.AfterClass; import org.junit.Before; import org.junit.BeforeClass; @@ -46,8 +32,6 @@ import io.vertx.core.AbstractVerticle; import io.vertx.core.DeploymentOptions; import io.vertx.core.Vertx; -import io.vertx.core.buffer.Buffer; -import jakarta.ws.rs.core.Response.Status; import mockit.Deencapsulation; import mockit.Mock; import mockit.MockUp; @@ -58,16 +42,6 @@ public class TestHighwayClient { HighwayClient client = new HighwayClient(); - Invocation invocation = Mockito.mock(Invocation.class); - - InvocationStageTrace invocationStageTrace = new InvocationStageTrace(invocation); - - OperationProtobuf operationProtobuf = Mockito.mock(OperationProtobuf.class); - - OperationMeta operationMeta = Mockito.mock(OperationMeta.class); - - Endpoint endpoint = Mockito.mock(Endpoint.class); - Environment environment = Mockito.mock(Environment.class); static long nanoTime = 123; @@ -124,132 +98,4 @@ boolean blockDeploy(Vertx vertx, ClientPoolManager clientMgr = Deencapsulation.getField(client, "clientMgr"); Assertions.assertSame(vertx, Deencapsulation.getField(clientMgr, "vertx")); } - - private Object doTestSend(Vertx vertx, HighwayClientConnectionPool pool, HighwayClientConnection tcpClient, - Object decodedResponse) throws Exception { - new MockUp() { - @Mock - boolean blockDeploy(Vertx vertx, - Class cls, - DeploymentOptions options) { - return true; - } - }; - - new MockUp>() { - @Mock - public HighwayClientConnectionPool findClientPool(boolean sync) { - return pool; - } - }; - - new MockUp() { - @Mock - public OperationProtobuf getOrCreateOperation(Invocation operationMeta) { - return operationProtobuf; - } - }; - - new MockUp() { - @Mock - HighwayClientConnection findOrCreateClient(String endpoint) { - return tcpClient; - } - }; - - new MockUp() { - @Mock - public Buffer encodeRequest(Invocation invocation, OperationProtobuf operationProtobuf, - long msgId) { - return null; - } - - @Mock - Response decodeResponse(Invocation invocation, OperationProtobuf operationProtobuf, TcpData tcpData) - throws Throwable { - if (decodedResponse instanceof Response) { - return (Response) decodedResponse; - } - - throw (Throwable) decodedResponse; - } - }; - - client.init(vertx); - - Mockito.when(invocation.getOperationMeta()).thenReturn(operationMeta); - Mockito.when(invocation.getEndpoint()).thenReturn(endpoint); - Mockito.when(invocation.getEndpoint().getEndpoint()).thenReturn("endpoint"); - Mockito.when(invocation.getResponseExecutor()).thenReturn(new ReactiveExecutor()); - Mockito.when(invocation.getInvocationStageTrace()).thenReturn(invocationStageTrace); - Mockito.when(operationMeta.getConfig()).thenReturn(Mockito.mock(OperationConfig.class)); - - Holder result = new Holder<>(); - client.send(invocation, ar -> result.value = ar.getResult()); - - return result.value; - } - - @Test - public void testSend_success(@Mocked Vertx vertx, @Mocked HighwayClientConnectionPool pool, - @Mocked HighwayClientConnection tcpClient) throws Exception { - new MockUp() { - @Mock - void send(AbstractTcpClientPackage tcpClientPackage, TcpResponseCallback callback) { - callback.success(null); - } - }; - new MockUp() { - @Mock - public long getFinishWriteToBuffer() { - return nanoTime; - } - }; - Object result = doTestSend(vertx, pool, tcpClient, Response.ok("ok")); - - Assertions.assertEquals("ok", result); - Assertions.assertEquals(nanoTime, invocationStageTrace.getStartClientFiltersResponse()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishClientFiltersResponse()); - - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishGetConnection()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishWriteToBuffer()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishReceiveResponse()); - } - - @Test - public void testSend_success_decode_failed(@Mocked Vertx vertx, @Mocked HighwayClientConnectionPool pool, - @Mocked HighwayClientConnection tcpClient) throws Exception { - new MockUp() { - @Mock - void send(AbstractTcpClientPackage tcpClientPackage, TcpResponseCallback callback) { - callback.success(null); - } - }; - - Object result = doTestSend(vertx, pool, tcpClient, new InvocationException(Status.BAD_REQUEST, (Object) "failed")); - - Assertions.assertEquals("failed", ((InvocationException) result).getErrorData()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getStartClientFiltersResponse()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishClientFiltersResponse()); - } - - @Test - public void testSend_failed(@Mocked Vertx vertx, @Mocked HighwayClientConnectionPool pool, - @Mocked HighwayClientConnection tcpClient) throws Exception { - new MockUp() { - @Mock - void send(AbstractTcpClientPackage tcpClientPackage, TcpResponseCallback callback) { - callback.fail(new InvocationException(Status.BAD_REQUEST, (Object) "failed")); - } - }; - - Object result = doTestSend(vertx, - pool, - tcpClient, - null); - - Assertions.assertEquals("failed", ((InvocationException) result).getErrorData()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getStartClientFiltersResponse()); - Assertions.assertEquals(nanoTime, invocationStageTrace.getFinishClientFiltersResponse()); - } } diff --git a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientCodecFilter.java b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientCodecFilter.java index 20a2d6c8dbf..72ff3f00e85 100644 --- a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientCodecFilter.java +++ b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientCodecFilter.java @@ -77,23 +77,17 @@ public RestClientCodecFilter setDecoder(RestClientDecoder decoder) { @Override public CompletableFuture onFilter(Invocation invocation, FilterNode nextNode) { - invocation.getInvocationStageTrace().startGetConnection(); - startClientFiltersRequest(invocation); + invocation.getInvocationStageTrace().startConsumerConnection(); CompletionStage createRequest = transportContextFactory.createHttpClientRequest(invocation).toCompletionStage() - .whenComplete((c, e) -> invocation.getInvocationStageTrace().finishGetConnection()); + .whenComplete((c, e) -> invocation.getInvocationStageTrace().finishConsumerConnection()); return CompletableFuture.completedFuture(null) .thenCompose(v -> createRequest) .thenAccept(httpClientRequest -> prepareTransportContext(invocation, httpClientRequest)) .thenAccept(v -> invocation.onStartSendRequest()) .thenAccept(v -> encoder.encode(invocation)) .thenCompose(v -> nextNode.onFilter(invocation)) - .thenApply(response -> decoder.decode(invocation, response)) - .whenComplete((response, throwable) -> finishClientFiltersResponse(invocation)); - } - - protected void startClientFiltersRequest(Invocation invocation) { - invocation.getInvocationStageTrace().startClientFiltersRequest(); + .thenApply(response -> decoder.decode(invocation, response)); } protected void prepareTransportContext(Invocation invocation, HttpClientRequest httpClientRequest) { @@ -119,8 +113,4 @@ protected void copyExtraHttpHeaders(Invocation invocation, HttpClientRequest htt } }); } - - protected void finishClientFiltersResponse(Invocation invocation) { - invocation.getInvocationStageTrace().finishClientFiltersResponse(); - } } diff --git a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientDecoder.java b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientDecoder.java index cd3c4e89ef0..4d59e9ccf5a 100644 --- a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientDecoder.java +++ b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientDecoder.java @@ -38,6 +38,7 @@ public class RestClientDecoder { private static final Logger LOGGER = LoggerFactory.getLogger(RestClientDecoder.class); public Response decode(Invocation invocation, Response response) { + invocation.getInvocationStageTrace().startConsumerDecodeResponse(); if (response.getResult() instanceof Buffer) { Object result = extractBody(invocation, response); response.entity(result); @@ -47,6 +48,7 @@ public Response decode(Invocation invocation, Response response) { } } + invocation.getInvocationStageTrace().finishConsumerDecodeResponse(); return response; } diff --git a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientEncoder.java b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientEncoder.java index b9c1e16a123..3bca8e89b6c 100644 --- a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientEncoder.java +++ b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientEncoder.java @@ -58,8 +58,10 @@ public class RestClientEncoder { public void encode(Invocation invocation) { try { + invocation.getInvocationStageTrace().startConsumerEncodeRequest(); EncoderSession encoderSession = new EncoderSession(invocation); encoderSession.doEncode(); + invocation.getInvocationStageTrace().finishConsumerEncodeRequest(); } catch (Exception e) { throw new InvocationException(BAD_REQUEST, FAILED_TO_ENCODE_REST_CLIENT_REQUEST, e.getMessage(), e); } @@ -96,8 +98,8 @@ protected void doEncode() throws Exception { } protected void swaggerArgumentsToRequest() throws Exception { - RestCodec - .argsToRest(invocation.getSwaggerArguments(), transportContext.getRestOperationMeta(), requestParameters); + RestCodec.argsToRest(invocation.getSwaggerArguments(), + transportContext.getRestOperationMeta(), requestParameters); } protected void writeCookies(Map cookieMap) { diff --git a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientSender.java b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientSender.java index 30ab71f7d37..1cdd54b1748 100644 --- a/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientSender.java +++ b/transports/transport-rest/transport-rest-client/src/main/java/org/apache/servicecomb/transport/rest/client/RestClientSender.java @@ -23,7 +23,6 @@ import java.util.concurrent.CompletableFuture; import org.apache.servicecomb.core.Invocation; -import org.apache.servicecomb.core.invocation.InvocationStageTrace; import org.apache.servicecomb.foundation.common.http.HttpStatus; import org.apache.servicecomb.foundation.vertx.executor.VertxContextExecutor; import org.apache.servicecomb.foundation.vertx.http.ReadStreamPart; @@ -62,6 +61,7 @@ public RestClientSender(Invocation invocation) { } public CompletableFuture send() { + invocation.getInvocationStageTrace().startConsumerSendRequest(); httpClientRequest.response().compose(response -> processResponse(response).compose(buffer -> { future.complete(createResponse(response, buffer)); return Future.succeededFuture(); @@ -78,7 +78,8 @@ protected void runInVertxContext() { if (e != null) { future.completeExceptionally(e); } - writeFinished(); + invocation.getInvocationStageTrace().finishConsumerSendRequest(); + invocation.getInvocationStageTrace().startWaitResponse(); }); } @@ -102,10 +103,6 @@ protected CompletableFuture sendInVertxContext() { return sendFiles(); } - private void writeFinished() { - invocation.getInvocationStageTrace().finishWriteToBuffer(System.nanoTime()); - } - protected CompletableFuture sendFiles() { CompletableFuture sendFileFuture = CompletableFuture.completedFuture(null); @@ -159,7 +156,7 @@ protected Response createResponse(HttpClientResponse httpClientResponse, Object } protected void afterSend(Response response, Throwable throwable) { - processMetrics(); + invocation.getInvocationStageTrace().finishWaitResponse(); if (throwable != null) { LOGGER.error("rest client send or receive failed, operation={}, method={}, endpoint={}, uri={}.", @@ -169,12 +166,4 @@ protected void afterSend(Response response, Throwable throwable) { httpClientRequest.getURI()); } } - - protected void processMetrics() { - InvocationStageTrace stageTrace = invocation.getInvocationStageTrace(); - // even failed and did not receive response, still set time for it - // that will help to know the real timeout time - stageTrace.finishReceiveResponse(); - stageTrace.startClientFiltersResponse(); - } }