activemq-users mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Alex Dean <ad...@meteostar.com>
Subject ajax delivery frequently gets delayed or stalled for 25 seconds in activemq 5.3
Date Wed, 14 Jul 2010 15:24:52 GMT
The ajax servlet in 5.3 will often 'stall', and fail to deliver  
messages for about 25 seconds at a time.  This behavior is not present  
in the 5.4 snapshots I've tried recently.  Everything seems to work  
perfectly with that code.  I've run tests up to a few hundred messages  
without missing one or having any of delays.  Dejan stated there has  
been some refactoring work going on in the ajax servlet code, and it  
seems like this has definitely improved things.

I'm writing now:
  1. as an FYI to other people who might be having problems with the  
ajax code in 5.3, and
  2. to ask if it's possible that these 5.4 changes merged back into  
5.3, since 5.4 is not yet stable/released.

More details:

I think that MessageListenerServlet is entering a sleeping/suspended  
state when it should not.
http://fisheye6.atlassian.com/browse/activemq/branches/activemq-5.3/activemq-web/src/main/java/org/apache/activemq/web/MessageListenerServlet.java?r=HEAD
In this link, line 72 sets "private long maximumReadTimeout =  
25000;".  This is used in "continuation.suspend(timeout);" on line  
301.  I'm not exactly sure why this is happening, but this timeout  
value very closely matches the delays I see in my message delivery.

In my testing, I created an HTML/JavaScript page which uses the  
ActiveMQ ajax connector to subscribe to a topic, and then publish 1  
message/second to this topic.  The first time the page loads, this  
works fine.  I receive messages immediately.  When I reload the page,  
however, it takes roughly 25 seconds for the first message to arrive.   
The first one I get is either #24 or #25, and all previous messages  
are not delivered.  If I close the window and open a new one, message  
delivery is normal.  When I reload, I often see this initial delay  
happen.  I see this same behavior in the chat.html script which is  
included in ActiveMQ, so I'm pretty sure it's not a client-side issue.

Sometimes, while messages are coming in normally, delivery will  
'stall', again for about 25 seconds.  After this time has elapsed, all  
the missing messages are delivered at once.  In other words, I can get  
messages 1-10 normally at a rate of approximately 1/second.  Then  
message #11 will fail to appear.  After 25 seconds, messages #11-#36  
appear nearly simultaneously.  After than, delivery returns to the  
normal 1/second rate.

Here's an example of what a 'stall' looks like.  The 'sent' and 'recd'  
times are in seconds since the page loaded.  Times are all calculated  
in javascript, so the same clock is in use for both.  'in-transit' is  
just recd minus sent.  Delivery is normal up to message 19, then  
messages 20-44 are delayed, then normal delivery resumes at message  
45.  Messages 20-44 all appear at nearly the same moment.

50  sent:49.999, recd: 50.035, in-transit: 0.036
49  sent:48.997, recd: 49.032, in-transit: 0.035
48  sent:47.999, recd: 48.038, in-transit: 0.039
47  sent:46.992, recd: 47.028, in-transit: 0.036
46  sent:45.998, recd: 46.021, in-transit: 0.023
45  sent:44.997, recd: 45.023, in-transit: 0.026
44  sent:44, recd: 44.457, in-transit: 0.457
43  sent:43, recd: 44.446, in-transit: 1.446
42  sent:42, recd: 44.435, in-transit: 2.435
41  sent:40.999, recd: 44.424, in-transit: 3.425
40  sent:39.999, recd: 44.413, in-transit: 4.414
39  sent:39, recd: 44.403, in-transit: 5.403
38  sent:38, recd: 44.393, in-transit: 6.393
37  sent:37, recd: 44.382, in-transit: 7.382
36  sent:35.994, recd: 44.372, in-transit: 8.378
35  sent:34.998, recd: 44.362, in-transit: 9.364
34  sent:34.002, recd: 44.352, in-transit: 10.35
33  sent:32.993, recd: 44.342, in-transit: 11.349
32  sent:32, recd: 44.333, in-transit: 12.333
31  sent:31, recd: 44.324, in-transit: 13.324
30  sent:29.999, recd: 44.316, in-transit: 14.317
29  sent:28.999, recd: 44.308, in-transit: 15.309
28  sent:27.999, recd: 44.3, in-transit: 16.301
27  sent:27, recd: 44.293, in-transit: 17.293
26  sent:25.998, recd: 44.286, in-transit: 18.288
25  sent:24.994, recd: 44.278, in-transit: 19.284
24  sent:23.999, recd: 44.272, in-transit: 20.273
23  sent:23, recd: 44.265, in-transit: 21.265
22  sent:21.996, recd: 44.259, in-transit: 22.263
21  sent:21, recd: 44.252, in-transit: 23.252
20  sent:19.997, recd: 44.245, in-transit: 24.248
19  sent:19.001, recd: 19.198, in-transit: 0.197
18  sent:17.995, recd: 18.028, in-transit: 0.033
17  sent:16.991, recd: 17.025, in-transit: 0.034
16  sent:16.005, recd: 16.04, in-transit: 0.035
15  sent:15.004, recd: 15.037, in-transit: 0.033
14  sent:14.01, recd: 14.04, in-transit: 0.03
13  sent:13.001, recd: 13.026, in-transit: 0.025
12  sent:12, recd: 12.027, in-transit: 0.027
11  sent:10.999, recd: 11.032, in-transit: 0.033
10  sent:9.998, recd: 10.024, in-transit: 0.026

While this 'stall' is happening, if I reload the page (either by  
clicking 'reload', or by focusing on the browser's address bar and  
hitting 'enter'), the stalled messages are immediately delivered.  So,  
if the stall happens after message 10, then I wait 5 seconds and  
reload, I see messages 11-15 displayed just before the browser  
reloads.  I'm guessing that when the client closes the open GET  
request which is parked on the server, that somehow causes the server  
to flush queued/suspended messages back to the client.  Why they get  
queued/suspended in the first place is really the question.

thanks,
alex



Mime
View raw message