[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #259

fl4via · 2022-02-10T21:02:01Z

… ack timeout wait to a loop to protect against spurious wakes. Plus, check for other causes for being awakened before assuming the message ack timeout has expired.

The other causes for being awaked are all points where notifyAll was invoked. So, we need to check for closeReceived, closeCalled & !eof, and cancelSent before checking if the timeout expired withou a message ack

Jiras: https://issues.redhat.com/browse/REM3-387
https://issues.redhat.com/browse/REM3-388

fl4via · 2022-02-10T21:06:07Z

@dmlloyd can you please have a look and let me know what you think of it? Thanks!

ropalka · 2022-02-11T07:46:40Z

src/main/java/org/jboss/remoting3/remote/OutboundMessage.java

+                        long ackTimeout = OutboundMessage.this.ackTimeout;
+                        long initialTime = System.currentTimeMillis();
+                        do {
+                            try {


initialTime = System.currentTimeMillis(); // initialization should be here inside do-while block, otherwise do-while() assignment of (ackTimeout -= (System.currentTimeMillis() - initialTime)) is invalid (may grow too fast incidentally)

Also, you should always use nanoTime for timeouts, not wall clock time.

@ropalka thanks for reviewing! The intention is that exactly. This block is there just to protect against spurious wakes. I.e., if I want to wait for a specific time and I'm awaken before that timeout expires without a notify. So, by comparing the elapsed time since initialTime everytime I'm awaken and the condition is not met, I can certify that the timeout has really expired.
@dmlloyd I was wondering that, I saw a PR to XNIO that used nanotime and converted that to ms, I'm going to do the same here.

@ropalka see my response to David below. Yes, you are correct, the initialization of intialTime is inconsistent with updating the field in the while loop.

The problem is still there @fl4via , nanoTime() wasn't moved to do-while block.

These timeout loops are a challenge every time. Part of the reason is that every blocking and timeout API works a little bit differently, so there's no single template that always works for all cases.

Because of this, my usual approach for these is to write the loop as being completely unwound, until I have enough repeated code that I can clearly see where the loop is and how it enters and exits, and then once I'm sure it's correct I can carefully refactor it into a cleaner loop "shape". This is something I learned after many, many mistakes.

@ropalka the initialization of initialTime outside the block was a deliberate choice. I just forgot to add a final to that field, btw.
So, I'm initializing initialTime outside of the block. This marks the beginning of the time I'll wait. My expectations is that the normal path is without spurious wakes, so, I'll probably reach the end of the while block and leave the do/while after a single iteration. I.e., I'll either have been able to acquireWindow, or I'll have verified that the timeout is expired. In the event there was a spurious wake and the window was not acquired, I reenter the loop, after updating ackTimeout based on current time minus initialTime, a value that is decremented from the total ack timeout. So, ackTimeout field is updated and then I wait for the remaining amount of time I have available. Because I'm always recalculating ackTimeout based on the original timeout (i.e., OutboundMessage.this.ackTimeout), initialTime does not have to be updated at every iteration of the loop. Unless I'm missing something, in that case please point me where is the mistake and I'll fix it right away :-)

Thanks for explanation @fl4via . Now I see what you had in mind.

ropalka · 2022-02-11T07:50:56Z

src/main/java/org/jboss/remoting3/remote/OutboundMessage.java

+                            if (cancelSent) {
+                                throw new MessageCancelledException(this + ": message was cancelled");
+                            }
+                        } while (!decrementWindow(msgSize) && (ackTimeout -= (System.currentTimeMillis() - initialTime)) > 0);


This condition evaluation should be reordered to
(ackTimeout -= (System.currentTimeMillis() - initialTime)) > 0 && !decrementWindow(msgSize)
otherwise an attempt to decrement the window may occur after timeout.

@ropalka that's exactly the goal. To decrement the window if the condition is met. If that's the case, it means I was awaken for the right reason, and timeout has not been reached. This is the condition that is expected to be met unless there is something off with the connection. If the condition is not met, I'm going to check for timeout just to protect myself against spurious wakes.

dmlloyd · 2022-02-11T16:15:13Z

src/main/java/org/jboss/remoting3/remote/OutboundMessage.java

+                        long ackTimeout = OutboundMessage.this.ackTimeout;
+                        long initialTime = System.currentTimeMillis();
+                        do {
+                            try {


Also, you should always use nanoTime for timeouts, not wall clock time.

dmlloyd · 2022-02-11T16:18:20Z

src/main/java/org/jboss/remoting3/remote/OutboundMessage.java

+                            if (cancelSent) {
+                                throw new MessageCancelledException(this + ": message was cancelled");
+                            }
+                        } while (!decrementWindow(msgSize) && (ackTimeout -= (System.currentTimeMillis() - initialTime)) > 0);


Is it intentional that ackTimeout is always reduced by the total time elapsed, rather than the time since the last loop?

Aha, now I see why @ropalka found it strange that I was initiating the initialTime before the loop. Thank you both for catching this. This is not correct, I'll fix it.

dmlloyd · 2022-02-25T20:56:50Z

src/main/java/org/jboss/remoting3/remote/RemoteReadListener.java

@@ -50,7 +50,7 @@
 */
 final class RemoteReadListener implements ChannelListener<ConduitStreamSourceChannel> {
    // FIXME temporarily using a system property as a solution to ACK TIMEOUT issue until an RFE is properly submitted
-    private static final int MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT)));
+    private static final long MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT))) * 1_000_000;


