Is short bursts of busyloop normal with HTTP/2 despite no activity?

[denizsokmen]

Discussed in #16080

^{Originally posted by denizsokmen January 24, 2025}
I wasn't sure to create this as an issue, as I also haven't dived into it myself. I use multi interface with libcurl 8.9.1 and nghttp2 1.63.0, I have a typical loop in a thread that takes requests, does curl_multi_perform, processes messages, calls curl_multi_poll to avoid busyloop. I noticed that in some of the HTTP/2 requests, curl_multi_poll returns immediately with no numfds set, hundreds of times just to send 80KB of data at the end. There's simply no activity on any sockets until the last step where 80KB data is finally sent:

 STATE: DO => DID handle 0x12ea30a00; line 2237
 STATE: DID => PERFORMING handle 0x12ea30a00; line 2355
 curl_multi_perform running handles: 1, numfd after multi_poll: 1, timeout: 1000
 multi changed, check CONNECT_PEND queue

...
hundreds of these spammed in just a few milliseconds:
 curl_multi_perform running handles: 1, numfd after multi_poll: 0, timeout: 0
...

finally:
 curl_multi_perform running handles: 1, numfd after multi_poll: 1, timeout: 1000
 upload completely sent off: 83671 bytes

In summary, something is setting the timeout to 0 in http/2 requests, turning the downloader thread into a busyloop. Is this normal?

[denizsokmen]

More verbose logs after the request finishes

 upload completely sent off: 83671 bytes
 HTTP/2 found, allow multiplexing
 HTTP/2 200 
 date: Fri, 24 Jan 2025 22:46:33 GMT
 access-control-allow-headers: Access-Control-Allow-Headers,Origin,Accept,X-Requested-With,Content-Type,Access-Control-Request-Method,Access-Control-Request-Headers
 access-control-allow-methods: GET,HEAD,POST,PUT,OPTIONS
 access-control-allow-origin: *
 readwrite_data: we are done
 nread == 0, stream closed, bailing
 STATE: PERFORMING => DONE handle 0x171d62800; line 2550
 multi_done[DONE]: status: 0 prem: 0 done: 0
 multi_done, not reusing connection=35, forbid=1, close=0, premature=0, conn_multiplex=1
 The cache now contains 0 members
 Curl_disconnect(conn #35, aborted=0)
 shutting down connection #35
 shutdown start on connection
 TLSv1.2 (OUT), TLS alert, close notify (256):
 [CCACHE] shutdown #35, done=0
 [CCACHE] added #35 to shutdown list of length 1
 Expire cleared

[denizsokmen]

Removing data_pending check from https://github.com/curl/curl/blob/master/lib/transfer.c#L357 seems to fix the "problem" here, though I don't know what else breaks if I do that. I guess the problem here is that readwrite_data seems to be meant for recvs, but the data_pending filter in http2 returns true for either of recv and send cases. And so the POST transfer here marks itself as "try me again immediately" just because it has some pending data in sendbuf, in a function that cares about reads. So it just retries infinitely until the socket is actually writable despite not getting any legit socket activity from poll or a prior send() call suggesting to do that.

[icing]

Thanks, @denizsokmen for the report. The behaviour of the HTTP/2 filter was indeed wrong. The semantics for data_pending() is to check if any received data is still lingering in buffers.

I propose to fix this via #16098.