activemq-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Stephen Vincent (JIRA)" <j...@apache.org>
Subject [jira] [Commented] (AMQ-3907) Restful HTTP MessageServlet causing trouble. May be a garbage collection issue.
Date Wed, 25 Jul 2012 22:31:35 GMT

    [ https://issues.apache.org/jira/browse/AMQ-3907?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13422689#comment-13422689
] 

Stephen Vincent commented on AMQ-3907:
--------------------------------------

   Just noticed that this jira was dup'd to AMQ3925, so I downloaded the 5.7 snapshot and
it does appear to solve item (1), where I was encountering trouble when attempt to write a
bunch of messages via http.  Thank you, I sincerely appreciate it.

   I am able still able to reproduce items (2) and (3), where my read loop kicks-out and the
consumer gobbles up some messages.  I am able to produced it with a freshly started broker.
 However, even though the first test attempt encounters the problem, subsequent attempts seem
to run fine.  On the first attempt(run of my test against a just-started broker), I notice
the following info message reported by the broker:

  INFO | PListStore:[C:\amq\apache-activemq-5.7-SNAPSHOT\bin\..\data\localhost\tmp_storage
] initialized

I think that has something to do with it.  If my test pgm only puts 300 messages(54 bytes
of text in the body), then that storage is not needed, and my read loop does *not* kick-out
prematurely.  However, if I put 3000 messages, then I encounter the above "tmp_storage" log
msg, and my read loop kicks-out early.  Even though the URL is specify includes "&consumer.prefetchSize=1",
I can lose a large number of messages when my read loop kicks-out.

Would you like me to open a new jira for items (2) and (3)?  Thanks in advance.

                
> Restful HTTP MessageServlet causing trouble.  May be a garbage collection issue.
> --------------------------------------------------------------------------------
>
>                 Key: AMQ-3907
>                 URL: https://issues.apache.org/jira/browse/AMQ-3907
>             Project: ActiveMQ
>          Issue Type: Bug
>          Components: Broker
>    Affects Versions: 5.6.0
>         Environment: 32-bit Windows
>            Reporter: Stephen Vincent
>            Priority: Critical
>
> I am developing a C-based client that uses the RESTful HTTP protocol to POST and GET
messages to and from an ActiveMQ broker.  I have seen my test run successfully.  However,
if I run it multiple times back to back in succession, it will usually encounter failures.
 The test has two steps, where the first POSTs a number of messages on the queue, then the
second step GETs them back off.  When it encounters trouble, it is usually in the first step
when posting messages.  When that encounters failures, it appears to be having trouble re-connecting,
and kicks-out of that first step, proceeding on to the second step where it GETs the messages
off of the queue.  When the first step encounters trouble, the second step usually just gets
a portion of the messages before getting a 204(No content).  The 204 notifies my test that
it is time to terminate.  I have seen the following in some of the server debug logs:
> -------------------------------------
> 2012-06-27 07:44:04,007 | DEBUG | Async client internal exception occurred with no exception
listener registered: java.lang.IllegalStateException: REDISPATCHING,initial,resumed | org.apache.activemq.ActiveMQConnection
| ActiveMQ Session Task-2 
> java.lang.IllegalStateException: REDISPATCHING,initial,resumed 
>         at org.eclipse.jetty.server.AsyncContinuation.dispatch(AsyncContinuation.java:403)

>         at org.eclipse.jetty.server.AsyncContinuation.resume(AsyncContinuation.java:810)

>         at org.apache.activemq.web.MessageServlet$Listener.onMessageAvailable(MessageServlet.java:368)

>         at org.apache.activemq.ActiveMQMessageConsumer.dispatch(ActiveMQMessageConsumer.java:1320)

>         at org.apache.activemq.ActiveMQSessionExecutor.dispatch(ActiveMQSessionExecutor.java:131)

>         at org.apache.activemq.ActiveMQSessionExecutor.iterate(ActiveMQSessionExecutor.java:202)

