On Mon, Dec 06, 2021 at 03:37:28PM +0300, Sergey Kandaurov wrote:
>
> > On 25 Nov 2021, at 17:20, Roman Arutyunyan <arut@nginx.com> wrote:
> >
> > # HG changeset patch
> > # User Roman Arutyunyan <arut@nginx.com>
> > # Date 1637692791 -10800
> > # Tue Nov 23 21:39:51 2021 +0300
> > # Branch quic
> > # Node ID 5b03ffd757804542daec73188a509b02e6b2c596
> > # Parent d041b8d6ab0b2dea150536531345fa47c696b303
> > QUIC: post stream events instead of calling their handlers.
> >
> > This potentially reduces the number of handler calls.
> >
> > diff --git a/src/event/quic/ngx_event_quic_streams.c b/src/event/quic/ngx_event_quic_streams.c
> > --- a/src/event/quic/ngx_event_quic_streams.c
> > +++ b/src/event/quic/ngx_event_quic_streams.c
> > @@ -1122,7 +1122,7 @@ ngx_quic_handle_stream_frame(ngx_connect
> > rev->ready = 1;
> >
> > if (rev->active) {
> > - rev->handler(rev);
> > + ngx_post_event(rev, &ngx_posted_events);
> > }
> > }
> >
> > @@ -1369,7 +1369,7 @@ ngx_quic_handle_reset_stream_frame(ngx_c
> > }
> >
> > if (rev->active) {
> > - rev->handler(rev);
> > + ngx_post_event(rev, &ngx_posted_events);
> > }
> >
> > return NGX_OK;
> > @@ -1438,7 +1438,7 @@ ngx_quic_handle_stop_sending_frame(ngx_c
> > wev = qs->connection->write;
> >
> > if (wev->active) {
> > - wev->handler(wev);
> > + ngx_post_event(wev, &ngx_posted_events);
> > }
> >
> > return NGX_OK;
>
> I don't like this change.
>
> While in practice this indeed tends to reduce the number of handler
> invocations in certain edge cases, it also entails negative effects.
> First, postponing processing the next part of a stream means that
> if the stream spans multiple packets, its handling will be deferred
> inadvertently until after the next packet is finished processing.
> Next, if a stream is the encoder stream, used to send new dynamic
> entries, then new request streams will be inevitably blocked.
> I've run intentionally on this to see what happens:
> looks like the blocked stream isn't woken up until connection close
> (which consumes active streams in ngx_quic_close_streams()).

Indeed, the change adds some reordering. Stream listen handler is always
called right after stream creation, but read handler is now postponed.
The change alters the order of these calls when multiple streams are involved.
This is not a problem per se since reordering can happen naturally as well.
Also, the next patch in series introduces listen handler call postpone, which
brings back the old ordering.

The problem discovered is triggered by another (not yet committed) change
which apparently breaks stream unblock. That change obviously needs some
improvement.

> 0x6 is the encoder stream, 0x40 is the request stream.
>
> 2021/12/06 14:45:36 [debug] 17379#0: *1 quic frame rx app STREAM id:0x6 off:1 len:428
> 2021/12/06 14:45:36 [debug] 17379#0: *4 post event 000062F000000740
> 2021/12/06 14:45:36 [debug] 17379#0: *1 quic frame rx app STREAM id:0x40 len:38 fin:1
> ...
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 check insert count req:23, have:0
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 block stream
> ...
> 2021/12/06 14:45:36 [debug] 17379#0: posted event 000062F000000740
> 2021/12/06 14:45:36 [debug] 17379#0: *4 delete posted event 000062F000000740
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 read handler
> 2021/12/06 14:45:36 [debug] 17379#0: *4 quic stream id:0x6 recv eof:0 buf:128
> 2021/12/06 14:45:36 [debug] 17379#0: *4 quic stream id:0x6 recv len:128
> 2021/12/06 14:45:36 [debug] 17379#0: *4 quic flow update 129
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse encoder instruction
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse prefix int 16384
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 set capacity 16384
> 2021/12/06 14:45:36 [debug] 17379#0: *1 malloc: 000062100005DD00:4096
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse encoder instruction
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse field inr
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse prefix int 0
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse prefix int 6
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse literal huff:1, len:6
> 2021/12/06 14:45:36 [debug] 17379#0: *4 malloc: 00006020000A5630:10
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse literal done "localhost"
> 2021/12/06 14:45:36 [debug] 17379#0: *4 http3 parse field inr done static[0] "localhost"
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 ref insert static[0] "localhost"
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 static[0] lookup ":authority":""
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 insert [0] ":authority":"localhost", size:51
> 2021/12/06 14:45:36 [debug] 17379#0: *1 malloc: 0000606000008D80:51
> 2021/12/06 14:45:36 [debug] 17379#0: *1 post event 0000614000005A78
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 new dynamic entry, blocked:1
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 unblock stream
> 2021/12/06 14:45:36 [debug] 17379#0: *1 post event 000062F000000608
> ...
> 2021/12/06 14:45:36 [debug] 17379#0: posted event 0000614000005A78
> 2021/12/06 14:45:36 [debug] 17379#0: *1 delete posted event 0000614000005A78
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 inc insert count handler
> 2021/12/06 14:45:36 [debug] 17379#0: *1 http3 send insert count increment 23
> ...
> 2021/12/06 14:45:36 [debug] 17379#0: posted event 000062F000000608
> 2021/12/06 14:45:36 [debug] 17379#0: *1 delete posted event 000062F000000608
> 2021/12/06 14:45:36 [debug] 17379#0: *1 quic input handler
> [nothing]
> 2021/12/06 14:45:36 [debug] 17379#0: posted event 000061D00003C648
> ...
> ...
> 2021/12/06 14:45:37 [debug] 17379#0: *1 quic frame rx app CONNECTION_CLOSE err:0 ft:0
> 2021/12/06 14:45:37 [debug] 17379#0: *1 quic immediate close drain:1
> 2021/12/06 14:45:37 [debug] 17379#0: *22 post event 000062F000000A18
> ...
> 2021/12/06 14:45:37 [debug] 17379#0: posted event 000062F000000A18
> 2021/12/06 14:45:37 [debug] 17379#0: *22 delete posted event 000062F000000A18
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http3 process request
> 2021/12/06 14:45:37 [debug] 17379#0: *1 http3 check insert count req:23, have:23
> ...
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http3 parse field representation done
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http3 parse headers done
> 2021/12/06 14:45:37 [debug] 17379#0: *1 http3 send section acknowledgement 64
> 2021/12/06 14:45:37 [debug] 17379#0: *1 quic creating server uni stream streams:2 max:100 id:0xb
> 2021/12/06 14:45:37 [debug] 17379#0: *1 quic stream id:0xb create
> ...
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http3 header: "user-agent: something something"
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http request count:1 blk:0
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http close request
> 2021/12/06 14:45:37 [debug] 17379#0: *22 http log handler
> 2021/12/06 14:45:37 [debug] 17379#0: *22 malloc: 000060D000007AF0:130
> 2021/12/06 14:45:37 [debug] 17379#0: *22 malloc: 000060F000019EA0:169
> 2021/12/06 14:45:37 [debug] 17379#0: *22 run cleanup: 000060300007D500
> 2021/12/06 14:45:37 [debug] 17379#0: *1 event timer add: 8: 75000:2579974395
> 2021/12/06 14:45:37 [debug] 17379#0: *22 close http connection: 8
> 2021/12/06 14:45:37 [debug] 17379#0: *1 http3 send stream cancellation 64
>
> --
> Sergey Kandaurov
>
> _______________________________________________
> nginx-devel mailing list
> nginx-devel@nginx.org
> http://mailman.nginx.org/mailman/listinfo/nginx-devel

--
Roman Arutyunyan
_______________________________________________
nginx-devel mailing list
nginx-devel@nginx.org
http://mailman.nginx.org/mailman/listinfo/nginx-devel