clj-http icon indicating copy to clipboard operation
clj-http copied to clipboard

Published 20 hours ago • verified publisher icon dakrone

Async client opens dozens of threads

Open camsaul opened this issue 5 years ago • 4 comments

For the purposes of testing something I've tried to issue 60 simultaneous long-running HTTP requests to our web server using the async functionality of this lib. However when issuing 30 or so requests they start throwing this Exception:

(dotimes [_ 60]
  (http/post url (assoc request :async? true) identity (fn [e] (throw e))))

org.apache.http.nio.reactor.IOReactorException: Failure opening selector
 at org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.<init> (AbstractMultiworkerIOReactor.java:144)
    org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init> (DefaultConnectingIOReactor.java:79)
    org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init> (DefaultConnectingIOReactor.java:94)
    clj_http.conn_mgr$make_ioreactor.invokeStatic (conn_mgr.clj:210)
    clj_http.conn_mgr$make_ioreactor.invoke (conn_mgr.clj:194)
    clj_http.conn_mgr$make_regular_async_conn_manager.invokeStatic (conn_mgr.clj:223)
    clj_http.conn_mgr$make_regular_async_conn_manager.invoke (conn_mgr.clj:212)
    clj_http.core$get_conn_mgr.invokeStatic (core.clj:550)
    clj_http.core$get_conn_mgr.invoke (core.clj:546)
    clj_http.core$request.invokeStatic (core.clj:572)
    clj_http.core$request.invoke (core.clj:554)
    clojure.lang.Var.invoke (Var.java:393)
    clj_http.client$wrap_request_timing$fn__75749.invoke (client.clj:1089)
    clj_http.headers$wrap_header_map$fn__74758.invoke (headers.clj:149)
    clj_http.client$wrap_query_params$fn__75629.invoke (client.clj:821)
    clj_http.client$wrap_basic_auth$fn__75635.invoke (client.clj:844)
    clj_http.client$wrap_oauth$fn__75640.invoke (client.clj:861)
    clj_http.client$wrap_user_info$fn__75649.invoke (client.clj:881)
    clj_http.client$wrap_url$fn__75731.invoke (client.clj:1039)
    clj_http.client$wrap_decompression$fn__75400.invoke (client.clj:422)
    clj_http.client$wrap_input_coercion$fn__75553.invoke (client.clj:641)
    clj_http.client$wrap_additional_header_parsing$fn__75578.invoke (client.clj:696)
    clj_http.client$wrap_output_coercion$fn__75540.invoke (client.clj:585)
    clj_http.client$wrap_exceptions$fn__75346.invoke (client.clj:256)
    clj_http.client$wrap_accept$fn__75593.invoke (client.clj:739)
    clj_http.client$wrap_accept_encoding$fn__75600.invoke (client.clj:761)
    clj_http.client$wrap_content_type$fn__75587.invoke (client.clj:722)
    clj_http.client$wrap_form_params$fn__75696.invoke (client.clj:963)
    clj_http.client$wrap_nested_params$fn__75717.invoke (client.clj:997)
    clj_http.client$wrap_flatten_nested_params$fn__75726.invoke (client.clj:1022)
    clj_http.client$wrap_method$fn__75654.invoke (client.clj:897)
    clj_http.cookies$wrap_cookies$fn__74656.invoke (cookies.clj:133)
    clj_http.links$wrap_links$fn__75144.invoke (links.clj:65)
    clj_http.client$wrap_unknown_host$fn__75734.invoke (client.clj:1055)
    clj_http.client$request_STAR_.invokeStatic (client.clj:1175)
    clj_http.client$request_STAR_.invoke (client.clj:1169)
    clj_http.client$post.invokeStatic (client.clj:1194)
    clj_http.client$post.doInvoke (client.clj:1190)
    clojure.lang.RestFn.invoke (RestFn.java:460)
    [...]