>         at org.apache.activemq.thread.PooledTaskRunner.runTask(PooledTaskRunner.java:122)

>         at org.apache.activemq.thread.PooledTaskRunner$1.run(PooledTaskRunner.java:43)

>         at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886)

>         at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908)

>         at java.lang.Thread.run(Thread.java:619) 
> -------------------------------------
> I am thinking that the garbage collector is not able to keep-up, and the broker has trouble
when running out of memory.
> I have also seen messages like this:
> -------------------------------------
> 2012-06-27 07:33:01,435 | DEBUG | Main:memory:queue://myqueue:memory: usage change from:
67% of available memory, to: 68% of available memory | org.apache.activemq.usage.Usage | VMTransport:
vm://localhost#71 
> -------------------------------------
> When the second step terminates prematurely due to the 204 status, the rest of the messages
are gone.  Maybe my "consumer.prefetchSize=1" is ignored, and the consumer on the server-side
grabs the rest of the messages.  Any ideas?
> Another thing I notice, is that the HTTP client code I use reports the following for
every message it posts: 
> "Web server requires that we close the current connection and obtain a new connection
to continue."  Is that normal, or can I change some configuration setting to prevent that?
> My test program is a SAS program.  Note: since my client code in question is not yet
production, you will not be able to run the test even if you do have a current version of
SAS.  Here is my test program:
> -------------------------------------
> data _null_;
>     file '' device=activemq lrecl=54
>         url='http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000'
>         ;
>     do i = 1 to 2000;
>         d = datetime();
>         put i z5. +1 'This is a test msg sent at' +1 d datetime21.2;
>     end;
> run;
> data _null_;
>     infile '' device=activemq lrecl=54 timeout=1000
>         url='http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=1'
>         ;
>     input;
> run;
> -------------------------------------
> That first DATA step POSTs 2000 messages to a queue, and the second DATA step GETs them
back off.  If I change the write loop to just POST 2 messages and I turn on some client-side
debug/trace logging, you can see what I am sending and receiving across the wire.  Here is
an excerpt from the log: 
> -------------------------------------
> INFO 1          data _null_;
> INFO 2              file '' device=activemq lrecl=54
> INFO 3                  url='http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PE
> INFO 3        ! RSISTENT&JMSTimeToLive=100000'
> INFO 4                  ;
> INFO 5              do i = 1 to 2;
> INFO 6                  d = datetime();
> INFO 7                  put i z5. +1 'This is a test msg sent at' +1 d datetime21.2;
> INFO 8              end;
> INFO 9          run;
> INFO 
> DEBUG Attempting to connect to Web server 10.23.11.16:8161.
> INFO NOTE: The file '' is:
> INFO       
> INFO       URL=http://d22275:8161/demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTi
> INFO       meToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874,
> INFO       LRECL=54,TIMEOUT=-1
> INFO 
> DEBUG Executing POST request.
> DEBUG >>> POST /demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874
HTTP/1.1
> DEBUG >>> Content-Type: APPLICATION/X-WWW-FORM-URLENCODED
> DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary Files\SAS_util000100001004_d22275\ut1004000002.utl
> DEBUG >>> Content-Length: 59
> DEBUG >>> Host: d22275:8161
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> TRACE >>> 341c000: 62 6f 64 79 3d 30 30 30 30 31 20 54 68 69 73 20 |body=00001
This |
> TRACE >>> 341c010: 69 73 20 61 20 74 65 73 74 20 6d 73 67 20 73 65 |is a test
msg se|
> TRACE >>> 341c020: 6e 74 20 61 74 20 30 31 4a 55 4c 32 30 31 32 3a |nt at 01JUL2012:|
> TRACE >>> 341c030: 31 38 3a 32 36 3a 34 33 2e 36 39                |18:26:43.69
    |
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< Set-Cookie: JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;Path=/demo
> DEBUG <<< Expires: Thu, 01 Jan 1970 00:00:00 GMT
> DEBUG <<< messageID: ID:d22275-1028-1341175648962-3:24:1:1:1
> DEBUG <<< Content-Length: 0
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> DEBUG Request POST returns status 200.
> DEBUG Executing POST request.
> DEBUG Web server requires that we close the current connection and obtain a new connection
to continue.
> DEBUG Attempting to connect to Web server 10.23.11.16:8161.
> DEBUG >>> POST /demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874
HTTP/1.1
> DEBUG >>> Content-Type: APPLICATION/X-WWW-FORM-URLENCODED
> DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary Files\SAS_util000100001004_d22275\ut1004000003.utl
> DEBUG >>> Content-Length: 59
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Cookie: $Version=1;JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;$Path=/demo
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> TRACE >>> 3422000: 62 6f 64 79 3d 30 30 30 30 32 20 54 68 69 73 20 |body=00002
This |
> TRACE >>> 3422010: 69 73 20 61 20 74 65 73 74 20 6d 73 67 20 73 65 |is a test
msg se|
> TRACE >>> 3422020: 6e 74 20 61 74 20 30 31 4a 55 4c 32 30 31 32 3a |nt at 01JUL2012:|
> TRACE >>> 3422030: 31 38 3a 32 36 3a 34 33 2e 37 30                |18:26:43.70
    |
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< messageID: ID:d22275-1028-1341175648962-3:24:1:1:2
> DEBUG <<< Content-Length: 0
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> DEBUG Request POST returns status 200.
> DEBUG Attempting to connect to Web server 10.23.11.16:8161.
> DEBUG Executing POST request.
> DEBUG >>> POST /demo/message/myqueue?type=queue&JMSDeliveryMode=NON_PERSISTENT&JMSTimeToLive=100000&clientId=839E8906-E338-4FDE-9818-665B14944874&action=unsubscribe
HTTP/1.1
> DEBUG >>> Content-Type: application/x-www-form-urlencoded
> DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary Files\SAS_util000100001004_d22275\ut1004000004.utl
> DEBUG >>> Content-Length: 0
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Cookie: $Version=1;JSESSIONID=1f4dfw7mbb4611ilhiznnkifi3;$Path=/demo
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< Content-Length: 0
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> DEBUG Request POST returns status 200.
> DEBUG Destroying connection to Web server d22275:8161.
> INFO NOTE: 2 records were written to the file ''.
> INFO       The minimum record length was 54.
> INFO       The maximum record length was 54.
> DEBUG Destroying connection to Web server d22275:8161.
> INFO NOTE: DATA statement used (Total process time):
> INFO       real time           0.17 seconds
> INFO       cpu time            0.00 seconds
> INFO       
> INFO 
> INFO 10         
> INFO 11         data _null_;
> INFO 12             infile '' device=activemq lrecl=54 timeout=1000
> INFO 13                 url='http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=
> INFO 13       ! 1'
> INFO 14                 ;
> INFO 15             input;
> INFO 16         run;
> INFO 
> DEBUG Attempting to connect to Web server 10.23.11.16:8161.
> INFO NOTE: The infile '' is:
> INFO       
> INFO       URL=http://d22275:8161/demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BA
> INFO       B771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000,
> INFO 2                                        The SAS System                18:26 Sunday,
July 1, 2012
> INFO 
> INFO       LRECL=54,TIMEOUT=1000
> INFO 
> DEBUG Executing GET request.
> DEBUG >>> GET /demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Accept: */*
> DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
> DEBUG >>> Accept-Encoding: identity
> DEBUG >>> Accept-Language: en
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< Set-Cookie: JSESSIONID=171xnui5b43xz1wpgghnpgtiws;Path=/demo
> DEBUG <<< Expires: Thu, 01 Jan 1970 00:00:00 GMT
> DEBUG <<< Content-Type: text/xml;charset=UTF-8
> DEBUG <<< destination: queue://myqueue
> DEBUG <<< id: ID:d22275-1028-1341175648962-3:24:1:1:1
> DEBUG <<< Content-Length: 54
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> TRACE <<< 415a740: 30 30 30 30 31 20 54 68 69 73 20 69 73 20 61 20 |00001 This
is a |
> TRACE <<< 415a750: 74 65 73 74 20 6d 73 67 20 73 65 6e 74 20 61 74 |test msg
sent at|
> TRACE <<< 415a760: 20 30 31 4a 55 4c 32 30 31 32 3a 31 38 3a 32 36 | 01JUL2012:18:26|
> TRACE <<< 415a770: 3a 34 33 2e 36 39                               |:43.69 
        |
> DEBUG Request GET returns status 200.
> DEBUG Executing GET request.
> DEBUG >>> GET /demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Accept: */*
> DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
> DEBUG >>> Accept-Encoding: identity
> DEBUG >>> Accept-Language: en
> DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< Content-Type: text/xml;charset=UTF-8
> DEBUG <<< destination: queue://myqueue
> DEBUG <<< id: ID:d22275-1028-1341175648962-3:24:1:1:2
> DEBUG <<< Content-Length: 54
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> TRACE <<< 415a740: 30 30 30 30 32 20 54 68 69 73 20 69 73 20 61 20 |00002 This
is a |
> TRACE <<< 415a750: 74 65 73 74 20 6d 73 67 20 73 65 6e 74 20 61 74 |test msg
sent at|
> TRACE <<< 415a760: 20 30 31 4a 55 4c 32 30 31 32 3a 31 38 3a 32 36 | 01JUL2012:18:26|
> TRACE <<< 415a770: 3a 34 33 2e 37 30                               |:43.70 
        |
