Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Lock contention in OutbackCDX PoolingHttpClientConnectionManager #57

Open
anjackson opened this issue Oct 2, 2020 · 12 comments
Open

Lock contention in OutbackCDX PoolingHttpClientConnectionManager #57

anjackson opened this issue Oct 2, 2020 · 12 comments
Assignees
@anjackson

Comments

@anjackson
Copy link
Contributor

Running at large scale, a many threads appear to be in a locked/waiting state, thrashing a lock in the PoolingHttpClientConnectionManager used by the OutbackCDXClient.
We are using a pool for multithreaded execution, which appears to have known contention issues at least in some cases. Note also, from the javadocs:

The handling of stale connections was changed in version 4.4. Previously, the code would check every connection by default before re-using it. The code now only checks the connection if the elapsed time since the last use of the connection exceeds the timeout that has been set. The default timeout is set to 2000ms

The documentation implies that the stale check could be disabled to increase performance (see CoreConnectionPNames.STALE_CONNECTION_CHECK).

Given we're generally managing pools of threads anyway, particularly the ToeThreads, it may make more sense to use a ThreadLocal HTTP client rather than having a separate pool. This would ensure no pool contention.

We likely need a performance test case that runs a lot of OutbackCDXClients that can detect the pool contention problem.
@anjackson anjackson self-assigned this Oct 2, 2020
@anjackson
Copy link
Contributor Author

I set up a load test class and ran it against OutbackCDX on my laptop. I found some scaling issues on both sides.

Firstly, OutbackCDX needs quite a lot of additional threads when heavily loaded (presumably it takes a while to drop them when requests finish). With 1000 clients, 2000 OutbackCDX threads were not enough to prevent requests getting dropped.

Secondly, with the client pool at 1000 threads the clients appears to start failing occasionally, and giving OutbackCDX even more threads does not help. Some connections hang for a long time (>60s!), and whatever timeout is used there are Socket closed errors. (leading to c. 70 drops out of 100,000 connections).

Threads, Total Milliseconds, Milliseconds per Thread, Errors, Successes

10	5163	516.3	0	1000
50	5805	116.1	0	5000
100	7556	75.56	0	10000
250	16192	64.768	0	25000
500	37316	74.632	0	50000
...Socket closed errors and timeouts...
1000	113744	113.744	73	99927

The first thing to try is to tune up OutbackCDX so there's definitely plenty of overhead. Grepping the logs shows lines like:

Mon Oct 05 22:55:07 UTC 2020 14 requests queued, all 2000 web server threads are busy

So it is running out and so the number should be raised. Then we can look at improving the client behaviour when the thread pool is large.

@anjackson
Copy link
Contributor Author

Hmmm, changes to ThreadLocal HTTP client setup, no change. And ulimits don't seem to be the problem.

core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 10240
pipe size            (512 bytes, -p) 1
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 2048
virtual memory          (kbytes, -v) unlimited
Here is the standard error of the command (if any):

10	6924	692.4	0	1000
50	8715	174.3	0	5000
100	11355	113.55	0	10000
250	17093	68.372	0	25000
500	35223	70.446	0	50000
Socket closed
Socket closed
Socket closed
Socket closed
Socket closed
Socket closed

@anjackson
Copy link
Contributor Author

anjackson commented Oct 6, 2020 •
edited
Loading

Hmm, further experimentation, including running this against a faux OutbackCDX server (actually an NGINX instance that returns the same thing all the time), indicates that this appears to be a problem with OutbackCDX itself. Momentarily switching to a more recent version of Apache HTTP Client gives somewhat more detailed errors.

From NGINX FauxCDX:

10	1119	111.9	0	1000
50	1523	30.46	0	5000
100	1893	18.93	0	10000
250	5001	20.004	0	25000
500	7413	14.826	0	50000
750	11879	15.838666666666667	0	75000
1000	21766	21.766	0	100000

Running against OutbackCDX:

10	5246	524.6	0	1000
50	4736	94.72	0	5000
100	5960	59.6	0	10000
250	13366	53.464	0	25000
500	27579	55.158	0	50000
750	43136	57.51466666666666	0	75000
Premature end of chunk coded message body: closing chunk expected
Socket closed
Socket closed
Socket closed
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Socket closed
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Socket closed
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Truncated chunk (expected size: 621; actual size: 0)
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Socket closed
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
Premature end of chunk coded message body: closing chunk expected
1000	63485	63.485	158	99842

