[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13772248#comment-13772248
]
Timothy Bish commented on AMQ-4710:
---
Not sure this fix is really the way to go, on a busy system we could be
canceling and rescheduling the timer quite a bit which introduces more overhead
than I think is good here. Would need to look at it more. Probably won't make
it into a v5.9.0 release.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
Attachments: amq-4710.diff
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13765545#comment-13765545
]
Paul Gale commented on AMQ-4710:
Any movement on this? I'd like to know whether this patch is going to be
accepted or if other feedback is available.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
Attachments: amq-4710.diff
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13761912#comment-13761912
]
Paul Gale commented on AMQ-4710:
Just realized I should have used a StompConnection object in the test. Trying
again.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
Attachments: amq-4710.diff
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13758353#comment-13758353
]
Paul Gale commented on AMQ-4710:
Sending a frame is sending data on the wire so the send of the RECEIPT frame
prempts any need to send a KEEPALIVE frame.
Agreed. However, once data has been sent in lieu of a KEEPALIVE frame the write
checker timer should be adjusted accordingly, otherwise it will sleep for twice
its configured interval.
I have attached a patch file containing a failing unit test (of sorts) and a
fix. The test is not the prettiest so adjust as necessary.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
Attachments: amq_4710.patch
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757082#comment-13757082
]
Timothy Bish commented on AMQ-4710:
---
Sending a frame is sending data on the wire so the send of the RECEIPT frame
prempts any need to send a KEEPALIVE frame.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757072#comment-13757072
]
Paul Gale commented on AMQ-4710:
This problem doesn't just happen on startup.
I've been able to induce this behavior in the broker. I modified the test to
periodically send a frame to the broker containing a receipt header. This
forces the broker to respond with a RECEIPT frame. After sending the RECEIPT
frame the broker waits another 1ms (in this case) before issuing another
write check.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757200#comment-13757200
]
Timothy Bish commented on AMQ-4710:
---
You'd need to submit the change as a patch, can't tell what's changed above.
Also tests to show there's an issue.
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757189#comment-13757189
]
Paul Gale commented on AMQ-4710:
I believe the fix for this condition is as follows. I've tested it and it
appears to work. However, feedback is welcome if there's a better way to handle
this.
{code}
private final Runnable writeChecker = new Runnable() {
long lastRunTime;
@Override
public void run() {
long now = System.currentTimeMillis();
long sleepTime = now - lastRunTime;
if (lastRunTime != 0 LOG.isDebugEnabled()) {
LOG.debug(this + + sleepTime + ms elapsed since last
write check.);
}
if (commandSent.get() sleepTime = getWriteCheckTime()) {
LOG.trace(Resetting to prevent double sleep !!);
commandSent.set(false);
}
lastRunTime = now;
writeCheck();
}
@Override
public String toString() {
return WriteChecker;
}
};
{code}
The first heart-beat after a connection becomes idle isn't sent as quickly as
it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up to
almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read = socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now - lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read: +
timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time it
wakes up, it notices that the CONNECTED frame was sent and does nothing. It
then sleeps for a further 1ms before checking again. As the CONNECTED
frame was sent very early in the first 1ms window, this leads to it
taking almost 2ms for the first heart-beat to be sent. From this point,
as no further data frames are sent, the write checker wakes up and sends a
heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that the
sender MUST send new data over the network connection at least every n
milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more
Re: [jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
This change won't work anyways.
How do you propose one unit test multi-threaded code in a repeatable manner
in Java? :) Examples and guidance much appreciated.
On Tue, Sep 3, 2013 at 6:55 PM, Timothy Bish (JIRA) j...@apache.org wrote:
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757200#comment-13757200]
Timothy Bish commented on AMQ-4710:
---
You'd need to submit the change as a patch, can't tell what's changed
above. Also tests to show there's an issue.
The first heart-beat after a connection becomes idle isn't sent as
quickly as it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up
to almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read =
socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer, read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now -
lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read:
+ timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first heartbeat
taking almost 2ms to be sent, things settle down and a heartbeat's
received every 1ms.
It looks like the write checker wakes up every 1ms. The first time
it wakes up, it notices that the CONNECTED frame was sent and does nothing.
It then sleeps for a further 1ms before checking again. As the
CONNECTED frame was sent very early in the first 1ms window, this leads
to it taking almost 2ms for the first heart-beat to be sent. From this
point, as no further data frames are sent, the write checker wakes up and
sends a heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that
the sender MUST send new data over the network connection at least every
n milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA
administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
Re: [jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be
Also, where are the existing unit tests in this area that should be
extended or modified? As far as I can see it appears that this inactivity
code has not been tested.
On Tue, Sep 3, 2013 at 7:21 PM, Paul Gale paul.n.g...@gmail.com wrote:
This change won't work anyways.
How do you propose one unit test multi-threaded code in a repeatable
manner in Java? :) Examples and guidance much appreciated.
On Tue, Sep 3, 2013 at 6:55 PM, Timothy Bish (JIRA) j...@apache.orgwrote:
[
https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanelfocusedCommentId=13757200#comment-13757200]
Timothy Bish commented on AMQ-4710:
---
You'd need to submit the change as a patch, can't tell what's changed
above. Also tests to show there's an issue.
The first heart-beat after a connection becomes idle isn't sent as
quickly as it should be
--
Key: AMQ-4710
URL: https://issues.apache.org/jira/browse/AMQ-4710
Project: ActiveMQ
Issue Type: Bug
Components: stomp
Affects Versions: 5.8.0
Reporter: Andy Wilkinson
After ActiveMQ sends a stomp frame, it may not send a heart-beat for up
to almost 2x the negotiated interval.
The following test should illustrate the problem:
{code}
import org.junit.Test;
import static org.junit.Assert.*;
public class ActiveMqHeartbeatTests {
@Test
public void heartbeats() throws Exception {
BrokerService broker = createAndStartBroker();
Socket socket = null;
try {
socket = new Socket(localhost, 61613);
byte[] connectFrame =
CONNECT\nheart-beat:0,1\naccept-version:1.2\n\n\0.getBytes();
socket.getOutputStream().write(connectFrame);
byte[] buffer = new byte[4096];
long lastReadTime = System.currentTimeMillis();
while (true) {
int read =
socket.getInputStream().read(buffer);
byte[] frame = Arrays.copyOf(buffer,
read);
long now = System.currentTimeMillis();
long timeSinceLastRead = now -
lastReadTime;
lastReadTime = now;
System.out.println(new String(frame));
System.out.println(Time since last read:
+ timeSinceLastRead + ms);
if (timeSinceLastRead 15000) {
fail(Data not received for +
timeSinceLastRead + ms);
}
}
} finally {
if (socket != null) {
socket.close();
}
broker.stop();
}
}
private BrokerService createAndStartBroker() throws Exception {
BrokerService broker = new BrokerService();
broker.addConnector(stomp://localhost:61613);
broker.setStartAsync(false);
broker.setDeleteAllMessagesOnStartup(true);
broker.start();
return broker;
}
}
{code}
For the initial read of the CONNECTED frame I see:
{noformat}
Time since last read: 49ms
{noformat}
However, it's then almost 20 seconds before a heart-beat's sent:
{noformat}
Time since last read: 19994ms
{noformat}
If I comment out the fail(…) line in the test, after the first
heartbeat taking almost 2ms to be sent, things settle down and a
heartbeat's received every 1ms.
It looks like the write checker wakes up every 1ms. The first time
it wakes up, it notices that the CONNECTED frame was sent and does nothing.
It then sleeps for a further 1ms before checking again. As the
CONNECTED frame was sent very early in the first 1ms window, this leads
to it taking almost 2ms for the first heart-beat to be sent. From this
point, as no further data frames are sent, the write checker wakes up and
sends a heart-beat every 1ms.
In short, I don't think ActiveMQ is adhering to the requirement that
the sender MUST send new data over the network connection at least every
n milliseconds.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA
administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