Caused by: java.io.IOException: Too many open files
 at sun.nio.ch.EPoll.create (EPoll.java:-2)
    sun.nio.ch.EPollSelectorImpl.<init> (EPollSelectorImpl.java:79)
    sun.nio.ch.EPollSelectorProvider.openSelector (EPollSelectorProvider.java:36)
    java.nio.channels.Selector.open (Selector.java:295)
    org.apache.http.impl.nio.reactor.AbstractMultiworkerIOReactor.<init> (AbstractMultiworkerIOReactor.java:142)
    org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init> (DefaultConnectingIOReactor.java:79)
    org.apache.http.impl.nio.reactor.DefaultConnectingIOReactor.<init> (DefaultConnectingIOReactor.java:94)
    clj_http.conn_mgr$make_ioreactor.invokeStatic (conn_mgr.clj:210)
    clj_http.conn_mgr$make_ioreactor.invoke (conn_mgr.clj:194)
    clj_http.conn_mgr$make_regular_async_conn_manager.invokeStatic (conn_mgr.clj:223)
    clj_http.conn_mgr$make_regular_async_conn_manager.invoke (conn_mgr.clj:212)
    clj_http.core$get_conn_mgr.invokeStatic (core.clj:550)
    clj_http.core$get_conn_mgr.invoke (core.clj:546)
    clj_http.core$request.invokeStatic (core.clj:572)
    clj_http.core$request.invoke (core.clj:554)
    clojure.lang.Var.invoke (Var.java:393)
    clj_http.client$wrap_request_timing$fn__75749.invoke (client.clj:1089)
    clj_http.headers$wrap_header_map$fn__74758.invoke (headers.clj:149)
    clj_http.client$wrap_query_params$fn__75629.invoke (client.clj:821)
    clj_http.client$wrap_basic_auth$fn__75635.invoke (client.clj:844)
    clj_http.client$wrap_oauth$fn__75640.invoke (client.clj:861)
    clj_http.client$wrap_user_info$fn__75649.invoke (client.clj:881)
    clj_http.client$wrap_url$fn__75731.invoke (client.clj:1039)
    clj_http.client$wrap_decompression$fn__75400.invoke (client.clj:422)
    clj_http.client$wrap_input_coercion$fn__75553.invoke (client.clj:641)
    clj_http.client$wrap_additional_header_parsing$fn__75578.invoke (client.clj:696)
    clj_http.client$wrap_output_coercion$fn__75540.invoke (client.clj:585)
    clj_http.client$wrap_exceptions$fn__75346.invoke (client.clj:256)
    clj_http.client$wrap_accept$fn__75593.invoke (client.clj:739)
    clj_http.client$wrap_accept_encoding$fn__75600.invoke (client.clj:761)
    clj_http.client$wrap_content_type$fn__75587.invoke (client.clj:722)
    clj_http.client$wrap_form_params$fn__75696.invoke (client.clj:963)
    clj_http.client$wrap_nested_params$fn__75717.invoke (client.clj:997)
    clj_http.client$wrap_flatten_nested_params$fn__75726.invoke (client.clj:1022)
    clj_http.client$wrap_method$fn__75654.invoke (client.clj:897)
    clj_http.cookies$wrap_cookies$fn__74656.invoke (cookies.clj:133)
    clj_http.links$wrap_links$fn__75144.invoke (links.clj:65)
    clj_http.client$wrap_unknown_host$fn__75734.invoke (client.clj:1055)
    clj_http.client$request_STAR_.invokeStatic (client.clj:1175)
    clj_http.client$request_STAR_.invoke (client.clj:1169)
    clj_http.client$post.invokeStatic (client.clj:1194)
    clj_http.client$post.doInvoke (client.clj:1190)
    clojure.lang.RestFn.invoke (RestFn.java:460)
    [...]

I've also seen

