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.

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

Hyper slowness issue #11203

Closed
gvanem opened this issue May 25, 2023 · 48 comments
Closed

Hyper slowness issue #11203

gvanem opened this issue May 25, 2023 · 48 comments

Comments

@gvanem
Copy link
Contributor

gvanem commented May 25, 2023

I did this

Trying to transfer 3 URLs like:

https://api.adsb.lol/api/0/route/SAS4133 
https://api.adsb.lol/api/0/route/BBD6810
https://api.adsb.lol/api/0/route/THY19Y

to get Airplane flight-information (in series or parallel), causes curl to hang for a really long time between each URL.
But only when built with -DUSE_HYPER !? Entering the URLs either from a config-file or set on the command-line doesn't matter.
A simple get-urls.bat file to reproduce:

@echo off
setlocal
set CURL_SSL_BACKEND=schannel
echo url=https://api.adsb.lol/api/0/route/SAS4133  > %TEMP%\curl_urls.txt
echo url=https://api.adsb.lol/api/0/route/BBD6810 >> %TEMP%\curl_urls.txt
echo url=https://api.adsb.lol/api/0/route/THY19Y  >> %TEMP%\curl_urls.txt
curl -s -K - < %TEMP%\curl_urls.txt | grep "_airport_codes_iata"

Running the above .bat file takes at least 1 minute to complete! With --parallel or not.

I expected the following

The transfer to complete in < 1 sec. as the curl.exe bundled with Win-10 does:

timer & c:\windows\system32\curl.exe -s https://api.adsb.lol/api/0/route/SAS4133 https://api.adsb.lol/api/0/route/BBD6810 https://api.adsb.lol/api/0/route/THY19Y | grep "_airport_codes_iata"  & timer
Timer 1 on:  9:42:26
  "_airport_codes_iata": "CGN-BLL-KEF",
  "_airport_codes_iata": "SFO-IST",
  "_airport_codes_iata": "BGO-SVG",
Timer 1 off:  9:42:26  Elapsed: 0:00:00,45

c:\windows\system32\curl -V
curl 8.0.1 (Windows) libcurl/8.0.1 Schannel WinIDN
Release-Date: 2023-03-20

Adding the --parallel option I'd assume the URLs would be issued in parallel. Doesn't look so to me.

Version info:

curl -V
curl 8.2.0-DEV (x86_64-pc-win32) libcurl/8.2.0-DEV (OpenSSL/3.2.0) Schannel 
  (rustls-ffi/0.10.0/rustls/0.21.0) zlib/1.2.12 brotli/1.0.9 zstd/1.5.2 c-ares/1.19.0 libssh2/1.10.1_DEV Hyper/1.0.0-rc.3
Release-Date: [unreleased]
Protocols: dict file ftp ftps gopher gophers http https imap imaps ldap ldaps mqtt pop3 pop3s scp sftp smb smbs smtp 
  smtps telnet tftp ws wss
Features: alt-svc AsynchDNS brotli HSTS HTTP2 HTTPS-proxy Kerberos Largefile libz MultiSSL NTLM SPNEGO SSL SSPI threadsafe 
  TLS-SRP UnixSockets zstd

I'm on Windows-10, 22H2 (OS-build 19045.2965).

@gvanem
Copy link
Contributor Author

gvanem commented May 26, 2023

After updating Rust with:

  rustup update
  rustup toolchain install nightly-x86_64-pc-windows-msvc
  rustup override set nightly-x86_64-pc-windows-msvc

a git pull of Hyper's master and rebuilding everything, this issue persists.

@bagder
Copy link
Member

bagder commented May 29, 2023

Reproduces for me as well on Linux.

@icing
Copy link
Contributor

icing commented May 30, 2023

Added some debug info's to this. I see that in Curl_hyper_stream()which is called by curl's transfer loop:

  1. socket gives POLLIN event
  2. Curl_hyper_stream() is called
  3. hyper_waker_wake(h->read_waker) is called
  4. socket input reads the HTTP response
  5. hyper_executor_poll(h->exec); gives HYPER_TASK_EMPTY
  6. Curl_hyper_stream() returns
  7. time passes
  8. transfer loop calls this transfer again after 100ms or more
  9. no POLL event, no hyper_wake..., NO network IO
  10. hyper_executor_poll(h->exec); gives HYPER_TASK_RESPONSE

this explains the "slowness" of handling hyper transfers.

Experimentally, if I change step 5 to call hyper_executor_poll(h->exec); a second time, directly after the EMPTY result, it delivers HYPER_TASK_RESPONSE and the transfers are fast.