> DEBUG Request GET returns status 200.
> DEBUG Executing GET request.
> DEBUG >>> GET /demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000
HTTP/1.1
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Accept: */*
> DEBUG >>> Accept-Charset: iso-8859-1,*,utf-8
> DEBUG >>> Accept-Encoding: identity
> DEBUG >>> Accept-Language: en
> DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> DEBUG <<< HTTP/1.1 204 No Content
> DEBUG <<< Content-Type: text/xml;charset=UTF-8
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> DEBUG Request GET returns status 204.
> DEBUG Attempting to connect to Web server 10.23.11.16:8161.
> DEBUG Executing POST request.
> DEBUG >>> POST /demo/message/myqueue?type=queue&consumer.prefetchSize=1&clientId=7BAB771E-AF44-4597-B603-FC018C1069B3&READTIMEOUT=1000&action=unsubscribe
HTTP/1.1
> DEBUG >>> Content-Type: application/x-www-form-urlencoded
> DEBUG Cache file name used is C:\DOCUME~1\sav\LOCALS~1\Temp\SAS Temporary Files\SAS_util000100001004_d22275\ut1004000005.utl
> DEBUG >>> Content-Length: 0
> DEBUG >>> Host: d22275:8161
> DEBUG >>> Cookie: $Version=1;JSESSIONID=171xnui5b43xz1wpgghnpgtiws;$Path=/demo
> DEBUG >>> User-Agent: SAS/9
> DEBUG >>> 
> DEBUG <<< HTTP/1.1 200 OK
> DEBUG <<< Content-Length: 0
> DEBUG <<< Server: Jetty(7.6.1.v20120215)
> DEBUG <<< 
> DEBUG Request POST returns status 200.
> DEBUG Destroying connection to Web server d22275:8161.
> INFO NOTE: 2 records were read from the infile ''.
> INFO       The minimum record length was 54.
> INFO       The maximum record length was 54.
> DEBUG Destroying connection to Web server d22275:8161.
> -------------------------------------

--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators: https://issues.apache.org/jira/secure/ContactAdministrators!default.jspa
For more information on JIRA, see: http://www.atlassian.com/software/jira

        

Mime
View raw message