httpd-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From "Bert Huijben" <b...@qqmail.nl>
Subject RE: H2 stream dependencies
Date Wed, 25 Nov 2015 02:10:21 GMT
> -----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