From d56d8d9d323958c8709d36aff0a0769019521d43 Mon Sep 17 00:00:00 2001 From: xiuyuhang <442367943@qq.com> Date: Wed, 9 Jan 2019 11:01:45 +0800 Subject: [PATCH 1/5] Fix timeout filter not work in async way. --- .../dubbo/rpc/filter/TimeoutFilter.java | 33 +++++++++++++------ 1 file changed, 23 insertions(+), 10 deletions(-) diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java index ad783efd992..d2baff2d933 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java @@ -36,21 +36,34 @@ public class TimeoutFilter implements Filter { private static final Logger logger = LoggerFactory.getLogger(TimeoutFilter.class); + private static final String TIMEOUT_FILTER_START_TIME = "timeout_filter_start_time"; + @Override public Result invoke(Invoker invoker, Invocation invocation) throws RpcException { long start = System.currentTimeMillis(); - Result result = invoker.invoke(invocation); - long elapsed = System.currentTimeMillis() - start; - if (invoker.getUrl() != null - && elapsed > invoker.getUrl().getMethodParameter(invocation.getMethodName(), - "timeout", Integer.MAX_VALUE)) { - if (logger.isWarnEnabled()) { - logger.warn("invoke time out. method: " + invocation.getMethodName() - + " arguments: " + Arrays.toString(invocation.getArguments()) + " , url is " - + invoker.getUrl() + ", invoke elapsed " + elapsed + " ms."); + if (invocation.getAttachments() != null) { + invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); + } + return invoker.invoke(invocation); + } + + @Override + public Result onResponse(Result result, Invoker invoker, Invocation invocation) { + String startAttach = invocation.getAttachment(TIMEOUT_FILTER_START_TIME); + if (startAttach != null) { + long elapsed = System.currentTimeMillis() - Long.valueOf(startAttach); + if (invoker.getUrl() != null + && elapsed > invoker.getUrl().getMethodParameter(invocation.getMethodName(), + "timeout", Integer.MAX_VALUE)) { + if (logger.isWarnEnabled()) { + logger.warn("invoke time out. method: " + invocation.getMethodName() + + " arguments: " + Arrays.toString(invocation.getArguments()) + " , url is " + + invoker.getUrl() + ", invoke elapsed " + elapsed + " ms."); + } } + // we should not change the attachments of the invocation. + invocation.getAttachments().remove(TIMEOUT_FILTER_START_TIME); } return result; } - } From abe5600e6c1ff0a594cad36b5f8b1cc029d7e9c1 Mon Sep 17 00:00:00 2001 From: xiuyuhang <442367943@qq.com> Date: Wed, 9 Jan 2019 11:06:35 +0800 Subject: [PATCH 2/5] optimize logic. --- .../main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java index d2baff2d933..2ad2786ba27 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java @@ -40,8 +40,8 @@ public class TimeoutFilter implements Filter { @Override public Result invoke(Invoker invoker, Invocation invocation) throws RpcException { - long start = System.currentTimeMillis(); if (invocation.getAttachments() != null) { + long start = System.currentTimeMillis(); invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); } return invoker.invoke(invocation); From c8c1f7b44c4fcb1db7a665d811917fa2d7aff31c Mon Sep 17 00:00:00 2001 From: xiuyuhang <442367943@qq.com> Date: Mon, 14 Jan 2019 17:45:04 +0800 Subject: [PATCH 3/5] optimize binding params --- .../java/org/apache/dubbo/rpc/filter/TimeoutFilter.java | 7 +++++++ 1 file changed, 7 insertions(+) diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java index 2ad2786ba27..6153e340730 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java @@ -25,6 +25,7 @@ import org.apache.dubbo.rpc.Invoker; import org.apache.dubbo.rpc.Result; import org.apache.dubbo.rpc.RpcException; +import org.apache.dubbo.rpc.RpcInvocation; import java.util.Arrays; @@ -43,6 +44,12 @@ public Result invoke(Invoker invoker, Invocation invocation) throws RpcExcept if (invocation.getAttachments() != null) { long start = System.currentTimeMillis(); invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); + } else { + if (invocation instanceof RpcInvocation) { + RpcInvocation invc = (RpcInvocation) invocation; + long start = System.currentTimeMillis(); + invc.setAttachment(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); + } } return invoker.invoke(invocation); } From 6d1c1227b3aad22ecd54c050a9054d98799e63d7 Mon Sep 17 00:00:00 2001 From: xiuyuhang <442367943@qq.com> Date: Wed, 23 Jan 2019 20:50:55 +0800 Subject: [PATCH 4/5] Use map to keep Invocation and startTime. --- .../dubbo/rpc/filter/TimeoutFilter.java | 25 ++++++------------- 1 file changed, 8 insertions(+), 17 deletions(-) diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java index 6153e340730..d1dbacf716d 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java @@ -25,9 +25,10 @@ import org.apache.dubbo.rpc.Invoker; import org.apache.dubbo.rpc.Result; import org.apache.dubbo.rpc.RpcException; -import org.apache.dubbo.rpc.RpcInvocation; import java.util.Arrays; +import java.util.Map; +import java.util.concurrent.ConcurrentHashMap; /** * Log any invocation timeout, but don't stop server from running @@ -37,28 +38,20 @@ public class TimeoutFilter implements Filter { private static final Logger logger = LoggerFactory.getLogger(TimeoutFilter.class); - private static final String TIMEOUT_FILTER_START_TIME = "timeout_filter_start_time"; + private static final Map START_TIME_KEEPER = new ConcurrentHashMap<>(); @Override public Result invoke(Invoker invoker, Invocation invocation) throws RpcException { - if (invocation.getAttachments() != null) { - long start = System.currentTimeMillis(); - invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); - } else { - if (invocation instanceof RpcInvocation) { - RpcInvocation invc = (RpcInvocation) invocation; - long start = System.currentTimeMillis(); - invc.setAttachment(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); - } - } + long start = System.currentTimeMillis(); + START_TIME_KEEPER.put(invocation, start); return invoker.invoke(invocation); } @Override public Result onResponse(Result result, Invoker invoker, Invocation invocation) { - String startAttach = invocation.getAttachment(TIMEOUT_FILTER_START_TIME); - if (startAttach != null) { - long elapsed = System.currentTimeMillis() - Long.valueOf(startAttach); + Long startTime = START_TIME_KEEPER.remove(invocation); + if (startTime != null) { + long elapsed = System.currentTimeMillis() - startTime; if (invoker.getUrl() != null && elapsed > invoker.getUrl().getMethodParameter(invocation.getMethodName(), "timeout", Integer.MAX_VALUE)) { @@ -68,8 +61,6 @@ public Result onResponse(Result result, Invoker invoker, Invocation invocatio + invoker.getUrl() + ", invoke elapsed " + elapsed + " ms."); } } - // we should not change the attachments of the invocation. - invocation.getAttachments().remove(TIMEOUT_FILTER_START_TIME); } return result; } From a19cb2ab9426a76d68038634ccdb8488647f42d5 Mon Sep 17 00:00:00 2001 From: xiuyuhang <442367943@qq.com> Date: Thu, 24 Jan 2019 11:41:04 +0800 Subject: [PATCH 5/5] revert code --- .../dubbo/rpc/filter/TimeoutFilter.java | 23 ++++++++++++------- 1 file changed, 15 insertions(+), 8 deletions(-) diff --git a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java index d1dbacf716d..c00689fc1c8 100644 --- a/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java +++ b/dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java @@ -25,10 +25,9 @@ import org.apache.dubbo.rpc.Invoker; import org.apache.dubbo.rpc.Result; import org.apache.dubbo.rpc.RpcException; +import org.apache.dubbo.rpc.RpcInvocation; import java.util.Arrays; -import java.util.Map; -import java.util.concurrent.ConcurrentHashMap; /** * Log any invocation timeout, but don't stop server from running @@ -38,20 +37,28 @@ public class TimeoutFilter implements Filter { private static final Logger logger = LoggerFactory.getLogger(TimeoutFilter.class); - private static final Map START_TIME_KEEPER = new ConcurrentHashMap<>(); + private static final String TIMEOUT_FILTER_START_TIME = "timeout_filter_start_time"; @Override public Result invoke(Invoker invoker, Invocation invocation) throws RpcException { - long start = System.currentTimeMillis(); - START_TIME_KEEPER.put(invocation, start); + if (invocation.getAttachments() != null) { + long start = System.currentTimeMillis(); + invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); + } else { + if (invocation instanceof RpcInvocation) { + RpcInvocation invc = (RpcInvocation) invocation; + long start = System.currentTimeMillis(); + invc.setAttachment(TIMEOUT_FILTER_START_TIME, String.valueOf(start)); + } + } return invoker.invoke(invocation); } @Override public Result onResponse(Result result, Invoker invoker, Invocation invocation) { - Long startTime = START_TIME_KEEPER.remove(invocation); - if (startTime != null) { - long elapsed = System.currentTimeMillis() - startTime; + String startAttach = invocation.getAttachment(TIMEOUT_FILTER_START_TIME); + if (startAttach != null) { + long elapsed = System.currentTimeMillis() - Long.valueOf(startAttach); if (invoker.getUrl() != null && elapsed > invoker.getUrl().getMethodParameter(invocation.getMethodName(), "timeout", Integer.MAX_VALUE)) {