This is subject to a wrapping error if the timeout is more than around 2000 milliseconds; maybe do it like this instead:

Suggested change

private static final long MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT))) * 1_000_000;

private static final long MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT))) * 1_000_000L;

dmlloyd

I only have one comment; otherwise I think it looks good!

fl4via · 2022-02-25T21:01:24Z

I only have one comment; otherwise I think it looks good!
@dmlloyd thanks David! I'm going to fix it!

fl4via · 2022-02-28T10:39:03Z

@ropalka if you can please give your okay, this is the final fix after incorporating feedback from @dmlloyd on Friday

fl4via · 2022-02-28T10:42:42Z

@ropalka as a second thought, I'm going to change this PR a bit, I'll let you know when it is ready

…oseconds

… ack timeout wait to a loop to protect against spurious wakes. Plus, check for other causes for being awakened before assuming the message ack timeout has expired. The other causes for being awaked are all points where notifyAll was invoked. So, we need to check for closeReceived, closeCalled & !eof, and cancelSent before checking if the timeout expired withou a message ack

fl4via · 2022-02-28T10:55:57Z

@ropalka ready, please, review and, if you think it is okay, merge it

ropalka

LGTM

ropalka · 2022-02-28T13:57:47Z

src/main/java/org/jboss/remoting3/remote/OutboundMessage.java

+                        long ackTimeout = OutboundMessage.this.ackTimeout;
+                        long initialTime = System.currentTimeMillis();
+                        do {
+                            try {


Thanks for explanation @fl4via . Now I see what you had in mind.

ropalka requested changes Feb 11, 2022

View reviewed changes

dmlloyd reviewed Feb 11, 2022

View reviewed changes

fl4via force-pushed the REM3-387 branch from a112eb4 to 3659a1c Compare February 21, 2022 06:44

fl4via requested review from ropalka and dmlloyd February 21, 2022 06:44

fl4via force-pushed the REM3-387 branch from 3659a1c to b793431 Compare February 22, 2022 05:17

dmlloyd reviewed Feb 25, 2022

View reviewed changes

dmlloyd approved these changes Feb 25, 2022

View reviewed changes

fl4via force-pushed the REM3-387 branch from 0d3efab to 9536c10 Compare February 28, 2022 10:38

fl4via changed the title ~~[REM3-387] At OutboundMessage.bufferWriter.accept(), move the message…~~ [REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… Feb 28, 2022

fl4via added 2 commits February 28, 2022 07:52

[REM3-388] Move message ack timeout from int milliseconds to long nan…

1eebd17

…oseconds

fl4via force-pushed the REM3-387 branch from 9536c10 to 35fedde Compare February 28, 2022 10:53

ropalka approved these changes Feb 28, 2022

View reviewed changes

ropalka merged commit 7ee29f5 into jboss-remoting:5.0 Mar 1, 2022

fl4via deleted the REM3-387 branch March 3, 2022 14:57

fl4via mentioned this pull request Mar 10, 2022

[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #265

Merged

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #259

[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #259

fl4via commented Feb 10, 2022 •

edited

fl4via commented Feb 10, 2022

ropalka Feb 11, 2022

dmlloyd Feb 11, 2022

fl4via Feb 21, 2022

fl4via Feb 21, 2022

ropalka Feb 21, 2022

dmlloyd Feb 21, 2022

fl4via Feb 25, 2022

ropalka Feb 28, 2022

ropalka Feb 11, 2022 •

edited

fl4via Feb 21, 2022

dmlloyd Feb 11, 2022

dmlloyd Feb 11, 2022

fl4via Feb 21, 2022

dmlloyd Feb 25, 2022

dmlloyd left a comment

fl4via commented Feb 25, 2022

fl4via commented Feb 28, 2022

fl4via commented Feb 28, 2022

fl4via commented Feb 28, 2022

ropalka left a comment

ropalka Feb 28, 2022

	private static final long MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT))) * 1_000_000;
	private static final long MESSAGE_ACK_TIMEOUT = Integer.parseInt(WildFlySecurityManager.getPropertyPrivileged("org.jboss.remoting3.remote.message.ack.timeout", String.valueOf(RemotingOptions.DEFAULT_MESSAGE_ACK_TIMEOUT))) * 1_000_000L;

[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #259

[REM3-388][REM3-387] At OutboundMessage.bufferWriter.accept(), move the message… #259

Conversation

fl4via commented Feb 10, 2022 • edited

fl4via commented Feb 10, 2022

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

ropalka Feb 11, 2022 • edited

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

dmlloyd left a comment

Choose a reason for hiding this comment

fl4via commented Feb 25, 2022

fl4via commented Feb 28, 2022

fl4via commented Feb 28, 2022

fl4via commented Feb 28, 2022

ropalka left a comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

fl4via commented Feb 10, 2022 •

edited

ropalka Feb 11, 2022 •

edited