You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@dubbo.apache.org by al...@apache.org on 2022/02/06 04:32:36 UTC
[dubbo] branch 3.0 updated: [3.0] Make Profiler work in Injvm invoke (#9619)
This is an automated email from the ASF dual-hosted git repository.
albumenj pushed a commit to branch 3.0
in repository https://gitbox.apache.org/repos/asf/dubbo.git
The following commit(s) were added to refs/heads/3.0 by this push:
new 2fca467 [3.0] Make Profiler work in Injvm invoke (#9619)
2fca467 is described below
commit 2fca4677825ac4ee4449176783cdba9d81c545e0
Author: Albumen Kevin <jh...@gmail.com>
AuthorDate: Sun Feb 6 12:32:23 2022 +0800
[3.0] Make Profiler work in Injvm invoke (#9619)
---
.../org/apache/dubbo/common/profiler/Profiler.java | 7 ++--
.../apache/dubbo/common/profiler/ProfilerTest.java | 16 ++++-----
.../dubbo/rpc/filter/ProfilerServerFilter.java | 14 +++++---
.../dubbo/rpc/proxy/InvokerInvocationHandler.java | 42 ++++++++++------------
.../dubbo/rpc/protocol/injvm/InjvmInvoker.java | 4 +++
5 files changed, 44 insertions(+), 39 deletions(-)
diff --git a/dubbo-common/src/main/java/org/apache/dubbo/common/profiler/Profiler.java b/dubbo-common/src/main/java/org/apache/dubbo/common/profiler/Profiler.java
index 9ef8c91..3d1250f 100644
--- a/dubbo-common/src/main/java/org/apache/dubbo/common/profiler/Profiler.java
+++ b/dubbo-common/src/main/java/org/apache/dubbo/common/profiler/Profiler.java
@@ -59,10 +59,9 @@ public class Profiler {
}
public static String buildDetail(ProfilerEntry entry) {
- ProfilerEntry firstEntry = entry.getFirst();
- long totalUsageTime = firstEntry.getEndTime() - firstEntry.getStartTime();
- return "Start time: " + firstEntry.getStartTime() + "\n" +
- String.join("\n", buildDetail(firstEntry, firstEntry.getStartTime(), totalUsageTime, 0));
+ long totalUsageTime = entry.getEndTime() - entry.getStartTime();
+ return "Start time: " + entry.getStartTime() + "\n" +
+ String.join("\n", buildDetail(entry, entry.getStartTime(), totalUsageTime, 0));
}
public static List<String> buildDetail(ProfilerEntry entry, long startTime, long totalUsageTime, int depth) {
diff --git a/dubbo-common/src/test/java/org/apache/dubbo/common/profiler/ProfilerTest.java b/dubbo-common/src/test/java/org/apache/dubbo/common/profiler/ProfilerTest.java
index 05f740f..d235264 100644
--- a/dubbo-common/src/test/java/org/apache/dubbo/common/profiler/ProfilerTest.java
+++ b/dubbo-common/src/test/java/org/apache/dubbo/common/profiler/ProfilerTest.java
@@ -68,14 +68,14 @@ public class ProfilerTest {
* | +-[ Offset: 4.696655ms; Usage: 0.000195ms, 0% ] 1-2-6-8
* +-[ Offset: 4.721044ms; Usage: 0.000270ms, 0% ] 1-9
*/
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(two));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(three));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(four));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(five));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(six));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(seven));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(eight));
- Assertions.assertEquals(Profiler.buildDetail(one), Profiler.buildDetail(nine));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(two));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(three));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(four));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(five));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(six));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(seven));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(eight));
+ Assertions.assertNotEquals(Profiler.buildDetail(one), Profiler.buildDetail(nine));
}
@Test
diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/ProfilerServerFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/ProfilerServerFilter.java
index 553c30a..3dba1d1 100644
--- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/ProfilerServerFilter.java
+++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/ProfilerServerFilter.java
@@ -44,7 +44,13 @@ public class ProfilerServerFilter implements Filter, BaseFilter.Listener {
@Override
public Result invoke(Invoker<?> invoker, Invocation invocation) throws RpcException {
if (ProfilerSwitch.isEnableSimpleProfiler()) {
- ProfilerEntry bizProfiler = Profiler.start("Receive request. Server invoke begin.");
+ ProfilerEntry bizProfiler;
+ Object localInvokeProfiler = invocation.get(Profiler.PROFILER_KEY);
+ if (localInvokeProfiler instanceof ProfilerEntry) {
+ bizProfiler = Profiler.enter((ProfilerEntry) localInvokeProfiler, "Receive request. Local server invoke begin.");
+ } else {
+ bizProfiler = Profiler.start("Receive request. Server invoke begin.");
+ }
invocation.put(Profiler.PROFILER_KEY, bizProfiler);
invocation.put(CLIENT_IP_KEY, RpcContext.getServiceContext().getRemoteAddressString());
}
@@ -69,7 +75,7 @@ public class ProfilerServerFilter implements Filter, BaseFilter.Listener {
ProfilerEntry profiler = Profiler.release((ProfilerEntry) fromInvocation);
invocation.put(Profiler.PROFILER_KEY, profiler);
- dumpIfNeed(invoker, invocation, profiler);
+ dumpIfNeed(invoker, invocation,(ProfilerEntry) fromInvocation);
}
}
}
@@ -90,11 +96,11 @@ public class ProfilerServerFilter implements Filter, BaseFilter.Listener {
attachment.append(entry.getKey()).append("=").append(entry.getValue()).append(";\n");
}
- logger.warn(String.format("[Dubbo-Provider] execute service %s#%s cost %d.%06d ms, this invocation almost (maybe already) timeout\n" +
+ logger.warn(String.format("[Dubbo-Provider] execute service %s#%s cost %d.%06d ms, this invocation almost (maybe already) timeout. Timeout: %dms\n" +
"client: %s\n" +
"invocation context:\n%s" +
"thread info: \n%s",
- invocation.getTargetServiceUniqueName(), invocation.getMethodName(), usage / 1000_000, usage % 1000_000,
+ invocation.getTargetServiceUniqueName(), invocation.getMethodName(), usage / 1000_000, usage % 1000_000, timeout,
invocation.get(CLIENT_IP_KEY), attachment, Profiler.buildDetail(profiler)));
}
}
diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/proxy/InvokerInvocationHandler.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/proxy/InvokerInvocationHandler.java
index 8af03a3..0672e02 100644
--- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/proxy/InvokerInvocationHandler.java
+++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/proxy/InvokerInvocationHandler.java
@@ -87,39 +87,35 @@ public class InvokerInvocationHandler implements InvocationHandler {
if (ProfilerSwitch.isEnableSimpleProfiler()) {
ProfilerEntry parentProfiler = Profiler.getBizProfiler();
ProfilerEntry bizProfiler;
- boolean containsBizProfiler = false;
if (parentProfiler != null) {
- containsBizProfiler = true;
- bizProfiler = Profiler.enter(parentProfiler, "Receive request. Client invoke begin.");
+ bizProfiler = Profiler.enter(parentProfiler, "Receive request. Client invoke begin. ServiceKey: " + serviceKey + " MethodName:" + methodName);
} else {
- bizProfiler = Profiler.start("Receive request. Client invoke begin.");
+ bizProfiler = Profiler.start("Receive request. Client invoke begin. ServiceKey: " + serviceKey + " MethodName:" + methodName);
}
rpcInvocation.put(Profiler.PROFILER_KEY, bizProfiler);
try {
return invoker.invoke(rpcInvocation).recreate();
} finally {
Profiler.release(bizProfiler);
- if (!containsBizProfiler) {
- int timeout;
- Object timeoutKey = rpcInvocation.getObjectAttachmentWithoutConvert(TIMEOUT_KEY);
- if (timeoutKey instanceof Integer) {
- timeout = (Integer) timeoutKey;
- } else {
- timeout = url.getMethodPositiveParameter(methodName, TIMEOUT_KEY, DEFAULT_TIMEOUT);
+ int timeout;
+ Object timeoutKey = rpcInvocation.getObjectAttachmentWithoutConvert(TIMEOUT_KEY);
+ if (timeoutKey instanceof Integer) {
+ timeout = (Integer) timeoutKey;
+ } else {
+ timeout = url.getMethodPositiveParameter(methodName, TIMEOUT_KEY, DEFAULT_TIMEOUT);
+ }
+ long usage = bizProfiler.getEndTime() - bizProfiler.getStartTime();
+ if ((usage / (1000_000L * ProfilerSwitch.getWarnPercent())) > timeout) {
+ StringBuilder attachment = new StringBuilder();
+ for (Map.Entry<String, Object> entry : rpcInvocation.getObjectAttachments().entrySet()) {
+ attachment.append(entry.getKey()).append("=").append(entry.getValue()).append(";\n");
}
- long usage = bizProfiler.getEndTime() - bizProfiler.getStartTime();
- if ((usage / (1000_000L * ProfilerSwitch.getWarnPercent())) > timeout) {
- StringBuilder attachment = new StringBuilder();
- for (Map.Entry<String, Object> entry : rpcInvocation.getObjectAttachments().entrySet()) {
- attachment.append(entry.getKey()).append("=").append(entry.getValue()).append(";\n");
- }
- logger.warn(String.format("[Dubbo-Consumer] execute service %s#%s cost %d.%06d ms, this invocation almost (maybe already) timeout\n" +
- "invocation context:\n%s" +
- "thread info: \n%s",
- protocolServiceKey, methodName, usage / 1000_000, usage % 1000_000,
- attachment, Profiler.buildDetail(bizProfiler)));
- }
+ logger.warn(String.format("[Dubbo-Consumer] execute service %s#%s cost %d.%06d ms, this invocation almost (maybe already) timeout. Timeout: %dms\n" +
+ "invocation context:\n%s" +
+ "thread info: \n%s",
+ protocolServiceKey, methodName, usage / 1000_000, usage % 1000_000, timeout,
+ attachment, Profiler.buildDetail(bizProfiler)));
}
}
}
diff --git a/dubbo-rpc/dubbo-rpc-injvm/src/main/java/org/apache/dubbo/rpc/protocol/injvm/InjvmInvoker.java b/dubbo-rpc/dubbo-rpc-injvm/src/main/java/org/apache/dubbo/rpc/protocol/injvm/InjvmInvoker.java
index 959b031..7f82aae 100644
--- a/dubbo-rpc/dubbo-rpc-injvm/src/main/java/org/apache/dubbo/rpc/protocol/injvm/InjvmInvoker.java
+++ b/dubbo-rpc/dubbo-rpc-injvm/src/main/java/org/apache/dubbo/rpc/protocol/injvm/InjvmInvoker.java
@@ -44,7 +44,9 @@ import java.util.Objects;
import java.util.concurrent.CompletableFuture;
import java.util.concurrent.ExecutorService;
+import static org.apache.dubbo.common.constants.CommonConstants.DEFAULT_TIMEOUT;
import static org.apache.dubbo.common.constants.CommonConstants.LOCALHOST_VALUE;
+import static org.apache.dubbo.common.constants.CommonConstants.TIMEOUT_KEY;
import static org.apache.dubbo.rpc.Constants.ASYNC_KEY;
/**
@@ -97,6 +99,8 @@ public class InjvmInvoker<T> extends AbstractInvoker<T> {
invocation.setAttachment(Constants.TOKEN_KEY, serverURL.getParameter(Constants.TOKEN_KEY));
}
+ invocation.setAttachment(TIMEOUT_KEY, invoker.getUrl().getMethodPositiveParameter(invocation.getMethodName(), TIMEOUT_KEY, DEFAULT_TIMEOUT));
+
String desc = ReflectUtils.getDesc(invocation.getParameterTypes());
// recreate invocation ---> deep copy parameters