[PATCH 1 of 3] QUIC: post stream events instead of calling their handlers

Mon Dec 6 12:37:28 UTC 2021

> On 25 Nov 2021, at 17:20, Roman Arutyunyan <arut at nginx.com> wrote:
> 
> # HG changeset patch
> # User Roman Arutyunyan <arut at 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()).

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