java.net.SocketException: Too many open files
 at java.net.Socket.createImpl (Socket.java:501)
    java.net.Socket.getImpl (Socket.java:534)
    java.net.Socket.setSoTimeout (Socket.java:1195)
    org.apache.http.impl.conn.DefaultHttpClientConnectionOperator.connect (DefaultHttpClientConnectionOperator.java:120)
    org.apache.http.impl.conn.BasicHttpClientConnectionManager.connect (BasicHttpClientConnectionManager.java:325)
    org.apache.http.impl.execchain.MainClientExec.establishRoute (MainClientExec.java:381)
    org.apache.http.impl.execchain.MainClientExec.execute (MainClientExec.java:237)
    org.apache.http.impl.execchain.ProtocolExec.execute (ProtocolExec.java:185)
    org.apache.http.impl.execchain.RetryExec.execute (RetryExec.java:89)
    org.apache.http.impl.execchain.RedirectExec.execute (RedirectExec.java:111)
    org.apache.http.impl.client.InternalHttpClient.doExecute (InternalHttpClient.java:185)
    org.apache.http.impl.client.CloseableHttpClient.execute (CloseableHttpClient.java:83)
    clj_http.core$request.invokeStatic (core.clj:626)
    clj_http.core$request.invoke (core.clj:554)
    clj_http.core$request.invokeStatic (core.clj:555)
    clj_http.core$request.invoke (core.clj:554)
    clojure.lang.Var.invoke (Var.java:384)
    clj_http.client$wrap_request_timing$fn__75749.invoke (client.clj:1085)
    clj_http.headers$wrap_header_map$fn__74758.invoke (headers.clj:147)
    clj_http.client$wrap_query_params$fn__75629.invoke (client.clj:819)
    clj_http.client$wrap_basic_auth$fn__75635.invoke (client.clj:842)
    clj_http.client$wrap_oauth$fn__75640.invoke (client.clj:859)
    clj_http.client$wrap_user_info$fn__75649.invoke (client.clj:879)
    clj_http.client$wrap_url$fn__75731.invoke (client.clj:1037)
    clj_http.client$wrap_decompression$fn__75400.invoke (client.clj:420)
    clj_http.client$wrap_input_coercion$fn__75553.invoke (client.clj:639)
    clj_http.client$wrap_additional_header_parsing$fn__75578.invoke (client.clj:694)
    clj_http.client$wrap_output_coercion$fn__75540.invoke (client.clj:583)
    clj_http.client$wrap_exceptions$fn__75346.invoke (client.clj:254)
    clj_http.client$wrap_accept$fn__75593.invoke (client.clj:737)
    clj_http.client$wrap_accept_encoding$fn__75600.invoke (client.clj:759)
    clj_http.client$wrap_content_type$fn__75587.invoke (client.clj:720)
    clj_http.client$wrap_form_params$fn__75696.invoke (client.clj:961)
    clj_http.client$wrap_nested_params$fn__75717.invoke (client.clj:995)
    clj_http.client$wrap_flatten_nested_params$fn__75726.invoke (client.clj:1019)
    clj_http.client$wrap_method$fn__75654.invoke (client.clj:895)
    clj_http.cookies$wrap_cookies$fn__74656.invoke (cookies.clj:131)
    clj_http.links$wrap_links$fn__75144.invoke (links.clj:63)
    clj_http.client$wrap_unknown_host$fn__75734.invoke (client.clj:1048)
    clj_http.client$request_STAR_.invokeStatic (client.clj:1176)
    clj_http.client$request_STAR_.invoke (client.clj:1169)
    clj_http.client$get.invokeStatic (client.clj:1182)
    clj_http.client$get.doInvoke (client.clj:1178)
    clojure.lang.RestFn.invoke (RestFn.java:423)
    [...]

When logging the number of active threads with (Thread/activeCount) it looks like each async request is opening a truly insane number of threads:

Requests in flight: 0 (0 queued) (435 total active threads) 
Requests in flight: 1 (0 queued) (544 total active threads) 
Requests in flight: 2 (0 queued) (568 total active threads) 
Requests in flight: 3 (0 queued) (574 total active threads) 
Requests in flight: 3 (0 queued) (575 total active threads) 
Requests in flight: 5 (0 queued) (583 total active threads) 
Requests in flight: 6 (0 queued) (592 total active threads) 
Requests in flight: 7 (0 queued) (732 total active threads) 
Requests in flight: 8 (0 queued) (743 total active threads) 
Requests in flight: 8 (0 queued) (744 total active threads) 
Requests in flight: 10 (0 queued) (769 total active threads) 
Requests in flight: 11 (0 queued) (775 total active threads) 
Requests in flight: 12 (0 queued) (786 total active threads) 
Requests in flight: 13 (0 queued) (799 total active threads) 
Requests in flight: 14 (0 queued) (805 total active threads) 
Requests in flight: 15 (0 queued) (807 total active threads) 
Requests in flight: 15 (0 queued) (807 total active threads) 
Requests in flight: 16 (1 queued) (807 total active threads) 
Requests in flight: 18 (0 queued) (808 total active threads) 
Requests in flight: 18 (0 queued) (808 total active threads)

