dakrone / clj-http

An idiomatic clojure http client wrapping the apache client. Officially supported version.
http://clojars.org/clj-http
MIT License
1.78k stars 408 forks source link

Async client opens dozens of threads #537

Open camsaul opened 4 years ago

camsaul commented 4 years ago

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?

rymndhng commented 4 years ago

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.

chriswatrous commented 4 years ago

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 commented 4 years ago

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.

DerGuteMoritz commented 11 months ago

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

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