[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be

classic Classic list List threaded Threaded
3 messages Options
Reply | Threaded
Open this post in threaded view
|

[jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be

JIRA jira@apache.org

    [ https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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,10000\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 20000ms to be sent, things settle down and a heartbeat's received every 10000ms.
> It looks like the write checker wakes up every 10000ms. The first time it wakes up, it notices that the CONNECTED frame was sent and does nothing. It then sleeps for a further 10000ms before checking again. As the CONNECTED frame was sent very early in the first 10000ms window, this leads to it taking almost 20000ms 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 10000ms.
> 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
Reply | Threaded
Open this post in threaded view
|

Re: [jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be

paulgale
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) <[hidden email]> wrote:

>
>     [
> https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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,10000\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 20000ms to be sent, things settle down and a heartbeat's
> received every 10000ms.
> > It looks like the write checker wakes up every 10000ms. The first time
> it wakes up, it notices that the CONNECTED frame was sent and does nothing.
> It then sleeps for a further 10000ms before checking again. As the
> CONNECTED frame was sent very early in the first 10000ms window, this leads
> to it taking almost 20000ms 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 10000ms.
> > 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
>
Reply | Threaded
Open this post in threaded view
|

Re: [jira] [Commented] (AMQ-4710) The first heart-beat after a connection becomes idle isn't sent as quickly as it should be

paulgale
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 <[hidden email]> 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) <[hidden email]>wrote:
>
>>
>>     [
>> https://issues.apache.org/jira/browse/AMQ-4710?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=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,10000\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 20000ms to be sent, things settle down and a
>> heartbeat's received every 10000ms.
>> > It looks like the write checker wakes up every 10000ms. The first time
>> it wakes up, it notices that the CONNECTED frame was sent and does nothing.
>> It then sleeps for a further 10000ms before checking again. As the
>> CONNECTED frame was sent very early in the first 10000ms window, this leads
>> to it taking almost 20000ms 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 10000ms.
>> > 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
>>
>
>