Compare the same loop, using

(future (http/post url request))

Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 2 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 2 (1 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 5 (1 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 0 (0 queued) (159 total active threads) 
Requests in flight: 7 (0 queued) (159 total active threads) 
Requests in flight: 5 (0 queued) (159 total active threads) 
Requests in flight: 2 (2 queued) (159 total active threads) 
Requests in flight: 11 (0 queued) (159 total active threads) 
Requests in flight: 13 (1 queued) (159 total active threads) 
Requests in flight: 15 (1 queued) (159 total active threads) 
Requests in flight: 19 (0 queued) (159 total active threads)

So I guess the fact that it's opening so many threads is causing me to hit the ulimit for my java process. Any ideas why this might be happening?

camsaul avatar Mar 04 '20 21:03 camsaul

Did you ever get to the bottom of this?

I'm not too familiar with the async workflow, however from a cursory glance, I have a hunch (unproven) that perhaps the connections in the async pool are not cleaning up properly (one per request).

One suggestion I have to try and uncover this is to create a single async connection manager and bind it in the request to see if that changes the # of active threads.

rymndhng avatar Apr 03 '20 14:04 rymndhng

I think I'm seeing the same problem.

[clj-http "3.10.1"]

Here's the code I'm using:

; get number of threads and file descriptors
{:threads (Thread/activeCount)
 :files (.getOpenFileDescriptorCount (ManagementFactory/getOperatingSystemMXBean))}

(def n 1)

; Sync
(dotimes [i n]
  (clojure.core.async/thread
    (println "starting request" i)
    (try
      (http/get "http://localhost:8080/delay")
      (println "request" i "responded")
      (catch Throwable e
        (println "request" i "threw" e)))))

; Async
(dotimes [i n]
  (println "starting request" i)
  (http/get "http://localhost:8080/delay"
            {:async? true}
            (fn [r] (println "request" i "responded"))
            (fn [e] (println "request" i "threw" e))))

When I first start the repl with lein repl:

{:threads 11, :files 95}

With n=1 while the sync request is running:

{:threads 12, :files 98}

Then it goes back to:

{:threads 12, :files 97}

With n=1 while the async request is running:

{:threads 20, :files 126}

Then back to:

{:threads 11, :files 98}

With n=100, sync requests:

{:threads 111, :files 200}

then

{:threads 111, :files 100}

With n=100, async requests, only the first 33 get started. Then:

Execution error (IOException) at sun.nio.ch.IOUtil/makePipe (IOUtil.java:-2).
Too many open files

{:threads 308, :files 1024}

chriswatrous avatar May 10 '20 21:05 chriswatrous

Ok, creating an async connection manager seems to solve it.

; get number of threads and file descriptors
{:threads (Thread/activeCount)
 :files (.getOpenFileDescriptorCount (ManagementFactory/getOperatingSystemMXBean))}

(def n 100)

(def acm (clj-http.conn-mgr/make-reusable-async-conn-manager
           {:threads n
            :default-per-route n}))
(dotimes [i n]
  (println "starting request" i)
  (http/get "http://localhost:8080/delay"
            {:async? true
             :connection-manager acm}
            (fn [r] (println "request" i "responded"))
            (fn [e] (println "request" i "threw " e))))

After startup:

{:threads 11, :files 95}

After creating the async connection manager:

{:threads 20, :files 122}

While requests are running:

{:threads 20, :files 228}

After requests completed (and a few more seconds to wait for the cached connections to close):

{:threads 20, :files 128}

With n=800 it goes up to:

{:threads 20, :files 925}

From experimenting it looks like both :threads and :default-per-route are required to get all of the requests to run in parallel but :threads doesn't seem to control the actual number of threads created.

chriswatrous avatar May 11 '20 03:05 chriswatrous

but :threads doesn't seem to control the actual number of threads created.

related: https://github.com/dakrone/clj-http/issues/633

DerGuteMoritz avatar Oct 18 '23 08:10 DerGuteMoritz