Skip to content

Fix timeout filter not work in async way. #3174

New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Merged
chickenlj merged 5 commits into from
Jan 24, 2019
Merged

Fix timeout filter not work in async way. #3174

Changes from 3 commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
d56d8d9
Fix timeout filter not work in async way.
carryxyh Jan 9, 2019
abe5600
optimize logic.
carryxyh Jan 9, 2019
c8c1f7b
optimize binding params
carryxyh Jan 14, 2019
6d1c122
Use map to keep Invocation and startTime.
carryxyh Jan 23, 2019
a19cb2a
revert code
carryxyh Jan 24, 2019
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
42 changes: 31 additions & 11 deletions dubbo-rpc/dubbo-rpc-api/src/main/java/org/apache/dubbo/rpc/filter/TimeoutFilter.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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;

Expand All @@ -36,21 +37,40 @@ 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();
Comment thread
chickenlj marked this conversation as resolved.
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) {
Copy link
Copy Markdown
Contributor

@khanimteyaz khanimteyaz Jan 12, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

If there is no attachement for invocation, to handle fix timeout should we care to create a attachment and set TIMEOUT_FILTER_START_TIME ? What do you say?

Copy link
Copy Markdown
Member Author

@carryxyh carryxyh Jan 14, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Seems like you are right...
Great suggestion, I will fix it.
👍

Copy link
Copy Markdown
Member Author

@carryxyh carryxyh Jan 14, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have fix this place.
Seems like only RpcInvocation can set attachments.

Copy link
Copy Markdown
Contributor

@khanimteyaz khanimteyaz Jan 14, 2019 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@carryxyh
I was thinking to have the responsibility of assigning a default TIMEOUT_FILTER_START_TIME in RpcInvocation, but then realized that, I am going in wrong direction and it will landed up mixing RpcInvocation Responsibility with TimerFilter.

Just thinking loud here (please bear with me 😄 ), should we create a FilterWrapper and use it to store framework code related internal properties here, it may give us better way of separating object information. e.g

Class FilterWrapper {
  private Invocation target;
  private Map<String,Object> properties = new HashMap<>();
   FilterWrapper (Invocation invocation)  {
      this.target = invocation;
  }
  public void addProperties(String key,Object value) {
   properties.put(key,value);
} 
   public Map<String,Object> getProperties() {
     return this.properties;
 }
   public Map<String,Object> getAttachment() {
      this.target.getAttachment();
  }
  ..........
_more getter and setter or deleter as per needs_
  ....
}
wrapper=FilterWrapper.of(invocation); 
wrapper.addProperties(TIMEOUT_FILTER_START_TIME, String.valueOf(start));

So even in future we need to keep add internal properties we may not be landed up overriding user propvided values.
What do you say?

Copy link
Copy Markdown
Contributor

@chickenlj chickenlj Jan 23, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

@khanimteyaz That's interesting, but if we add an extra properties just like you did in FilterWrapper, we need to further figure out how to pass the properties onto the wire. But at present invocation is the only carrier, so everything needs to finally go into invocation to get transferred.

long start = System.currentTimeMillis();
invocation.getAttachments().put(TIMEOUT_FILTER_START_TIME, String.valueOf(start));
Copy link
Copy Markdown
Contributor

@chickenlj chickenlj Jan 23, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Be careful that this attachment TIMEOUT_FILTER_START_TIME will be passed throughout the RPC chain because of the drawback of RpcContext. #3017

Copy link
Copy Markdown
Member Author

@carryxyh carryxyh Jan 23, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is indeed a problem. I personally think that my revision is rather stubborn. But haven't found a better way to pass the start time. . .

Maybe using a DataStore or sth else?

Copy link
Copy Markdown
Contributor

@chickenlj chickenlj Jan 24, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Now I think the previous way you give is better, please see my comments below.
So what do you think now? Would you please revert the code?

Copy link
Copy Markdown
Member Author

@carryxyh carryxyh Jan 24, 2019

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I have checked the code.
As you said, the timeoutfilter does not affect the RpcContext, nor does it affect the invocation downstream of the call chain. I have reverted the code.

} else {
if (invocation instanceof RpcInvocation) {
RpcInvocation invc = (RpcInvocation) invocation;
long start = System.currentTimeMillis();
invc.setAttachment(TIMEOUT_FILTER_START_TIME, String.valueOf(start));
}
}
return result;
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);
Comment thread
chickenlj marked this conversation as resolved.
Outdated
}
return result;
}
}
⚡