[prev in list] [next in list] [prev in thread] [next in thread]
List: activemq-dev
Subject: [jira] [Commented] (AMQ-3907) Restful HTTP MessageServlet causing trouble. May be a garbage collect
From: "Stephen Vincent (JIRA)" <jira () apache ! org>
Date: 2012-07-29 20:52:34
Message-ID: 789460485.114684.1343595154575.JavaMail.jiratomcat () issues-vm
[Download RAW message or body]
[ https://issues.apache.org/jira/browse/AMQ-3907?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13424626#comment-13424626 \
]
Stephen Vincent commented on AMQ-3907:
--------------------------------------
I seem to be able to avoid problems if I prevent the Non-Persistent Pending Cursor \
from filling up. I think I have been able to accomplish that in a number of ways: \
1) Turning off Flow Control, 2) Increasing my prefetch size, and 3) Using a pending \
queue VMQueueCursor. In all three of those uses cases, I do not see it initializing \
temporary disk storage, so I assume those configurations prevent the Non-Persistent \
Pending Cursor from exhausting its RAM when running my test case. Remember my test \
case is put 10000 non-persistent messages and then get them back off. I assume that \
test case constitutes a slow-consumer scenario.
> 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
[prev in list] [next in list] [prev in thread] [next in thread]
Configure |
About |
News |
Add a list |
Sponsored by KoreLogic