@anjackson anjackson mentioned this issue Oct 6, 2020
Closed
@anjackson
Copy link
Contributor Author

Hm, so the code was not well written to cope with whatever the underlying failure mode was, and that has contributed to the mess. Having tidied up the code and made it retry more sensibly, it's more consistent and the transient failures are overcome.

Having just re-run following this tweak:

It ran with no errors!

10	805	80.5	0	1000
50	573	11.46	0	5000
100	1099	10.99	0	10000
250	2204	8.816	0	25000
500	4135	8.27	0	50000
750	5811	7.748	0	75000
1000	12849	12.849	0	100000

Note that this is much faster but largely because I'm running against OutbackCDX outside a container (which is interesting in itself).

Running against the containerised version:

core file size          (blocks, -c) 0
data seg size           (kbytes, -d) unlimited
file size               (blocks, -f) unlimited
max locked memory       (kbytes, -l) unlimited
max memory size         (kbytes, -m) unlimited
open files                      (-n) 10240
pipe size            (512 bytes, -p) 1
stack size              (kbytes, -s) 8192
cpu time               (seconds, -t) unlimited
max user processes              (-u) 1418
virtual memory          (kbytes, -v) unlimited
10	5307	530.7	0	1000
50	8024	160.48	0	5000
100	10518	105.18	0	10000
250	23169	92.676	0	25000
500	35980	71.96	0	50000
750	48530	64.70666666666666	0	75000
...a lot of these exeptions...
Oct 07, 2020 3:56:38 PM uk.bl.wap.util.OutbackCDXClient getCDXLine
SEVERE: GET http://localhost:9090/fc?limit=100&matchType=exact&sort=reverse&url=http%3A%2F%2Facid.matkelly.com%2F failed with error Socket closed
java.net.SocketException: Socket closed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:150)
	at java.net.SocketInputStream.read(SocketInputStream.java:121)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)
	at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:240)
	at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:206)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:169)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.BufferedReader.fill(BufferedReader.java:161)
	at java.io.BufferedReader.readLine(BufferedReader.java:324)
	at java.io.BufferedReader.readLine(BufferedReader.java:389)
	at uk.bl.wap.util.OutbackCDXClient.getCDXLine(OutbackCDXClient.java:291)
	at uk.bl.wap.util.OutbackCDXClient.getLastCrawl(OutbackCDXClient.java:354)
	at uk.bl.wap.util.OutbackCDXClientLoadTest.lambda$0(OutbackCDXClientLoadTest.java:102)
	at uk.bl.wap.util.OutbackCDXClientLoadTest$$Lambda$1/1554547125.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:744)
1000	73354	73.354	0	100000

@anjackson
Copy link
Contributor Author

So, the kernel change I made was:

sudo sysctl -w net.inet.tcp.msl=5000

Since doing that, it all seems a bit happier. Setting it back to 15000 to see if that reverts the behaviour.

Hmmm.

10	1331	133.1	0	1000
50	1053	21.06	0	5000
100	1749	17.49	0	10000
250	2818	11.272	0	25000
500	4946	9.892	0	50000
750	7422	9.896	0	75000
Oct 07, 2020 4:10:13 PM uk.bl.wap.util.OutbackCDXClient getCDXLine
SEVERE: GET http://localhost:9090/fc?limit=100&matchType=exact&sort=reverse&url=http%3A%2F%2Facid.matkelly.com%2F failed with error Socket closed
java.net.SocketException: Socket closed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:150)
	at java.net.SocketInputStream.read(SocketInputStream.java:121)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)
	at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:240)
	at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:206)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:169)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.BufferedReader.fill(BufferedReader.java:161)
	at java.io.BufferedReader.readLine(BufferedReader.java:324)
	at java.io.BufferedReader.readLine(BufferedReader.java:389)
	at uk.bl.wap.util.OutbackCDXClient.getCDXLine(OutbackCDXClient.java:291)
	at uk.bl.wap.util.OutbackCDXClient.getLastCrawl(OutbackCDXClient.java:354)
	at uk.bl.wap.util.OutbackCDXClientLoadTest.lambda$0(OutbackCDXClientLoadTest.java:102)
	at uk.bl.wap.util.OutbackCDXClientLoadTest$$Lambda$1/1554547125.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:744)
