https://bz.apache.org/bugzilla/show_bug.cgi?id=70302
Bug ID: 70302
Summary: mod_http2: stream finishing in hold logged only at
KeepAliveTimeout
Product: Apache httpd-2
Version: 2.4.69
Hardware: PC
OS: Linux
Status: NEW
Severity: normal
Priority: P2
Component: mod_http2
Assignee: [email protected]
Reporter: [email protected]
Target Milestone: ---
Created attachment 40242
--> https://bz.apache.org/bugzilla/attachment.cgi?id=40242&action=edit
Reproduction: httpd + php-fpm + Node http2 client, see README.txt
I noticed occasional HTTP/2 requests in my access log whose %T was
exactly KeepAliveTimeout (5 s, and 3 s after I lowered it to 3), while
%^FB for the same requests was a few ms. It only ever happened over
HTTP/2, to roughly one request in a few thousand, and it threw off my
latency percentiles and alerts. Switching the vhosts to http/1.1 made it
go away.
Reading mod_http2, I think this is what happens: if c1 cleans up a
stream while its c2 hasn't reported done yet, the stream is parked in
m->shold (h2_mplx.c:187-195). When c2 then finishes, s_c2_done takes the
"c2_done, in hold" branch (h2_mplx.c:1042-1047), and c1c2_stream_joined
(h2_mplx.c:141-147) only adds the stream to m->spurge. Unlike the
"stream open" branch right above it (h2_mplx.c:1034-1041), nothing wakes
c1 up. If c1 has already gone through h2_mplx_c1_going_keepalive
(h2_mplx.c:659-666, called from h2_session.c:2146) and the connection is
sitting in the event MPM's keepalive queue, the stream stays in spurge
until the keepalive timeout closes the connection. Only then is the EOR
bucket destroyed and the request logged, and mod_log_config takes the
end time at that moment (mod_log_config.c:637).
So as far as I can tell the client isn't affected, it gets the response
right away. But the request is logged late and the c2 pool is held
until the connection closes.
--------------
Steps to reproduce
The attached mod_http2-hold-repro.tar.gz runs httpd (mpm_event, mod_ssl,
mod_http2, mod_proxy_fcgi) and php-fpm as the current user on
127.0.0.1:18443 with KeepAliveTimeout 2, plus a small Node http2 client.
Each connection sends one GET, waits 900 ms, sends 3 GETs at once, and
then stays open without sending anything for 3 s. The race needs c2 to
be descheduled at the wrong moment, so it helps to put some load on the
CPUs:
CPUS=0-1 CPU_BURNERS=1 ROUNDS=300 CONCURRENT_ROUNDS=30 ./run.sh
--------------
Actual results
In two runs, 17 and 24 of 1201 requests were logged with %T of
2001-2011 ms and %^FB of 0.7-8 ms. The client measured every one of them
under 1.8 s. Without the CPU load it's about 1 in 2000. With HOLD_MS=0
(closing the connection right after the burst) there were none, which
fits: closing the connection purges the stream.
--------------
Expected results
The request is logged, and c2 freed, when the stream is done.
--------------
Version
Apache 2.4.69 (Debian 13 package), mod_http2 2.0.42. I first saw it in
production on Ubuntu. The code looks the same on trunk.
A fix could be to wake c1 in the "in hold" branch like the "stream open"
branch does, or to purge held streams before c1 parks the connection. I
haven't tried either.
--
You are receiving this mail because:
You are the assignee for the bug.
---------------------------------------------------------------------
To unsubscribe, e-mail: [email protected]
For additional commands, e-mail: [email protected]
