core: delay sending cancel request on client-side when deadline expires by ran-su · Pull Request #6328 · grpc/grpc-java

ran-su · 2019-10-23T21:53:51Z

When deadline expires, both the client and the server try to cancel the stream. There is a race between server receiving the cancellation from the client and the server cancelling the stream, which changes the final status of the stream from the server's perspective. If the former wins, server sees CANCELLED. If the latter wins, server sees DEADLINE_EXCEEDED.

Because ServerCall.Listener doesn't pass the final status to the server-side application, this ambiguity isn't a problem in most cases. However, the status is passed to ServerStreamTracer, and thus will cause confusion in stats.

This PR delays the client-side cancellation in case of deadline exceeded by a small margin, thus makes DEADLINE_EXCEEDED be reported most of the time.

b/118879795

zhangkun83

We should also handle the case where the

zhangkun83

LGTM.

@ejona86 it's ready for you to review now.

ejona86 · 2019-11-11T22:36:18Z

+        stream.cancel(statusFromCancelled(context));
+      } else {
+        if (deadlineCancellationSendToServerFuture == null) {
+          deadlineCancellationSendToServerFuture = deadlineCancellationExecutor.schedule(


I don't see anything here that triggers the application to be called immediately when the deadline is exceeded. Won't this delay all deadline notifications to the application by 1 second?

All notifications to the application are sent in startDeadlineNotifyApplicationTimer(), which follows the initial deadline.

In the case calloption's deadline equals to the context deadline, startDeadlineNotifyApplicationTimer() is not called when the ClientCall is started.

zhangkun83 · 2019-11-22T01:48:13Z

+      deadlineCancellationNotifyApplicationFuture =
+          startDeadlineNotifyApplicationTimer(effectiveDeadline, observer);
+    } else {
+      if (cancellationListener instanceof ClientCallImpl.ContextCancellationListener) {


It's always the case. You can change cancellationListener's type to ContextCancellationListener to avoid the casting.

zhangkun83 · 2019-11-22T02:03:13Z

+          startDeadlineNotifyApplicationTimer(effectiveDeadline, observer);
+    } else {
+      if (cancellationListener instanceof ClientCallImpl.ContextCancellationListener) {
+        ((ContextCancellationListener) cancellationListener).setObserver(observer);


You probably need to move line 320 (context.addListener()) to after this else-block, so that if the deadline is exceeded immediately, observer can still be notified.

zhangkun83 · 2019-11-22T02:08:23Z

+        if (observer != null) {
+          Status status = statusFromCancelled(context);
+          deadlineCancellationSendToServerFuture = startDeadlineSendCancelToServerTimer(status);
+          executeCloseObserverInContext(observer, status);


These two lines are repeated in DeadlineExceededNotifyApplicationTimer. Since this is the core logic of delayed cancellation, it should be in its own method (delayedCancelOnDeadlineExceeded(status, observer)), and the two cases just call it.

zhangkun83 · 2019-11-22T02:11:09Z

+  }

-        callExecutor.execute(new CloseInContext());
+  private void executeCloseObserverInContext(final Listener<RespT> observer, final Status status) {


There are other two call sites of closeObserver() at the start of startInternal() that can be simplified by calling this method.

zhangkun83

@ejona86. I believe @ran-su has addressed your last comment. You can take another look.

zhangkun83 · 2019-12-09T19:32:02Z

+        TimeUnit.NANOSECONDS);
+  }
+
+  private Status buildDeadlineExceededStatusWithRemainingNanos(long remainingNanos) {


nit: this method is used only once, and the only caller is very short. It may be more readable as an inline codeblock at the call site.

zhangkun83 · 2019-12-09T19:33:47Z

+    }
+  }
+
+  private ScheduledFuture<?> startDeadlineSendCancelToServerTimer(final Status status) {


nit: now that there is only one caller of this method, it would be more readable to merge it into its caller.

ejona86 · 2019-12-09T22:21:58Z

+  // cancelling the stream, which changes the final status of the stream from the server's
+  // perspective.
+  // Mitigate this by introduce a delay for client to send the cancel request.(b/118879795)
+  // This only impacts server statistics.


The language here is a bit fragmented. How about

When a deadline is exceeded, there is a race between the server receiving the cancellation from the client and the server cancelling the stream itself. If the client's cancellation is received first, then the stream's status will be CANCELLED instead of DEADLINE_EXCEEDED. This prevents server monitoring from noticing high rate of DEADLINE_EXCEEDED, a common monitoring metric (b/118879795). Mitigate this by delayed sending of the client's cancellation.

ejona86 · 2019-12-09T22:32:33Z

    @Override
-    public void cancelled(Context context) {
-      stream.cancel(statusFromCancelled(context));
+    public void cancelled(final Context context) {


Remove final (revert change)

ejona86 · 2019-12-09T23:03:41Z

    }
  }

+  @SuppressWarnings("unchecked")


Why is this necessary?

ejona86 · 2019-12-09T23:35:34Z

+      if (context.getDeadline() == null || !context.getDeadline().isExpired()) {
+        stream.cancel(statusFromCancelled(context));
+      } else {
+        if (observer != null) {


I'm not very comfortable with this doing nothing if observer is null. It looks like an optimization, but it requires multiple pieces to behave in a particular way. I think it would be better to add the optimization to delayedCancelOnDeadlineExceeded(): if deadlineCancellationSendToServerFuture is already non-null (the method has already been called), return early. Note there's a race there, but there's a race there already (and so I'll have another comment about it elsewhere).

Changing this would also mean we could pass the Listener in the constructor and get rid of setObserver().

ejona86

One important change, but should be easy.

ejona86 · 2019-12-11T22:47:28Z

+      deadlineCancellationNotifyApplicationFuture =
+          startDeadlineNotifyApplicationTimer(effectiveDeadline, observer);
    }
+    cancellationListener = new ContextCancellationListener(observer);


I don't think this is thread-safe, since this field is read in removeContextListenerAndCancelDeadlineFuture(). I think you need to just move this initialization up higher before stream.start().

core: delay sending cancel request on client-side when deadline expires

fbd71c3

ran-su requested a review from zhangkun83 October 23, 2019 22:32

creamsoup reviewed Oct 24, 2019

View reviewed changes

ran-su and others added 2 commits October 23, 2019 20:53

address review comments.

f719fab

fix comment style.

a47c6ac

zhangkun83 requested a review from ejona86 October 24, 2019 17:35

zhangkun83 reviewed Oct 24, 2019

View reviewed changes

Comment thread core/src/main/java/io/grpc/internal/ClientCallImpl.java Outdated

Comment thread core/src/main/java/io/grpc/internal/ClientCallImpl.java Outdated

core: notify application when deadline exceeded

dd5623c

ran-su requested a review from zhangkun83 October 24, 2019 22:19

zhangkun83 reviewed Oct 25, 2019

View reviewed changes

set the cancel stream timer within the notify app timer.

883df49

ran-su requested a review from zhangkun83 October 25, 2019 23:41

zhangkun83 reviewed Oct 28, 2019

View reviewed changes

address review comments

faf926b

ran-su requested a review from zhangkun83 October 29, 2019 21:29

address review comment

5cd33d8

zhangkun83 reviewed Oct 30, 2019

View reviewed changes

add delay for deadline cancel from context. address review comments.

f2cba8f

ran-su force-pushed the race-ddl-cancel branch from 8095621 to f2cba8f Compare October 31, 2019 20:52

undo unnecessary code moves.

56b802b

ran-su requested a review from zhangkun83 November 1, 2019 21:35

zhangkun83 reviewed Nov 6, 2019

View reviewed changes

ran-su added 3 commits November 7, 2019 14:42

address review comments.

0f6fa0f

resolve conflict

62bde76

resolve conflict

1477e33

ran-su force-pushed the race-ddl-cancel branch from 76c8bd8 to 1477e33 Compare November 8, 2019 17:59

Merge branch 'master' into race-ddl-cancel

54e21a8

ran-su requested a review from zhangkun83 November 8, 2019 21:25

zhangkun83 reviewed Nov 8, 2019

View reviewed changes

ejona86 reviewed Nov 11, 2019

View reviewed changes

ran-su added 2 commits November 12, 2019 17:15

improve comment msg

ffaaf4f

cover deadline from context case.

0a8e1d9

zhangkun83 reviewed Nov 22, 2019

View reviewed changes

address review comments.

1e29de9

zhangkun83 reviewed Dec 9, 2019

View reviewed changes

inline a function which has only one call site.

245b230

ejona86 reviewed Dec 9, 2019

View reviewed changes

address review comments.

c905810

ejona86 approved these changes Dec 11, 2019

View reviewed changes

move initialization of contextCancellationListener above stream.start().

97a58b1

ran-su merged commit f6544bf into grpc:master Dec 16, 2019

ran-su deleted the race-ddl-cancel branch December 16, 2019 17:58

lock Bot locked as resolved and limited conversation to collaborators Mar 17, 2020

Conversation

ran-su commented Oct 23, 2019 • edited by zhangkun83 Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

zhangkun83 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

zhangkun83 left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

zhangkun83 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Uh oh!

ejona86 left a comment

Choose a reason for hiding this comment

Uh oh!

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

ran-su commented Oct 23, 2019 •

edited by zhangkun83

Loading