httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stefan Eissing <stefan.eiss...@greenbytes.de>
Subject Re: H2 stream dependencies
Date Wed, 25 Nov 2015 09:04:42 GMT
The execution order of requests is not defined by the protocol and up to the server implementation.
As you noticed, one major factor is the mpm active in httpd, influencing how, and if, requests
are handled in parallel.

Even setting dependencies and priorities on streams will not make this fully deterministic,
as I tried to explain.

The case of a prefork mpm without further configuration is an extreme case. Prefork, intended
to allow a single thread processing model, has by default 1(!) http/2 worker. That means that
requests are worked on one at a time. A blocking request may therefore block all later requests.
This is not how HTTP/2 is supposed to work, but  it is how prefork is.

You can configure more H2Workers and have multiple threads even in prefork. But you need to
be sure that the application you run can live with multi-threading.

Without knowing your client that well, it seems to assume that requests are processed one
after the other. And rely on that. This assumption no longer holds in HTTP/2. If you send
2 requests, responses may arrive in any order or interleaved, not matter what you specify
for priority. Relying on the exposed behaviour of a certain implementation under certain configuration
is probably the least that you'd want.

//Stefan



> Am 25.11.2015 um 03:10 schrieb Bert Huijben <bert@qqmail.nl>:
> 
>> -----Original Message-----
>> From: Stefan Eissing [mailto:stefan.eissing@greenbytes.de]
>> Sent: vrijdag 20 november 2015 10:26
>> To: dev@httpd.apache.org
>> Subject: Re: H2 stream dependencies
>> 
>> Bert,
>> 
>> interesting and nice to see the progress. You probably could use priorities for
>> ordering, especially when using the stream dependencies. I am not certain,
>> however, if this will give you totally deterministic behavior. If stream B
>> depends on A, usually A will be sent out before B. However, should stream A
>> become suspended - e.g. unable to progress, either because there is no data
>> available which some other thread needs to produce, or because the flow
>> control window has not been updated in time - the server will start sending
>> data for B.
>> 
>> The state of the implementation is:
>> 2.4.17: fully implemented priority handling on sending stream data, as
>> implemented by the nghttp2 library
> 
> I'm seeing different behavior when running against my FreeBSD httpd 2.4.17 (prefork mpm)
and Windows (winnt mpm) builds.
> 
> Everything appears to work ok when sending a dependency within the headers frame to my
FreeBSD box, while on my Windows build I get responses out of order.
> 
> Is it possible that different requests over the same connection are handled by different
threads in this case?
> 
> Is there any logging that may help me diagnose this further?
> (See log below)
> 
> The propfind is handled by mod_dav, while the report is handled by mod_dav_svn.
> 
> 	Bert
> 
> --
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(58): [client ::1:15125]
h2_stream(12-11): created
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(71): [client ::1:15125]
h2_session: stream(12-11): opened
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_workers.c(303): h2_workers: register
mplx(12)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(167): [client ::1:15125]
h2_mplx(12-11): start stream, task PROPFIND /svn-test-work/local_tmp/repos/!svn/rev/1 (localhost:7829)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(180): [client ::1:15125]
h2_stream(12-11): closing input
> [:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_workers.c(166): h2_worker(14):
start task(12-11)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(420): [client ::1:15125]
h2_stream(12-11): input closed
> [:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(84): [client ::1:15125]
h2_task_input(12-11): request is: 
> [:09.091881 2015] [http2:debug] [pid 1956:tid 572] h2_h2.c(215): [client ::1:15125] adding
h1_to_h2_resp output filter
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(58): [client ::1:15125]
h2_stream(12-13): created
> [:09.091881 2015] [ssl:debug] [pid 1956:tid 572] ssl_engine_kernel.c(238): [client ::1:15125]
AH02034: Subsequent (No.2) HTTPS request received for child 119652660 (server localhost:443)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(71): [client ::1:15125]
h2_session: stream(12-13): opened
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_workers.c(303): h2_workers: register
mplx(12)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(167): [client ::1:15125]
h2_mplx(12-13): start stream, task REPORT /svn-test-work/local_tmp/repos/!svn/rev/1 (localhost:7829)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_workers.c(166): h2_worker(4): start
task(12-13)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(180): [client ::1:15125]
h2_stream(12-13): closing input
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(84): [client ::1:15125]
h2_task_input(12-13): request is: 
> [:09.091881 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(420): [client ::1:15125]
h2_stream(12-13): input closed
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_h2.c(215): [client ::1:15125] adding
h1_to_h2_resp output filter
> [:09.091881 2015] [ssl:debug] [pid 1956:tid 340] ssl_engine_kernel.c(238): [client ::1:15125]
AH02034: Subsequent (No.2) HTTPS request received for child 56701100 (server localhost:443)
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=0, mode=1, readbytes=0
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=0, mode=0, readbytes=153
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=0, mode=1, readbytes=0
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=0, mode=1, readbytes=0
> [:09.091881 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=0, mode=1, readbytes=0
> [:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=0, mode=1, readbytes=0
> [:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=0, mode=0, readbytes=95
> [:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=0, mode=1, readbytes=0
> [:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=0, mode=1, readbytes=0
> [:09.092880 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=0, mode=1, readbytes=0
> [:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_mplx.c(564): [client ::1:15125]
h2_mplx(12-13): open response: 200
> ::1 - jrandom [25/Nov/2015:02:55:09 +0100] "REPORT /svn-test-work/local_tmp/repos/!svn/rev/1
HTTP/1.1" 200 2718
> [:09.097882 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(1126): [client ::1:15125]
h2_stream(12-13): submitted response 200, rv=0
> [:09.097882 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(234): [client ::1:15125]
h2_stream(12-13): handled, closing
> [:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-13): read, block=1, mode=3, readbytes=1
> [:09.097882 2015] [http2:debug] [pid 1956:tid 340] h2_stream.c(75): [client ::1:15125]
h2_stream(12-13): destroy
> [:09.105878 2015] [http2:debug] [pid 1956:tid 572] h2_mplx.c(564): [client ::1:15125]
h2_mplx(12-11): open response: 207
> ::1 - jrandom [25/Nov/2015:02:55:09 +0100] "PROPFIND /svn-test-work/local_tmp/repos/!svn/rev/1
HTTP/1.1" 207 1267
> [:09.105878 2015] [http2:debug] [pid 1956:tid 572] h2_task_input.c(107): [client ::1:15125]
h2_task_input(12-11): read, block=1, mode=3, readbytes=1
> [:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(1126): [client ::1:15125]
h2_stream(12-11): submitted response 207, rv=0
> [:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(234): [client ::1:15125]
h2_stream(12-11): handled, closing
> [:09.105878 2015] [http2:debug] [pid 1956:tid 908] h2_stream.c(75): [client ::1:15125]
h2_stream(12-11): destroy
> 
> 
> [:11.307516 2015] [ssl:info] [pid 1956:tid 908] (OS 10054)An existing connection was
forcibly closed by the remote host.  : [client ::1:15125] AH01991: SSL input filter read failed.
> [:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_conn_io.c(170): (OS 10054)An existing
connection was forcibly closed by the remote host.  : [client ::1:15125] h2_conn_io: error
reading
> [:11.307516 2015] [ssl:info] [pid 1956:tid 904] (OS 10054)An existing connection was
forcibly closed by the remote host.  : [client ::1:15126] AH01991: SSL input filter read failed.
> [:11.307516 2015] [http2:info] [pid 1956:tid 908] (OS 10054)An existing connection was
forcibly closed by the remote host.  : [client ::1:15125] AH02950: h2_session(12): error reading,
terminating
> [:11.307516 2015] [http2:debug] [pid 1956:tid 904] h2_conn_io.c(170): (OS 10054)An existing
connection was forcibly closed by the remote host.  : [client ::1:15126] h2_conn_io: error
reading
> [:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_session.c(693): [client ::1:15125]
session(12): aborting session, reason=-505 Protocol error
> [:11.307516 2015] [http2:info] [pid 1956:tid 904] (OS 10054)An existing connection was
forcibly closed by the remote host.  : [client ::1:15126] AH02950: h2_session(14): error reading,
terminating
> [:11.308516 2015] [http2:debug] [pid 1956:tid 904] h2_session.c(693): [client ::1:15126]
session(14): aborting session, reason=-505 Protocol error
> [:11.307516 2015] [http2:debug] [pid 1956:tid 908] h2_conn.c(328): (OS 10054)An existing
connection was forcibly closed by the remote host.  : [client ::1:15125] h2_session(12): done
> [:11.308516 2015] [http2:debug] [pid 1956:tid 904] h2_conn.c(328): (OS 10054)An existing
connection was forcibly closed by the remote host.  : [client ::1:15126] h2_session(14): done
> [:11.308516 2015] [ssl:debug] [pid 1956:tid 904] ssl_engine_io.c(1003): [client ::1:15126]
AH02001: Connection closed to child 14 with standard shutdown (server localhost:443)
> [:11.308516 2015] [ssl:debug] [pid 1956:tid 908] ssl_engine_io.c(1003): [client ::1:15125]
AH02001: Connection closed to child 12 with standard shutdown (server localhost:443)
> [:11.359567 2015] [mpm_winnt:crit] [pid 1956:tid 364] AH02538: Child: Parent process
exited abruptly. Child process is ending
> [:11.359567 2015] [mpm_winnt:warn] [pid 1956:tid 936] (OS 995)The I/O operation has been
aborted because of either a thread exit or an application request.  : AH00341: winnt_accept:
Asynchronous AcceptEx failed.
> [:11.359567 2015] [mpm_winnt:warn] [pid 1956:tid 920] (OS 995)The I/O operation has been
aborted because of either a thread exit or an application request.  : AH00341: winnt_accept:
Asynchronous AcceptEx failed.
> [:11.359567 2015] [mpm_winnt:debug] [pid 1956:tid 936] child.c(735): AH00348: Child:
Accept thread exiting.
> [:11.359567 2015] [mpm_winnt:debug] [pid 1956:tid 920] child.c(735): AH00348: Child:
Accept thread exiting.
> [:12.360520 2015] [mpm_winnt:debug] [pid 1956:tid 364] child.c(1215): AH00359: Child:
Released the start mutex
> [:12.360520 2015] [mpm_winnt:debug] [pid 1956:tid 364] child.c(1227): AH00361: Child:
16 threads blocked on the completion port


Mime
View raw message