On Thu, Nov 15, 2018 at 8:59 AM Gary Gregory <[email protected]> wrote:
> On Thu, Nov 15, 2018 at 8:45 AM Oleg Kalnichevski <[email protected]> > wrote: > >> On Sun, 2018-11-11 at 18:30 -0700, Gary Gregory wrote: >> > Hi All: >> > >> >> ... >> >> > I am looking for guidance here. I suppose this could be a bug in the >> > example, or in the core, or that the example could/should be adjusted >> > to >> > avoid this unfortunate sequence. Again, the IO rector parameters I >> > used are >> > only to demonstrate the problem. In my set up, I use the default >> > select >> > timeout of 1 second and reactor IO thread counts of 2. >> > >> > Thank you, >> > Gary >> >> >> Oh, it was a nasty one. It is just sheer luck that the problem was much >> easier to reproduce with non-persistent connections and out of laziness >> I opted for AB (which uses non-persistent HTTP/1.0 by default) instead >> of JMeter. >> >> I believe the culprit was this race condition: >> >> >> https://github.com/apache/httpcomponents-core/commit/f5590e471f46892787df01fca2a6e8faf26fd454 >> >> I also fixed incorrect handling of incoming HTTP/1.0 requests by the >> reverse proxy example. >> >> Please test the latest snapshot with your application and let me know the >> outcome. >> > > Thank you Oleg, I am testing... My initial app test failed (I made the > same change to my app as you made to the sample to use a distinct > HttpContext for outgoing message exchanges) so I will review and try to > reproduce with the example... > Hi Oleg, Using the previous example I posted called "AsyncReverseProxyExampleNoLogging" which I updated to use a distinct HttpContext for outgoing message exchanges (just like the updated example), and JMeter, I can send over 285K requests but it fails on the 285,032th request with a different error. The last line in the resulting JMeter output file OneByteHttpCore.csv is: 1542298828472,10053,One Byte HttpCore,Non HTTP response code: org.apache.http.NoHttpResponseException,Non HTTP response message: localhost:9094 failed to respond,Thread Group 1-1,text,false,,2090,0,1,1, http://localhost:9094/one-byte.txt,0,0,1 Which does not tell us much sadly. BUT, perhaps more tellingly, the console for the proxy (running from Eclipse), shows: Reverse proxy to http://localhost:8080 Listening on port 9094 java.net.SocketTimeoutException: 10 SECONDS at org.apache.hc.core5.io.SocketTimeoutExceptionFactory.create(SocketTimeoutExceptionFactory.java:50) at org.apache.hc.core5.http.impl.nio.AbstractHttp1StreamDuplexer.onTimeout(AbstractHttp1StreamDuplexer.java:416) at org.apache.hc.core5.http.impl.nio.AbstractHttp1IOEventHandler.timeout(AbstractHttp1IOEventHandler.java:81) at org.apache.hc.core5.http.impl.nio.ServerHttp1IOEventHandler.timeout(ServerHttp1IOEventHandler.java:40) at org.apache.hc.core5.reactor.InternalDataChannel.onTimeout(InternalDataChannel.java:184) at org.apache.hc.core5.reactor.InternalChannel.checkTimeout(InternalChannel.java:67) at org.apache.hc.core5.reactor.SingleCoreIOReactor.checkTimeout(SingleCoreIOReactor.java:232) at org.apache.hc.core5.reactor.SingleCoreIOReactor.validateActiveChannels(SingleCoreIOReactor.java:165) at org.apache.hc.core5.reactor.SingleCoreIOReactor.doExecute(SingleCoreIOReactor.java:127) at org.apache.hc.core5.reactor.AbstractSingleCoreIOReactor.execute(AbstractSingleCoreIOReactor.java:80) at org.apache.hc.core5.reactor.IOReactorWorker.run(IOReactorWorker.java:44) at java.lang.Thread.run(Thread.java:745) Which would indicate that the problem is the same as before. I will try with different parameters to see if I can make it fail faster. FTR, the JMeter output is: C:\Java\apache-jmeter-5.0\bin>rmdir /q/s c:\test\jmeter-OneByteHttpCore & del /F c:\test\OneByteHttpCore.csv & jmeter -n -t C:\Users\ggregory\Downloads\OneByteHttpCore.jmx -l c:\test\OneByteHttpCore.csv -e -o c:\test\jmeter-OneByteHttpCore Creating summariser <summary> Created the tree successfully using C:\Users\ggregory\Downloads\OneByteHttpCore.jmx Starting the test @ Thu Nov 15 08:50:25 MST 2018 (1542297025377) Waiting for possible Shutdown/StopTestNow/Heapdump message on port 4445 summary + 424 in 00:00:04 = 100.4/s Avg: 8 Min: 4 Max: 228 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary + 4903 in 00:00:30 = 163.5/s Avg: 5 Min: 4 Max: 56 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 5327 in 00:00:34 = 155.7/s Avg: 6 Min: 4 Max: 228 Err: 0 (0.00%) summary + 5257 in 00:00:30 = 175.2/s Avg: 5 Min: 3 Max: 110 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 10584 in 00:01:04 = 164.8/s Avg: 5 Min: 3 Max: 228 Err: 0 (0.00%) summary + 5646 in 00:00:30 = 188.2/s Avg: 5 Min: 3 Max: 45 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 16230 in 00:01:34 = 172.2/s Avg: 5 Min: 3 Max: 228 Err: 0 (0.00%) summary + 5776 in 00:00:30 = 192.6/s Avg: 4 Min: 3 Max: 51 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 22006 in 00:02:04 = 177.1/s Avg: 5 Min: 3 Max: 228 Err: 0 (0.00%) summary + 3738 in 00:00:30 = 124.6/s Avg: 7 Min: 3 Max: 9818 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 25744 in 00:02:34 = 166.9/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5633 in 00:00:30 = 187.7/s Avg: 5 Min: 3 Max: 64 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 31377 in 00:03:04 = 170.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5631 in 00:00:30 = 187.8/s Avg: 5 Min: 3 Max: 61 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 37008 in 00:03:34 = 172.8/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5736 in 00:00:30 = 191.2/s Avg: 5 Min: 3 Max: 19 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 42744 in 00:04:04 = 175.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5240 in 00:00:30 = 174.7/s Avg: 5 Min: 3 Max: 474 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 47984 in 00:04:34 = 175.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4498 in 00:00:30 = 149.9/s Avg: 6 Min: 3 Max: 387 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 52482 in 00:05:04 = 172.5/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5099 in 00:00:30 = 169.8/s Avg: 5 Min: 3 Max: 340 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 57581 in 00:05:34 = 172.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3838 in 00:00:30 = 128.0/s Avg: 7 Min: 3 Max: 1403 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 61419 in 00:06:04 = 168.6/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4413 in 00:00:30 = 147.1/s Avg: 6 Min: 3 Max: 4468 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 65832 in 00:06:34 = 167.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4901 in 00:00:30 = 163.3/s Avg: 5 Min: 3 Max: 95 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 70733 in 00:07:04 = 166.7/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5136 in 00:00:30 = 171.2/s Avg: 5 Min: 3 Max: 60 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 75869 in 00:07:34 = 167.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5126 in 00:00:30 = 170.9/s Avg: 5 Min: 3 Max: 81 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 80995 in 00:08:04 = 167.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4996 in 00:00:30 = 166.5/s Avg: 5 Min: 3 Max: 82 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 85991 in 00:08:34 = 167.2/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4781 in 00:00:30 = 159.4/s Avg: 6 Min: 3 Max: 81 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 90772 in 00:09:04 = 166.8/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5136 in 00:00:30 = 171.2/s Avg: 5 Min: 3 Max: 53 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 95908 in 00:09:34 = 167.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5342 in 00:00:30 = 178.1/s Avg: 5 Min: 3 Max: 189 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 101250 in 00:10:04 = 167.6/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4895 in 00:00:30 = 163.1/s Avg: 5 Min: 3 Max: 235 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 106145 in 00:10:34 = 167.4/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5124 in 00:00:30 = 170.8/s Avg: 5 Min: 3 Max: 68 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 111269 in 00:11:04 = 167.5/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5587 in 00:00:30 = 186.2/s Avg: 5 Min: 3 Max: 51 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 116856 in 00:11:34 = 168.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4987 in 00:00:30 = 166.2/s Avg: 5 Min: 3 Max: 221 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 121843 in 00:12:04 = 168.2/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3699 in 00:00:30 = 123.3/s Avg: 7 Min: 3 Max: 147 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 125542 in 00:12:34 = 166.5/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5499 in 00:00:30 = 183.3/s Avg: 5 Min: 3 Max: 102 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 131041 in 00:13:04 = 167.1/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5684 in 00:00:30 = 189.5/s Avg: 5 Min: 3 Max: 29 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 136725 in 00:13:34 = 167.9/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4898 in 00:00:30 = 163.3/s Avg: 5 Min: 3 Max: 66 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 141623 in 00:14:04 = 167.8/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5506 in 00:00:30 = 183.5/s Avg: 5 Min: 3 Max: 37 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 147129 in 00:14:34 = 168.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5388 in 00:00:30 = 179.6/s Avg: 5 Min: 3 Max: 60 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 152517 in 00:15:04 = 168.7/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4588 in 00:00:32 = 143.9/s Avg: 6 Min: 3 Max: 5522 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 157105 in 00:15:36 = 167.8/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5083 in 00:00:28 = 180.7/s Avg: 5 Min: 3 Max: 64 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 162188 in 00:16:04 = 168.2/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5208 in 00:00:30 = 173.6/s Avg: 5 Min: 3 Max: 62 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 167396 in 00:16:34 = 168.4/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 5420 in 00:00:30 = 180.7/s Avg: 5 Min: 3 Max: 35 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 172816 in 00:17:04 = 168.7/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4802 in 00:00:30 = 160.1/s Avg: 6 Min: 3 Max: 88 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 177618 in 00:17:34 = 168.5/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3879 in 00:00:30 = 129.3/s Avg: 7 Min: 3 Max: 128 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 181497 in 00:18:04 = 167.4/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3410 in 00:00:30 = 113.7/s Avg: 8 Min: 4 Max: 99 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 184907 in 00:18:34 = 166.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3960 in 00:00:30 = 132.0/s Avg: 7 Min: 3 Max: 106 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 188867 in 00:19:04 = 165.1/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3977 in 00:00:30 = 132.6/s Avg: 7 Min: 4 Max: 74 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 192844 in 00:19:34 = 164.2/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4564 in 00:00:30 = 152.1/s Avg: 6 Min: 3 Max: 35 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 197408 in 00:20:04 = 163.9/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4576 in 00:00:30 = 152.5/s Avg: 6 Min: 3 Max: 43 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 201984 in 00:20:34 = 163.7/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4216 in 00:00:30 = 140.5/s Avg: 6 Min: 3 Max: 113 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 206200 in 00:21:04 = 163.1/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4485 in 00:00:30 = 149.5/s Avg: 6 Min: 3 Max: 68 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 210685 in 00:21:34 = 162.8/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4698 in 00:00:30 = 156.6/s Avg: 6 Min: 3 Max: 52 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 215383 in 00:22:04 = 162.6/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4463 in 00:00:30 = 148.7/s Avg: 6 Min: 3 Max: 62 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 219846 in 00:22:34 = 162.3/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4353 in 00:00:30 = 145.2/s Avg: 6 Min: 3 Max: 598 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 224199 in 00:23:04 = 162.0/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4333 in 00:00:30 = 144.4/s Avg: 6 Min: 3 Max: 827 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 228532 in 00:23:34 = 161.6/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4983 in 00:00:30 = 166.1/s Avg: 5 Min: 3 Max: 26 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 233515 in 00:24:04 = 161.7/s Avg: 5 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4066 in 00:00:30 = 135.5/s Avg: 7 Min: 4 Max: 81 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 237581 in 00:24:34 = 161.2/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4282 in 00:00:30 = 142.8/s Avg: 6 Min: 3 Max: 73 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 241863 in 00:25:04 = 160.8/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4486 in 00:00:30 = 149.5/s Avg: 6 Min: 4 Max: 66 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 246349 in 00:25:34 = 160.6/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4244 in 00:00:30 = 141.5/s Avg: 6 Min: 4 Max: 48 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 250593 in 00:26:04 = 160.2/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 3691 in 00:00:30 = 123.1/s Avg: 7 Min: 3 Max: 118 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 254284 in 00:26:34 = 159.5/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4155 in 00:00:30 = 138.5/s Avg: 7 Min: 3 Max: 69 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 258439 in 00:27:04 = 159.1/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4305 in 00:00:30 = 143.5/s Avg: 6 Min: 3 Max: 55 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 262744 in 00:27:34 = 158.8/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4218 in 00:00:30 = 140.6/s Avg: 6 Min: 3 Max: 60 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 266962 in 00:28:04 = 158.5/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4255 in 00:00:30 = 141.8/s Avg: 6 Min: 3 Max: 85 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 271217 in 00:28:34 = 158.2/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4452 in 00:00:30 = 148.4/s Avg: 6 Min: 3 Max: 39 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 275669 in 00:29:04 = 158.0/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4803 in 00:00:30 = 160.0/s Avg: 6 Min: 3 Max: 78 Err: 0 (0.00%) Active: 1 Started: 1 Finished: 0 summary = 280472 in 00:29:34 = 158.1/s Avg: 6 Min: 3 Max: 9818 Err: 0 (0.00%) summary + 4559 in 00:00:39 = 118.3/s Avg: 8 Min: 3 Max: 10053 Err: 1 (0.02%) Active: 0 Started: 1 Finished: 1 summary = 285031 in 00:30:13 = 157.2/s Avg: 6 Min: 3 Max: 10053 Err: 1 (0.00%) Tidying up ... @ Thu Nov 15 09:20:38 MST 2018 (1542298838562) ... end of run Gary > Gary > > >> >> Cheers >> >> Oleg >> >> >> --------------------------------------------------------------------- >> To unsubscribe, e-mail: [email protected] >> For additional commands, e-mail: [email protected] >> >>