Oct 07, 2020 4:10:13 PM uk.bl.wap.util.OutbackCDXClient getCDXLine
SEVERE: GET http://localhost:9090/fc?limit=100&matchType=exact&sort=reverse&url=http%3A%2F%2Facid.matkelly.com%2F failed with error Socket closed
java.net.SocketException: Socket closed
	at java.net.SocketInputStream.socketRead0(Native Method)
	at java.net.SocketInputStream.read(SocketInputStream.java:150)
	at java.net.SocketInputStream.read(SocketInputStream.java:121)
	at org.apache.http.impl.io.SessionInputBufferImpl.streamRead(SessionInputBufferImpl.java:136)
	at org.apache.http.impl.io.SessionInputBufferImpl.fillBuffer(SessionInputBufferImpl.java:152)
	at org.apache.http.impl.io.SessionInputBufferImpl.readLine(SessionInputBufferImpl.java:270)
	at org.apache.http.impl.io.ChunkedInputStream.getChunkSize(ChunkedInputStream.java:240)
	at org.apache.http.impl.io.ChunkedInputStream.nextChunk(ChunkedInputStream.java:206)
	at org.apache.http.impl.io.ChunkedInputStream.read(ChunkedInputStream.java:169)
	at org.apache.http.conn.EofSensorInputStream.read(EofSensorInputStream.java:137)
	at sun.nio.cs.StreamDecoder.readBytes(StreamDecoder.java:284)
	at sun.nio.cs.StreamDecoder.implRead(StreamDecoder.java:326)
	at sun.nio.cs.StreamDecoder.read(StreamDecoder.java:178)
	at java.io.InputStreamReader.read(InputStreamReader.java:184)
	at java.io.BufferedReader.fill(BufferedReader.java:161)
	at java.io.BufferedReader.readLine(BufferedReader.java:324)
	at java.io.BufferedReader.readLine(BufferedReader.java:389)
	at uk.bl.wap.util.OutbackCDXClient.getCDXLine(OutbackCDXClient.java:291)
	at uk.bl.wap.util.OutbackCDXClient.getLastCrawl(OutbackCDXClient.java:354)
	at uk.bl.wap.util.OutbackCDXClientLoadTest.lambda$0(OutbackCDXClientLoadTest.java:102)
	at uk.bl.wap.util.OutbackCDXClientLoadTest$$Lambda$1/1554547125.run(Unknown Source)
	at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:511)
	at java.util.concurrent.FutureTask.run(FutureTask.java:266)
	at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
	at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
	at java.lang.Thread.run(Thread.java:744)
1000	13900	13.9	0	100000

Run two more times and consistently getting one Socket closed error each time.

Okay, trying a much smaller value (1000) and more runs at that value...

