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