This seem to be y hyper internal synchronization issue that make IO result not available though they have been processed internally. Only when calling the hyper poll function again, the result is returned.

@gvanem
Copy link
Contributor Author

gvanem commented Jun 1, 2023

@icing

Only when calling the hyper poll function again, the result is returned.

Hope someone (you?) is working on a fix. I'm clueless about such internal details.

@icing icing self-assigned this Jun 1, 2023
@icing
Copy link
Contributor

icing commented Jun 1, 2023

@gvanem you are right. I wanted to document my observations to drag the hyper project in. I think this is a bug on their behalf, but if the insist everything is fine, we'll make a workaround in curl.

@icing
Copy link
Contributor

icing commented Jun 1, 2023

Opened hyperium/hyper#3237

@bagder
Copy link
Member

bagder commented Jun 1, 2023

We also have #10803 as known bug now. It is a memory-leak with hyper as a backend.

icing added a commit to icing/curl that referenced this issue Jun 19, 2023
- refs curl#11203 where hyper was reported as being slow
- fixes hyper_executor_poll to loop until it is out of
  tasks as advised by @seanmonstar in hyperium/hyper#3237
- added a fix in hyper io handling for detecting EAGAIN
- added some debug logs to see IO results
- pytest http/1.1 test cases pass
- pytest h2 test cases fail on connection reuse. HTTP/2
  connection reuse does not seem to work. Hyper submits
  a request on a reused connection, curl's IO works and
  thereafter hyper declares `Hyper: [1] operation was canceled: connection closed`
  on stderr without any error being logged before.
@icing
Copy link
Contributor

icing commented Jun 19, 2023

On advisement of @seanmonstar I made some small changes that resolve the slowness for me. Pr in #11344.

I see our http/1.1 test cases work, h2 has issues with connection reuse.

@bagder bagder closed this as completed in 81e6793 Jun 20, 2023
@bagder
Copy link
Member

bagder commented Jun 20, 2023

Does not fix it for @gvanem apparently

@bagder bagder reopened this Jun 20, 2023
bch pushed a commit to bch/curl that referenced this issue Jul 19, 2023
- refs curl#11203 where hyper was reported as being slow
- fixes hyper_executor_poll to loop until it is out of
  tasks as advised by @seanmonstar in hyperium/hyper#3237
- added a fix in hyper io handling for detecting EAGAIN
- added some debug logs to see IO results
- pytest http/1.1 test cases pass
- pytest h2 test cases fail on connection reuse. HTTP/2
  connection reuse does not seem to work. Hyper submits
  a request on a reused connection, curl's IO works and
  thereafter hyper declares `Hyper: [1] operation was canceled: connection closed`
  on stderr without any error being logged before.

Fixes curl#11203
Reported-by: Gisle Vanem
Advised-by: Sean McArthur
Closes curl#11344
@bagder bagder closed this as completed in d54d5bf Jul 31, 2023
@nnethercote
Copy link
Contributor

I can replicate the slowness on Linux. I used this script:

#! /bin/sh
curl -s -K - <<EOF | grep "_airport_codes_iata"
url=https://api.adsb.lol/api/0/route/SAS4133
url=https://api.adsb.lol/api/0/route/BBD6810
url=https://api.adsb.lol/api/0/route/THY19Y
EOF

With normal curl it takes 1-2 seconds to complete. With curl+hyper it takes about a minute; the first result comes immediately, then there is a pause of about 30 seconds before the second result, then another pause of about 30 seconds before the third result.

@nnethercote
Copy link
Contributor

We also have #10803 as known bug now. It is a memory-leak with hyper as a backend.

#10803 has now been fixed. It is unrelated to this issue.

@gvanem
Copy link
Contributor Author

gvanem commented Aug 29, 2023

With everything up-to-date, .bat file above now shows Hyper is 20 sec slower than before:

Using 'c:\Windows\system32\curl.exe':
  "_airport_codes_iata": "BGO-SVG",
  "_airport_codes_iata": "CGN-BLL-KEF",
  "_airport_codes_iata": "SFO-IST",
Timer 1 off: 13:01:11  Elapsed: 0:00:01,515

Using 'curl -- tip of git master':
  "_airport_codes_iata": "CGN-BLL-KEF",
  "_airport_codes_iata": "SFO-IST",
Timer 1 off: 13:03:58  Elapsed: 0:01:01,321

Besides the response of first URL got dropped in some cases!

@nnethercote
Copy link
Contributor

Some notes from my investigations:

The first response arrives quickly. After that, logging shows that Curl_hyper_stream is called once per second for 30 seconds with select_res of 0. Every time hyper_executor_poll returns NULL and so Curl_hyper_stream returns without doing anything other than setting *didwhat = KEEP_RECV. Finally after 30 calls, Curl_hyper_stream is called with select_res of 1, and then things start happening. And it's a similar story for the third response.

I grepped for 30 and found that the -y/--speed-time option affects the behaviour here. If I use -y 5 then the 30 second loop is reduced to 5 seconds, but the middle response doesn't arrive, and the whole thing takes a little over 5 seconds. In fact, any -y value less than 30 seems to cause this drop-the-middle-response behaviour.

The 1 second delay comes from a Curl_poll call with a timeout of 1000ms in multi_wait.

multi_wait calls multi_timeout, to possibly adjust the timeout down from 1000ms. Normal curl frequently adjusts this down to very small numbers: 0, 1, etc. curl+hyper never does, because it doesn't have multi->timetree.

Questions:

  • Why does vanilla curl end up with a non-zero select_res (from Curl_socket_check) so much more quickly than curl+hyper?
  • And what changes at the 30 second mark for curl+hyper?

@bagder
Copy link
Member

bagder commented Aug 30, 2023

When the 30 second hang occurs, curl wants to send off the (second) request over the connection. But due to hyper's asynch API and behavior (combined with some bug in curl obviously) curl does not know it is still sending the request but it has already moved on to the PERFORMING state and since this is a plain GET, it does not wait for the socket to be writable and thus it sits there waiting without sending the request.

(Presumably the socket gets readable after 30 seconds anyway for some reason and that triggers the send to get sent.)

This is can be seen by multi_getsock() getting called and the handle being in state MSTATE_PERFORMING before the request has been sent. The native HTTP will issue the request in the DO or DOING states.

@bagder
Copy link
Member

bagder commented Aug 30, 2023

My adjusted reproduce script with tracing + time stamps

#! /bin/sh
./src/curl --trace-ascii - --trace-time -K - <<EOF | tee dump
url=https://api.adsb.lol/api/0/route/SAS4133
url=https://api.adsb.lol/api/0/route/BBD6810
url=https://api.adsb.lol/api/0/route/THY19Y
EOF

@nnethercote
Copy link
Contributor

Vanilla curl is using http/1.1 while curl+hyper is using h2. Is that significant?

@nnethercote
Copy link
Contributor

Also, the 30 second thing might be due to an SSL timeout, which trigger a new connection?

@bagder
Copy link
Member

bagder commented Aug 31, 2023

Vanilla curl is using http/1.1 while curl+hyper is using h2. Is that significant?

My vanilla build uses h2 for this. But no, that does not matter.

Also, the 30 second thing might be due to an SSL timeout, which trigger a new connection?

No, the trace shows no new connection. And a curl will not silently do a new connection if a transfer fails in the middle, it would return an error.

@marlonbaeten
Copy link

Would you see any problems in reusing the executor / client for multiple requests?

No. The easy handles are already encouraged to be reused in the public libcurl API. If we can reuse more parts within it, we should.

I have looked into persisting the hyptransfer struct between requests, but I can't pinpoint the appropriate place to do this. Do you have any suggestions?

@bagder
Copy link
Member

bagder commented Sep 19, 2023

The hypertransfer struct itself persists between requests since it is a member of the struct Curl_easy struct, which is the CURL * handle's internal version.

Curl_http_done() gets called when the request is "done" (reaches DONE state) and that then calls Curl_hyper_done() which currently seems to free most/all hyper related resources. I presume it should keep some of them around longer and instead rather close them later. Maybe in Curl_close() which is the function that kills and frees the handle.

Note that this handle is the handle for a transfer, but not for data that associated with the connections. They are in the struct connectdata as a single transfer very well may involve one or more connections and connections can survive and be used by other transfers.

@folkertdev
Copy link

is struct curl_easy the right place for the executor then? it is most efficient to only create the executor once, and then reuse it for any request that curl makes while it runs. So maybe it should instead live in struct connectdata?


The hypertransfer struct itself persists between requests since it is a member of the struct Curl_easy struct, which is the CURL * handle's internal version.

Yes, but somehow the executor gets cleared and we can't figure out why. This patch

  • disables a memset that would clear the pointer to the executor
  • disables the freeing of the executor
diff --git a/lib/c-hyper.c b/lib/c-hyper.c
index 61ca29a3a..d72c2c575 100644
--- a/lib/c-hyper.c
+++ b/lib/c-hyper.c
@@ -912,8 +912,11 @@ CURLcode Curl_http(struct Curl_easy *data, bool *done)
      the rest of the request in the PERFORM phase. */
   *done = TRUE;
 