Yep, consistently fine. Still getting some broken pipe errors and Protocol wrong type for socket (Write failed) (???) from OutbackCDX, but otherwise fine. (Although those errors might be unforseen consequences of my debugging changes to OutbackCDX as they seem to have gone away now I've reverted my changes).

@anjackson
Copy link
Contributor Author

Okay, so running natively with a low socket release timeout (1000) example results:

10	806	80.6	0	1000
50	709	14.18	0	5000
100	1068	10.68	0	10000
250	2324	9.296	0	25000
500	4148	8.296	0	50000
750	5869	7.825333333333333	0	75000
1000	12615	12.615	0	100000

Same running under Docker...

10	5422	542.2	0	1000
50	5306	106.12	0	5000
100	8371	83.71	0	10000
250	18349	73.396	0	25000
500	31710	63.42	0	50000
750	46159	61.54533333333333	0	75000
...ERRRORS...
1000	112118	112.118	0	100000

Again, a lot of socket errors. It's possible using Docker network means a lot more ephemeral ports tied together.

What about switching to host networking... Hm, ports declared with mode: host don't seem to change anything.

@anjackson
Copy link
Contributor Author

anjackson commented Oct 8, 2020 •
edited
Loading

So, on Mac, there's a weird Docker overhead and a weird slowdown at 1000 threads.

But that aside, as per nla/outbackcdx#389, using OutbackCDX's Undertow server mode (rather than NanoHTTPD), it seems to be stable and slightly faster.

@anjackson
Copy link
Contributor Author

anjackson commented Nov 13, 2020 •
edited
Loading

So, due to problems with NanoHTTPD and the JRE itself (which started behaving a bit better following an upgrade!), I think I lost track of the original problem, and would like to try switching back to thread-local BasicHttpConnectionManager usage. The Heritrix ToeThreads use this approach, so I'd like to try that rather than use the pool.

Right now running the tests is incredibly slow so something weird is going on.

@anjackson
Copy link
Contributor Author

Okay, so some macOS issues aside, seems to work fine now. Change code to make pooling OutbackCDX connections optional. Speed is roughly the same under simple load testing so shouldn't make things worse, and if there is a thread contention issue in the pool, may improve things somewhat.

@anjackson
Copy link
Contributor Author

Hm, using ThreadLocal leads to multiple thread errors I ill understand:

eritrix_1                           | java.lang.IllegalStateException: Connection is still allocated
heritrix_1                           | 	at org.apache.http.util.Asserts.check(Asserts.java:34)
heritrix_1                           | 	at org.apache.http.impl.conn.BasicHttpClientConnectionManager.getConnection(BasicHttpClientConnectionManager.java:248)
heritrix_1                           | 	at org.apache.http.impl.conn.BasicHttpClientConnectionManager$1.get(BasicHttpClientConnectionManager.java:199)
heritrix_1                           | 	at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:173)
heritrix_1                           | 	at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:195)
heritrix_1                           | 	at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:86)
heritrix_1                           | 	at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:108)
heritrix_1                           | 	at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:184)
heritrix_1                           | 	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:82)
heritrix_1                           | 	at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:106)
heritrix_1                           | 	at uk.bl.wap.util.OutbackCDXClient.getCDXLine(OutbackCDXClient.java:277)
heritrix_1                           | 	at uk.bl.wap.util.OutbackCDXClient.getLastCrawl(OutbackCDXClient.java:366)
heritrix_1                           | 	at uk.bl.wap.modules.deciderules.OutbackCDXRecentlySeenDecideRule.getInfo(OutbackCDXRecentlySeenDecideRule.java:49)
heritrix_1                           | 	at uk.bl.wap.modules.deciderules.RecentlySeenDecideRule.evaluateWithTTL(RecentlySeenDecideRule.java:327)
heritrix_1                           | 	at uk.bl.wap.modules.deciderules.RecentlySeenDecideRule.evaluate(RecentlySeenDecideRule.java:248)
heritrix_1                           | 	at org.archive.modules.deciderules.PredicatedDecideRule.innerDecide(PredicatedDecideRule.java:48)
heritrix_1                           | 	at org.archive.modules.deciderules.DecideRule.decisionFor(DecideRule.java:60)
heritrix_1                           | 	at org.archive.modules.deciderules.DecideRuleSequence.innerDecide(DecideRuleSequence.java:113)
heritrix_1                           | 	at org.archive.modules.deciderules.DecideRule.decisionFor(DecideRule.java:60)
heritrix_1                           | 	at org.archive.crawler.framework.Scoper.isInScope(Scoper.java:107)
heritrix_1                           | 	at org.archive.crawler.prefetch.Preselector.innerProcessResult(Preselector.java:152)
heritrix_1                           | 	at org.archive.modules.Processor.process(Processor.java:142)
heritrix_1                           | 	at org.archive.modules.ProcessorChain.process(ProcessorChain.java:131)
heritrix_1                           | 	at org.archive.crawler.framework.ToeThread.run(ToeThread.java:148)

@anjackson
Copy link
Contributor Author

Hm, okay, so the client was being held in the class scope, and that being re-used across threads probably cause the state problems. Making the client unique per request works, but the load test goes badly because we run out of transient ports (no connections are being re-used).

So, perhaps we can make the HttpClient (which contains the connnection manager) thread local, and get it working....

anjackson added a commit that referenced this issue Nov 13, 2020
@anjackson
Switching to ThreadLocal HttpClient for #57.
cbfe975
@anjackson
Copy link
Contributor Author

Yep, ThreadLocal<CloseableHttpClient> seems to work fine, and be fast enough (it's perhaps a little slower than pooled, but there's not much in it). Tagged as 2.7.7 - hopefully at some point I'll get chance to run this at large enough scale that we can tell it's helping.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@anjackson anjackson

Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
1 participant
@anjackson