Hello, and sorry for top-posting, I don't know how to configure Outlook to do
it differently.
I was finally able to run your test. I had a lot of trouble doing it:
* did not have SVN, downloaded TortoiseSVN
* tried to open the project in IDEA, but failed miserably, I really hope that
there was pom.xml
* was able to build whole Tomcat and test using ant command line, but it took
so long, had to abort
* was not able to run this single test with ant:
Testsuite: org.apache.tomcat.websocket.server.TestAsyncMessages.java
Tests run: 1, Failures: 0, Errors: 1, Skipped: 0, Time elapsed: 0 sec
Caused an ERROR
org.apache.tomcat.websocket.server.TestAsyncMessages.java
java.lang.ClassNotFoundException:
org.apache.tomcat.websocket.server.TestAsyncMessages.java
* but was able to make the Eclipse project with "ant ide-eclipse"
* was able to run the unit test in Eclipse:
08-Mar-2017 14:14:40.538 INFO [main]
org.apache.catalina.startup.LoggingBaseTest.setUp Starting test case
[testAsyncTiming]
08-Mar-2017 14:14:42.676 INFO [main] org.apache.coyote.AbstractProtocol.init
Initializing ProtocolHandler ["http-nio-127.0.0.1-auto-1"]
08-Mar-2017 14:14:42.778 INFO [main]
org.apache.tomcat.util.net.NioSelectorPool.getSharedSelector Using a shared
selector for servlet write/read
08-Mar-2017 14:14:42.800 INFO [main]
org.apache.catalina.core.StandardService.startInternal Starting service Tomcat
08-Mar-2017 14:14:42.802 INFO [main]
org.apache.catalina.core.StandardEngine.startInternal Starting Servlet Engine:
Apache Tomcat/@VERSION@
08-Mar-2017 14:14:43.213 INFO [main] org.apache.coyote.AbstractProtocol.start
Starting ProtocolHandler [http-nio-127.0.0.1-auto-1-54783]
Sent Hello message, waiting for data
Expected diff < 500,000 but was [6054390], count [2]
Expected diff < 500,000 but was [1015710], count [14]
Expected diff < 500,000 but was [642270], count [25]
Expected diff < 500,000 but was [1712852], count [26]
Expected diff < 500,000 but was [595293], count [41]
Expected diff < 500,000 but was [792673], count [61]
Expected diff < 500,000 but was [799777], count [62]
Expected diff < 500,000 but was [531738], count [68]
Expected diff < 500,000 but was [532922], count [76]
Expected diff < 500,000 but was [673851], count [98]
Expected diff < 500,000 but was [538054], count [133]
Expected diff < 500,000 but was [747276], count [158]
Expected diff < 500,000 but was [794646], count [262]
Expected diff < 500,000 but was [1290461], count [263]
Expected diff < 500,000 but was [1013341], count [296]
Expected diff < 500,000 but was [582267], count [311]
Expected diff < 500,000 but was [1377703], count [337]
Expected diff < 500,000 but was [1698245], count [338]
Expected diff < 500,000 but was [1303488], count [424]
Expected diff < 500,000 but was [965181], count [425]
Expected diff < 500,000 but was [534896], count [455]
Expected diff < 500,000 but was [847938], count [458]
Expected diff < 500,000 but was [883862], count [473]
Expected diff < 500,000 but was [1026368], count [475]
Expected diff < 500,000 but was [1096241], count [476]
Expected diff < 500,000 but was [518710], count [481]
Expected diff < 500,000 but was [1053607], count [482]
Expected diff < 500,000 but was [641481], count [500]
Expected diff < 500,000 but was [565292], count [512]
Expected diff < 500,000 but was [808857], count [556]
Expected diff < 500,000 but was [643455], count [653]
Expected diff < 500,000 but was [508447], count [670]
Expected diff < 500,000 but was [960839], count [671]
Expected diff < 500,000 but was [954918], count [683]
Expected diff < 500,000 but was [601215], count [749]
Expected diff < 500,000 but was [561345], count [752]
Expected diff < 500,000 but was [688062], count [935]
Expected diff < 500,000 but was [1405730], count [937]
Expected diff < 500,000 but was [1414415], count [938]
Expected diff < 500,000 but was [1284935], count [941]
Expected diff < 500,000 but was [516737], count [995]
Expected diff < 500,000 but was [587398], count [1067]
Expected diff < 500,000 but was [946233], count [1079]
Expected diff < 500,000 but was [5403041], count [1114]
Expected diff < 500,000 but was [1181114], count [1115]
Expected diff < 500,000 but was [554239], count [1118]
Expected diff < 500,000 but was [1437706], count [1121]
Expected diff < 500,000 but was [577925], count [1240]
Expected diff < 500,000 but was [1226115], count [1241]
Expected diff < 500,000 but was [2194850], count [1285]
Expected diff < 500,000 but was [522264], count [1292]
Expected diff < 500,000 but was [845964], count [1328]
Expected diff < 500,000 but was [3652294], count [1331]
Expected diff < 500,000 but was [727538], count [1343]
Expected diff < 500,000 but was [809252], count [1349]
Expected diff < 500,000 but was [1597188], count [1393]
Expected diff < 500,000 but was [525816], count [1394]
08-Mar-2017 14:15:09.251 INFO [main] org.apache.coyote.AbstractProtocol.pause
Pausing ProtocolHandler ["http-nio-127.0.0.1-auto-1-54783"]
08-Mar-2017 14:15:09.266 INFO [main]
org.apache.catalina.core.StandardService.stopInternal Stopping service Tomcat
Then I was able to run the test also in IDEA, by importing Eclipse project and
modifying the libraries.
I changed the big message size to 16384 bytes and small size to 1904 bytes (the
most common problem that we have seen).
So need to add the following to servlet configuration:
<context-param>
<param-name>org.apache.tomcat.websocket.binaryBufferSize</param-name>
<param-value>16384</param-value>
</context-param>
<context-param>
<param-name>org.apache.tomcat.websocket.textBufferSize</param-name>
<param-value>16384</param-value>
</context-param>
Like this:
ctx.addParameter(Constants.
BINARY_BUFFER_SIZE_SERVLET_CONTEXT_INIT_PARAM, "16384");
ctx.addParameter(org.apache.tomcat.websocket.server.Constants.
TEXT_BUFFER_SIZE_SERVLET_CONTEXT_INIT_PARAM, "16384");
wsContainer.setDefaultMaxBinaryMessageBufferSize(16384);
wsContainer.setDefaultMaxTextMessageBufferSize(16384);
Then I changed the test logic so that there are only 2 messages, one big and
one small, but it fails randomly like the original test.
Also added test for maximum delay for the big message:
} else if (diff > 60000000) {
System.out.println("Expected diff < 60ms but was [" +
diff + "], count [" + count + "]");
fail = true;
}
Sent Hello message, waiting for data
Expected diff < 500,000 but was [718458], count [9]
Expected diff < 500,000 but was [1224142], count [17]
Expected diff < 500,000 but was [1102952], count [19]
Expected diff < 500,000 but was [663587], count [21]
Expected diff < 500,000 but was [537659], count [43]
Expected diff < 500,000 but was [3158452], count [73]
Expected diff < 500,000 but was [582662], count [75]
Expected diff < 500,000 but was [825437], count [121]
Expected diff < 500,000 but was [605953], count [129]
Expected diff < 500,000 but was [1092293], count [143]
Expected diff < 500,000 but was [552660], count [145]
Expected diff < 500,000 but was [7926329], count [177]
Expected diff < 500,000 but was [507657], count [189]
Expected diff < 500,000 but was [913468], count [193]
Expected diff < 500,000 but was [560160], count [229]
Expected diff < 500,000 but was [1748774], count [319]
Expected diff < 500,000 but was [529764], count [321]
Expected diff < 500,000 but was [692009], count [381]
Expected diff < 500,000 but was [556213], count [389]
Expected diff < 500,000 but was [2727772], count [403]
Expected diff < 500,000 but was [937154], count [469]
Expected diff < 500,000 but was [544370], count [513]
Expected diff < 500,000 but was [1018473], count [575]
Expected diff < 500,000 but was [518711], count [601]
Expected diff < 500,000 but was [885441], count [613]
Expected diff < 500,000 but was [2075633], count [645]
Expected diff < 500,000 but was [606347], count [715]
Expected diff < 500,000 but was [561345], count [721]
Expected diff < 500,000 but was [947812], count [889]
Expected diff < 500,000 but was [513974], count [923]
Expected diff < 60ms but was [65475211], count [960]
Expected diff > 40ms but was [35346555], count [962]
So the delay is at most 2 milliseconds, which is acceptable.
I think that you understood my problem quite well. It seems that the problem
can't be reproduced in this test.
I also tried adding sendPing() there but it did not have any effect.
We do not use compression extension.
Thanks for the test! :-)
-Harri
-----Original Message-----
From: Mark Thomas [mailto:ma...@apache.org]
Sent: 7. maaliskuuta 2017 23:58
To: Tomcat Users List <users@tomcat.apache.org>
Subject: Re: Tomcat WebSocket does not always send asynchronous messages
On 07/03/17 14:55, Mark Thomas wrote:
> On 07/03/17 11:03, Mark Thomas wrote:
>> On 07/03/17 08:28, Pesonen, Harri wrote:
>>> Hello, we have a problem that Tomcat WebSocket does not always send
>>> asynchronous messages. This problem is random, and it has been reproduced
>>> in Tomcat 8.5.6 and 8.5.11. Synchronized operations work fine, and also the
>>> asynchronous operations work except in one special case. When there is a
>>> big message that we want to send to client, we split it into 16 kB packets
>>> for technical reasons, and then we send them very quickly after each other
>>> using
>>>
>>> /**
>>> * Initiates the asynchronous transmission of a binary message. This method
>>> returns before the message
>>> * is transmitted. Developers provide a callback to be notified when the
>>> message has been
>>> * transmitted. Errors in transmission are given to the developer in the
>>> SendResult object.
>>> *
>>> * @param data the data being sent, must not be {@code null}.
>>> * @param handler the handler that will be notified of progress, must not be
>>> {@code null}.
>>> * @throws IllegalArgumentException if either the data or the handler are
>>> {@code null}.
>>> */
>>> void sendBinary(ByteBuffer data, SendHandler handler);
>>>
>>> Because there can be only one ongoing write to socket, we use Semaphore
>>> that is released on the SendHandler callback:
>>>
>>> public void onResult(javax.websocket.SendResult result) {
>>> semaphore.release();
>>>
>>> So the code to send is actually:
>>>
>>> semaphore.acquireUninterruptibly();
>>> async.sendBinary(buf, asyncHandler);
>>>
>>> This works fine in most cases. But when we send one 16 kB packet and then
>>> immediately one smaller packet (4 kB), then randomly the smaller packet is
>>> not actually sent, but only after we call
>>>
>>> async.sendPing(new byte[0])
>>>
>>> in another thread. sendPing() is called every 20 seconds to keep the
>>> WebSocket connection alive. This means that the last packet gets extra
>>> delay on client, which varies between 0 - 20 seconds.
>>>
>>> We have an easy workaround to the problem. If we call flushBatch() after
>>> each sendBinary(), then it works great, but this means that the sending is
>>> not actually asynchronous, because flushBatch() is synchronous.
>>> Also we should not be forced to call flushBatch(), because we are not
>>> enabling batching. Instead we make sure that it is disabled:
>>>
>>> if (async.getBatchingAllowed()) {
>>> async.setBatchingAllowed(false);
>>>
>>> So the working code is:
>>>
>>> semaphore.acquireUninterruptibly();
>>> async.sendBinary(buf, asyncHandler);
>>> async.flushBatch();
>>>
>>> Normally the code works fine without flushBatch(), if there is delay
>>> between the messages, but when we send the messages right after each other,
>>> then the last small message is not always sent immediately.
>>> I looked at the Apache WebSocket code, but it was not clear to me what is
>>> happening there.
>>> Any ideas what is going on here? Any ideas how I could troubleshoot this
>>> more?
>>
>> Thanks for providing such a clear description of the problem you are seeing.
>>
>> It sounds like there is a race condition somewhere in the WebSocket
>> code. With the detail you have provided, I think there is a reasonable
>> chance of finding via code inspection.
>
> Some follow-up questions to help narrow the search.
>
> This is server side, correct?
>
> Are you using the compression extension? If yes, do you see the problem
> without it?
>
> When you say "we split it into 16 kB packets" do you mean you split it
> into multiple WebSocket messages?
>
> If you insert a short delay before sending the final 4kB does that
> reduce the frequency of the problem?
I've added a (disabled by default) test case to explore the issue
described based on my understanding. It passes for me (ignoring what
look like GC introduced delays) with NIO.
http://svn.apache.org/viewvc?rev=1785893&view=rev
What would be really helpful would be if you could use this as a basis
for providing a test case that demonstrates the problem you are seeing.
Thanks,
Mark
---------------------------------------------------------------------
To unsubscribe, e-mail: users-unsubscr...@tomcat.apache.org
For additional commands, e-mail: users-h...@tomcat.apache.org