+  infof(data, "-------------------------> the hyptransfer pointer is %p", h);
+  infof(data, "-------------------------> the executor pointer is %p", h->exec);
+
   infof(data, "Time for the Hyper dance");
-  memset(h, 0, sizeof(struct hyptransfer));
+  // memset(h, 0, sizeof(struct hyptransfer));
 
   result = Curl_http_host(data, conn);
   if(result)
@@ -1261,8 +1264,8 @@ void Curl_hyper_done(struct Curl_easy *data)
 {
   struct hyptransfer *h = &data->hyp;
   if(h->exec) {
-    hyper_executor_free(h->exec);
-    h->exec = NULL;
+    // hyper_executor_free(h->exec);
+    // h->exec = NULL;
   }
   if(h->read_waker) {
     hyper_waker_free(h->read_waker);

we see this output

*   Trying 104.26.5.74:443...
* Connected to api.adsb.lol (104.26.5.74) port 443
* ALPN: curl offers h2,http/1.1
* rustls_connection wants us to write_tls.
* Curl_socket_check: reading would block
* rustls_connection wants us to read_tls.
* rustls_connection wants us to write_tls.
* rustls_connection wants us to read_tls.
* Curl_socket_check: reading would block
* rustls_connection wants us to read_tls.
* Done handshaking
* ALPN: server accepted h2
* -------------------------> the hyptransfer pointer is 0x55b69b469a18
* -------------------------> the executor pointer is (nil)
* Time for the Hyper dance
> GET /api/0/route/SAS4133 HTTP/2
> Host: api.adsb.lol
> User-Agent: curl/8.4.0-DEV
> Accept: */*
> 
< HTTP/2 200 OK
< date: Tue, 19 Sep 2023 17:00:45 GMT
< content-type: application/json
< content-length: 659
< access-control-allow-origin: *
< access-control-allow-methods: POST, OPTIONS
< access-control-allow-headers: access-control-allow-origin,content-type
< strict-transport-security: max-age=31536000; includeSubDomains
< cf-cache-status: DYNAMIC
< report-to: {"endpoints":[{"url":"https:\/\/a.nel.cloudflare.com\/report\/v3?s=1lneCHWqONSQxNCcJMd5cO9gX7h2SxL01tWW28YlzR7E5HYGTBSAfpW46NhHWrDQ2w%2ForS4K%2Fj6hgTMQCu2DpVwsDgMz58JsinMUg199oTCTxrq1U9QEBl6JaeSKNA%3D%3D"}],"group":"cf-nel","max_age":604800}
< nel: {"success_fraction":0,"report_to":"cf-nel","max_age":604800}
< server: cloudflare
< cf-ray: 809362fd1b0efa40-AMS
< alt-svc: h3=":443"; ma=86400
< 
<http response body>
* hyperstream is done
* Connection #0 to host api.adsb.lol left intact
* Found bundle for host: 0x55b69b4648e0 [can multiplex]
* Re-using existing connection with host api.adsb.lol
* -------------------------> the hyptransfer pointer is 0x55b69b469a18
* -------------------------> the executor pointer is (nil)
* Time for the Hyper dance
> GET /api/0/route/BBD6810 HTTP/2
> Host: api.adsb.lol
> User-Agent: c
...

so hyptransfer is the same pointer, but the executor pointer does get reset. We haven't been able to figure out why this happens.

@bagder
Copy link
Member

bagder commented Sep 19, 2023

is struct curl_easy the right place for the executor then? it is most efficient to only create the executor once, and then reuse it for any request that curl makes while it runs. So maybe it should instead live in struct connectdata?

The executor is independent of the connection, right? Then I think the Curl_easy sounds like exactly the right place for it to be.

the executor pointer does get reset

I can find two places where curl does it:

$ git grep -n 'h->exec = NULL'
lib/c-hyper.c:1265:    h->exec = NULL;
lib/cf-h1-proxy.c:947:    h->exec = NULL;

@folkertdev
Copy link

those are the obvious places, but

  • the first one is commented out by the patch I included. So it does not run
  • the second one does not get run anyway (maybe because we do http2?)

so just a simple grep does not answer the question of why that field is reset. So I tried some fancier debugging by watching the memory address of the executor in the hyptransfer struct (so &h->exec).

* -----------------> the hyptransfer pointer is 0x5555555e2f20
916	  infof(data, "-----------------> the executor pointer field is %p", &h->exec);
(gdb) 
* -----------------> the executor pointer field is 0x5555555e2f30
918	  infof(data, "Time for the Hyper dance");
(gdb) watch *(long **)0x5555555e2f30
Hardware watchpoint 3: *(long **)0x5555555e2f30  # we just need to provide any pointer type here
(gdb) c
Continuing.
* Time for the Hyper dance

Thread 1 "curl" hit Hardware watchpoint 2: *0x5555555e2f30

Old value = 0
New value = 1432576368

Thread 1 "curl" hit Hardware watchpoint 3: *(long **)0x5555555e2f30

Old value = (long *) 0x0
New value = (long *) 0x555555636170
Curl_http (data=0x5555555e1a78, done=0x7fffffffd99e) at c-hyper.c:968
968	    if(!h->exec) {
(gdb) 

So far it kind of makes sense. The line number seems to be off-by-one though, the actual write happens a line earlier. So now if this field were persisted, we'd expect no further changes to it until all requests have completed, right? Well that is not what I see

* hyperstream is done
* STATE: PERFORMING => DONE handle 0x5555555e1a78; line 2550
* multi_done[DONE]: status: 0 prem: 0 done: 0
* Connection #0 to host api.adsb.lol left intact
}
Thread 1 "curl" hit Hardware watchpoint 3: *(long **)0x5555555e2f30

Old value = (long *) 0x555555636170
New value = (long *) 0x555555636100
__memset_avx2_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:151
151	../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S: No such file or directory.
(gdb) bt
#0  __memset_avx2_erms () at ../sysdeps/x86_64/multiarch/memset-vec-unaligned-erms.S:151
#1  0x00007ffff7d03df2 in __libc_calloc (n=<optimized out>, elem_size=<optimized out>) at malloc.c:3480
#2  0x00007ffff7f23f2a in curl_dbg_calloc (wanted_elements=1, wanted_size=5328, line=644, source=0x7ffff7f8d840 "url.c") at memdebug.c:175
#3  0x00007ffff7f5e604 in Curl_open (curl=0x7fffffffd930) at url.c:644
#4  0x00007ffff7ef87be in curl_easy_init () at easy.c:379
#5  0x0000555555575eb2 in single_transfer (global=0x7fffffffddd0, config=0x5555555bd2a8, share=0x5555555ded88, capath_from_env=false, 
    added=0x7fffffffdc9d) at tool_operate.c:945
#6  0x000055555557d3db in transfer_per_config (global=0x7fffffffddd0, config=0x5555555bd2a8, share=0x5555555ded88, added=0x7fffffffdc9d)
    at tool_operate.c:2629
#7  0x000055555557d43b in create_transfer (global=0x7fffffffddd0, share=0x5555555ded88, added=0x7fffffffdc9d) at tool_operate.c:2645
#8  0x000055555557cf66 in serial_transfers (global=0x7fffffffddd0, share=0x5555555ded88) at tool_operate.c:2492
#9  0x000055555557d4f8 in run_all_transfers (global=0x7fffffffddd0, share=0x5555555ded88, result=CURLE_OK) at tool_operate.c:2670
#10 0x000055555557d8ab in operate (global=0x7fffffffddd0, argc=5, argv=0x7fffffffdf48) at tool_operate.c:2786
#11 0x00005555555737b3 in main (argc=5, argv=0x7fffffffdf48) at tool_main.c:274

we hit this place several more times

Old value = (long *) 0x555555636100
New value = (long *) 0x555555630000

Old value = (long *) 0x555555630000
New value = (long *) 0x555555000000

Old value = (long *) 0x555555000000
New value = (long *) 0x555500000000

Old value = (long *) 0x555500000000
New value = (long *) 0x550000000000

Old value = (long *) 0x550000000000
New value = (long *) 0x0

So that just looks like calloc at url.c:644 wiping the memory.

// url.c
/**
 * Curl_open()
 *
 * @param curl is a pointer to a sessionhandle pointer that gets set by this
 * function.
 * @return CURLcode
 */

CURLcode Curl_open(struct Curl_easy **curl)
{
  CURLcode result;
  struct Curl_easy *data;

  /* Very simple start-up: alloc the struct, init it with zeroes and return */
  data = calloc(1, sizeof(struct Curl_easy)); // <- line 644

So, the hypertransfer struct (or its exec field, anyway) just gets wiped after the first request, right? Which suggests that the whole thing has been freed and definitely is not persisted across requests.

But we never see free(data->hyp) in the source code, so how this works is not clear yet.

@bagder
Copy link
Member

bagder commented Sep 20, 2023

Curl_open() is the internal version of curl_easy_init(). It creates a new handle so it is not strange that it clears the struct.

So, the hypertransfer struct (or its exec field, anyway) just gets wiped after the first request, right?

Right now, yes, as I said before

But we never see free(data->hyp) in the source code

It is a sub-struct of struct Curl_easy, it is not individually allocated so there cannot be any separate free of it. It gets freed in Curl_close(), the internal version of curl_easy_cleanup().

ptitSeb pushed a commit to wasix-org/curl that referenced this issue Sep 25, 2023
- refs curl#11203 where hyper was reported as being slow
- fixes hyper_executor_poll to loop until it is out of
  tasks as advised by @seanmonstar in hyperium/hyper#3237
- added a fix in hyper io handling for detecting EAGAIN
- added some debug logs to see IO results
- pytest http/1.1 test cases pass
- pytest h2 test cases fail on connection reuse. HTTP/2
  connection reuse does not seem to work. Hyper submits
  a request on a reused connection, curl's IO works and
  thereafter hyper declares `Hyper: [1] operation was canceled: connection closed`
  on stderr without any error being logged before.

Fixes curl#11203
Reported-by: Gisle Vanem
Advised-by: Sean McArthur
Closes curl#11344
ptitSeb pushed a commit to wasix-org/curl that referenced this issue Sep 25, 2023
@marlonbaeten
Copy link

@bagder thanks a lot for your help!

I was able to persist the hyper client between requests by making it part of the connectdata, which makes sense for HTTP/2, since the connection configuration should happen once per connection.

However I encountered a potential issue in the hyper C API:

  • When using HTTP/1.1 the GET requests are sent immediately after calling hyper_clientconn_send and pushing the resulting task to the executor.
  • When using HTTP/2 the GET request is only sent after calling hyper_clientconn_free on the corresponding hyper client.

A minimal way of reproducing this issue is by not-freeing the hyper client and trying to perform a HTTP/2 request with curl:

diff --git a/lib/c-hyper.c b/lib/c-hyper.c
index c558955c9..c85fb5569 100644
--- a/lib/c-hyper.c
+++ b/lib/c-hyper.c
@@ -1218,8 +1218,8 @@ CURLcode Curl_http(struct Curl_easy *data, bool *done)
   }
   sendtask = NULL; /* ownership passed on */
 
-  hyper_clientconn_free(client);
-  client = NULL;
+  /* hyper_clientconn_free(client);
+  client = NULL; */
 
   if((httpreq == HTTPREQ_GET) || (httpreq == HTTPREQ_HEAD)) {
     /* HTTP GET/HEAD download */

@seanmonstar do you have any idea why the request is not sent if we do not free the client?

@bagder
Copy link
Member

bagder commented Sep 25, 2023

I was able to persist the hyper client between requests by making it part of the connectdata, which makes sense for HTTP/2, since the connection configuration should happen once per connection.

I'm not sure I follow this. What struct did you move? hyper does not manage connections for libcurl, so I fail to see how that is important here. We setup all the necessary configs per request in Curl_http() so couldn't the same structs serve multiple requests done for several connections?

  • When using HTTP/2 the GET request is only sent after calling hyper_clientconn_free on the corresponding hyper client.

That sounds like a hyper bug to me. At least based on the rust API docs for hyper_clientconn_send

@seanmonstar
Copy link
Contributor

do you have any idea why the request is not sent if we do not free the client?

If that's really the case, that would be a hyper bug. I can't think of anything in hyper that would need to wait until it was freed to send.

@jsha
Copy link
Contributor

jsha commented Oct 23, 2023

@marlonbaeten I think I found the source of the "request never sends" problem you found: hyperium/hyper#3369. I also filed a PR that fixes it: hyperium/hyper#3370. Please let us know if that fixes it for you!

For this slowness bug it seems there are two problems:

  • a hyper_clientconn is created for each request, instead of once per connection, causing the connection preface to be sent multiple times, which is invalid HTTP/2
  • when the server sends a GOAWAY frame with an error code, curl silently retries on a new connection (possibly after a delay) or drops the request, rather than reporting it as an error on the request that triggered it.

@marlonbaeten it sounds like you're moving in the right direction with persisting the hyper_clientconn in connectdata. Probably the hyper_executor needs to be there too. Want to share what you've got so far even if it's only a branch-in-progress? I might take a stab at a fix and it would be nice to not duplicate work.

@marlonbaeten
Copy link

@jsha nice work!

I think your summary is correct.

Together with @folkertdev I have tried several approaches in persisting both the hyper_executer and hyper_clientconn between requests. However, I was not able to persist these without triggering memory issues, and concluded that it requires more in-depth knowledge to do this without introducing any bugs. So our tests might not be the correct starting point. Just to summarize:

  • Keeping hyptransfer in the Curl_easy struct and removing the places where (parts) are cleared [1] still does not prevent it from being cleared [2] - it seems that Curl_open is called between requests which could cause this issue.
  • Making the hyper_clientconn part of the connectdata seems more appropriate and does help persisting the data, but triggers all kinds of memory issues that I was not able to debug.
  • I guess the hyper_executer should not be part of connectdata, since there might be multiple connections and, I think, there should only be one hyper_executer

I hope to try out your fix for hyper this week.

Good luck!

[1] #11203 (comment)
[2] #11203 (comment)

@bagder
Copy link
Member

bagder commented Oct 23, 2023

the Curl_easy struct and removing the places where (parts) are cleared [1] still does not prevent it from being cleared [2] - it seems that Curl_open is called between requests which could cause this issue.

Curl_easy is a handle for a single transfer ( but it can be reused) while connectdata is for a specific connection. A transfer can use one or more connections to perform a single transfer.

Curl_open() creates a new easy handle (it is the internal version of curl_easy_init()) and a new transfer can reuse a connection that was previously used by another transfer if the conditions are right - or create a new one.

Making the hyper_clientconn part of the connectdata seems more appropriate and does help persisting the data, but triggers all kinds of memory issues that I was not able to debug.

I think the libcurl story is easy enough but I can't tell much about hyper and how we are supposed to work with it since the API is undocumented unless you can do the rust-to-C translation in your head. And it seems very few can.

@jsha
Copy link
Contributor

jsha commented Oct 24, 2023

I've dug into this a little and feel like I made good progress, but I believe I'm running into an issue of conflicting lifecycles. If you want to view my branch-in-progress, very non-working, it's here: https://github.com/curl/curl/compare/master...jsha:curl:fix-hyper?expand=1

Here's the lifecycle issue. @bagder and @seanmonstar please correct me if I'm wrong about these assumptions.

Hyper has read and write callbacks. These get bundled into a hyper_io * object, which gets bundled into a hyper_clientconn_handshake *, which eventually gets bundled into a hyper_clientconn *. Once they're in there, they can't be changed for the lifetime of the hyper_clientconn *, which is the lifetime of the TCP / TLS connection.

Also bundled into the hyper_clientconn * is a void *userp to be passed to the read and write callbacks. It is set at creation time and never changed for the lifetime of the connection.

Right now Curl sets the void *userp to Curl_easy *data. That's handy for the callbacks (Curl_hyper_recv and Curl_hyper_send), because those delegate to Curl_read / Curl_write, which want a Curl_easy *. However, I think it's semantically wrong. A Curl_easy * represents a transfer, and one connection may serve many transfers during its lifetime.

Really, I think the void *userp should be set to a struct connectdata *conn, since it has to be chosen once at the start of the connection and can never be changed.

But that runs into a problem. The connectdata has fields recv and send, through which we should send all data. But they have a signature like this:

curl/lib/urldata.h

Lines 145 to 158 in 31d96af

/* return the count of bytes sent, or -1 on error */
typedef ssize_t (Curl_send)(struct Curl_easy *data, /* transfer */
int sockindex, /* socketindex */
const void *buf, /* data to write */
size_t len, /* max amount to write */
CURLcode *err); /* error to return */
/* return the count of bytes read, or -1 on error */
typedef ssize_t (Curl_recv)(struct Curl_easy *data, /* transfer */
int sockindex, /* socketindex */
char *buf, /* store data here */
size_t len, /* max amount to read */
CURLcode *err); /* error to return */

In other words, to do a read or write, we need to pass a valid Curl_easy *. But if we make the hyper_clientconn * part of the connectdata instead of the Curl_easy, then it can never get a pointer to the current Curl_easy in order to pass it to recv / send.

Is there any object we can set as the void *userp in a hyper_io * / hyper_clientconn * that lives as long as the connection, and allows us to find a Curl_easy * when we need to send / receive? I've thought about adding a pointer from connectdata to the currently functioning Curl_easy * but I figure that must be wrong or it probably would already have been done for convenience in other areas. :D

@bagder
Copy link
Member

bagder commented Oct 24, 2023

Great research @jsha

In curl a single connection might have many concurrent transfers (when multiplexed) so a connection cannot itself identify a single transfer - each connection has a list transfers. Also, every ongoing transfer has a single current connection it uses (at a time). An individual connection is used by none, one or many transfers.

I've thought about adding a pointer from connectdata to the currently functioning Curl_easy * but I figure that must be wrong or it probably would already have been done for convenience in other areas. :D

Right. Because the connection can be used by up to several hundred concurrent transfers...

@icing
Copy link
Contributor

icing commented Oct 24, 2023

There are other places in curl with the same use pattern/problem. Callbacks in OpenSSL, nghttp2 and quiche.

The solution there, all of those being connection filters, is to either:

  • set the "current" easy handle in the filter's context and look it up from there in a callback
  • have an id for the transfer (e.g. HTTP stream id) and look up the matching easy handle at the multi.

Moving hyper from a http "protocol handler" replacement to a connection filter is not a small task. But it might be the better design.

@jsha
Copy link
Contributor

jsha commented Oct 24, 2023

Great, thanks for the confirmation @bagder. And thanks for pointing a way forward @icing.

I think for the short term, we should disable HTTP/2 support in the Hyper integration, because it's broken (sends the connection preface on every request) and requires a rearchitecture to fix, which might take some time. The other alternative would be to have the HTTP/2 support send only a single request per connection. But it seems better to fall back to HTTP/1.1 where connections can be reused.

@jsha
Copy link
Contributor

jsha commented Oct 24, 2023

I've posted #12191 with the quick / temporary fix of disabling HTTP2 with Hyper.

@jsha
Copy link
Contributor

jsha commented Nov 19, 2023

I've posted hyperium/hyper#3424 adding documentation for Hyper's FFI API.

@bagder @icing would one of you be willing to add more detail to the connection filter docs and/or cfilters.h? I looked at docs/CONNECTION-FILTERS.md and I don't understand how the connection filter API handles multiplexing of multiple requests on a single connection. Also, the docs suggest that HTTP/2 might be a connection filter, which seems to be presently the case, so maybe it needs some updating? Thanks!

@gvanem
Copy link
Contributor Author

gvanem commented Nov 24, 2023

@jsha After getting the latest Hyper + curl from git master and rebuilding everything, the speed has improved
very much.

The API at ADSB-LOL has changed into a new JSON-format. So with this .bat-file:

@echo off
setlocal
set CURL_SSL_BACKEND=schannel
set URLS= https://vrs-standing-data.adsb.lol/routes/SA/SAS4133.json ^
          https://vrs-standing-data.adsb.lol/routes/BB/BBD6810.json ^
          https://vrs-standing-data.adsb.lol/routes/TH/THY19Y.json

echo Using 'c:\Windows\system32\curl.exe':
timer
c:\Windows\system32\curl.exe -s %URLS% > NUL
timer

echo.
echo Using 'curl -- tip of git master':
timer 
%~dp0\src\curl -s %URLS% > NUL
timer

The timings are:

Using 'c:\Windows\system32\curl.exe':
Timer 1 off: 10:05:45  Elapsed: 0:00:00,233

Using 'curl -- tip of git master':
Timer 1 off: 10:05:46  Elapsed: 0:00:01,137

Much better; not >1 minute as before.
But the Win-10 bundled curl (w/o Hyper) is still ~5 times faster.

@jsha
Copy link
Contributor

jsha commented Nov 27, 2023

@gvanem thanks for verifying that things got faster.

I'm not very surprised that the Hyper backend is still slightly slower than the nghttp2 (default) backend, because the hyper backend is now using HTTP/1.1. I'm guessing that curl serializes the requests when using HTTP/1.1 and parallelizes them when using HTTP/2.

I think the solution will be as @icing said: to rewrite the Hyper backend as a connection filter so we can restore HTTP/2 support with the Hyper backend and have it work properly.

@gvanem
Copy link
Contributor Author

gvanem commented Dec 2, 2023

to rewrite the Hyper backend as a connection filter so we can restore HTTP/2 support with the Hyper backend and
have it work properly.

Has this been done? Just rebuilt everything and now it's only 20% slower than the Win-10 bundled curl:

Using 'c:\Windows\system32\curl.exe':
Timer 1 on: 10:18:49
Timer 1 off: 10:18:49  Elapsed: 0:00:00,803

Using 'curl -- tip of git master':
Timer 1 on: 10:18:49
Timer 1 off: 10:18:50  Elapsed: 0:00:00,974

@bagder
Copy link
Member

bagder commented Feb 10, 2024

This is mentioned in KNOWN_BUGS.

@bagder bagder closed this as completed Feb 10, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Development

No branches or pull requests

9 participants