Re: nginxQuic: скорость загрузки при активации kTLS

Илья Шипицин chipitsine на gmail.com
Чт Янв 11 19:11:56 UTC 2024


чт, 11 янв. 2024 г. в 20:00, <izorkin на gmail.com>:

> Добрый вечер, Илья.
>
>
> Да, только 9 раз. Сейчас в тестах вообще только 3 раза был вызов. И в
> debug режиме
>
> чаще используется __libc_write вызов.
>
>
>
>     6965  69.8%  69.8%    6965  69.8% __libc_write
>
>     654  6.6%  76.3%      654  6.6% __sendmsg
>
>     357  3.6%  79.9%      357  3.6% _aesni_ctr32_ghash_6x
>
>     322  3.2%  83.1%      536  5.4% ngx_vslprintf
>
>     300  3.0%  86.1%      300  3.0% syscall
>
>     277  2.8%  88.9%      277  2.8% __libc_pread64
>
>     226  2.3%  91.2%      226  2.3% __memmove_avx_unaligned_erms
>
>     142  1.4%  92.6%      190  1.9% ngx_sprintf_num
>
>       93  0.9%  93.5%    7911  79.2% ngx_log_error_core
>
>       63  0.6%  94.1%      63  0.6% epoll_wait
>
>       55  0.6%  94.7%      55  0.6% __recvmsg
>
>       35  0.4%  95.0%      300  3.0% ngx_slprintf
>
>       19  0.2%  95.2%      19  0.2% __strcmp_avx2
>
>       17  0.2%  95.4%      89  0.9% ngx_quic_create_frame
>
>       16  0.2%  95.6%      16  0.2% _init на 39000
>
> ...
>
>        3   0.0%  98.6%        3   0.0% __sendmmsg
>
> ...
>
>
>
> Размер лог-файла получился очень большим, около 1.5 Gb. В нём около
> нескольких сотен
>
> упоминаний sendmmsg. Что там искать, на что обратить внимание?
>


я имею в виду вот этот код

+        if (n == -1) {
+            err = ngx_errno;
+
+            switch (err) {
+            case NGX_EAGAIN:
+                ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, err,
+                               "sendmmsg() not ready");
+
+                ngx_quic_revert_send(c, ctx, preserved_pnum);
+
+                ngx_add_timer(&qc->push, NGX_QUIC_SOCKET_RETRY_DELAY);
+                return NGX_OK;
+
+            case NGX_EINTR:
+                ngx_log_debug0(NGX_LOG_DEBUG_EVENT, c->log, err,
+                               "sendmmsg() was interrupted");
+                goto eintr;
+
+            default:
+                c->write->error = 1;
+                ngx_connection_error(c, err, "sendmsg() failed");
+                return NGX_ERROR;
+            }
+        }

ну то есть искать либо "sendmmsg()", либо явно поправить ngx_log_debug,
чтобы удобнее было искать

в том, что вы прислали, я не вижу такого патерна


>
>
> cat /tmp/nginx/debug.log| grep 'sendmmsg'
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size
> 69087
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size
> 69087
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size
> 69087
>
> ...
>
> Часть лога с sendmmsg:
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx app STREAM
> id:0x0 off:3145389 len:339
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet tx app bytes:1162
> need_ack:1 number:2784 encoded nl:1 trunc:0xe0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size
> 69087
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:69087
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer: 9, old:
> 863483412, new: 863483521
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic lost timer pto:48
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer add: 9:
> 48:863423569
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic state: send:59891 pto:48
>
> 2024/01/11 21:32:36 [debug] 33853#33853: quic recvmsg on [::]:443, ready: 0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic recvmsg: fd:9 n:51
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic input handler
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet rx short flags:42
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet rx dcid len:20
> 000000000001a00183bd407243b7f2011ca86733
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet rx clearflags:40
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet rx number:52 len:1
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet len:51 via sock
> seq:0 path seq:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic path seq:0 status
> tx:3319325 rx:7668 valid:1 st:2 mtu:1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame rx app ACK n:0
> delay:15 2784-2669
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic ngx_quic_handle_ack_frame
> level:3
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion slow start
> win:3379951 ss:-1 if:67887
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic stream id:0x0 ack
> len:1152 fin:0 unacked:64384
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *6 post event 00006741DE771C80
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion slow start
> win:3381151 ss:-1 if:66687
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic stream id:0x0 ack
> len:1152 fin:0 unacked:63232
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion slow start
> win:3382351 ss:-1 if:65487
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic stream id:0x0 ack
> len:1152 fin:0 unacked:62080
>
>
>
> Ещё часть лога с sendmsg:
>
> 024/01/11 21:32:36 [debug] 33853#33853: *1 quic ngx_quic_add_handshake_data
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> SSL_get_peer_quic_transport_params(): params_len:74
>
> 2024/01/11 21:32:36 [info] 33853#33853: *1 quic unknown transport param
> id:0x11, skipped while handling frames, client: ::1, server: [::]:443
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic transport parameters
> parsed ok
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp disable active
> migration: 0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp idle_timeout:60000
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> max_udp_payload_size:65527
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp max_data:1310720
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> max_stream_data_bidi_local:131072
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> max_stream_data_bidi_remote:131072
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> max_stream_data_uni:131072
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> initial_max_streams_bidi:262144
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> initial_max_streams_uni:262144
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp ack_delay_exponent:3
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp max_ack_delay:25
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp
> active_connection_id_limit:2
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic tp initial
> source_connection_id len:20 de1e73dcd4e6a4fdc6ecfb38ac840a34922b8517
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 posix_memalign:
> 00006741DE627800:512 @16
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 malloc: 00006741DE650000:4096
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 post event 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_set_encryption_secrets() level:2
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_add_handshake_data
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 malloc: 00006741DE651000:4096
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 posix_memalign:
> 00006741DE627A00:512 @16
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 update posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_add_handshake_data
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 malloc: 00006741DE652000:4096
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 update posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_add_handshake_data
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 malloc: 00006741DE653000:4096
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 posix_memalign:
> 00006741DE627C00:512 @16
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 update posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_add_handshake_data
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 malloc: 00006741DE654000:4096
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 update posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic ngx_quic_flush_flight()
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic
> ngx_quic_set_encryption_secrets() level:3
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 SSL_do_handshake: -1
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 SSL_get_error: 2
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame rx init PADDING
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic ngx_quic_ack_packet pn:0
> largest -1 fr:0 nranges:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 update posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet done rc:0
> level:init decr:1 pn:0 perr:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer add: 9:
> 60000:863483412
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer add: 9:
> 60000:863483412
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic state: read:60000
> close:60000
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 delete posted event
> 00006741DE6D5608
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic push handler
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 posix_memalign:
> 00006741DE627E00:512 @16
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic output init packet
> max:1200 min:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx init ACK n:0
> delay:0 0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx init CRYPTO
> len:123 off:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet tx init bytes:132
> need_ack:1 number:0 encoded nl:1 trunc:0x0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic output hs packet max:1001
> min:1001
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO
> len:163 off:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic split frame now:1403
> need:768 shrink:635
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO
> len:763 off:163
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet tx hs bytes:935
> need_ack:1 number:0 encoded nl:1 trunc:0x0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmsg: 1200 of 1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:199
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic output hs packet max:1200
> min:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO
> len:635 off:926
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic split frame now:525
> need:494 shrink:31
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO
> len:489 off:1561
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet tx hs bytes:1134
> need_ack:1 number:1 encoded nl:1 trunc:0x1
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmsg: 1200 of 1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:2400
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:2400
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic output hs packet max:1200
> min:0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO len:31
> off:2050
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic frame tx hs CRYPTO len:36
> off:2081
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic packet tx hs bytes:75
> need_ack:1 number:2 encoded nl:1 trunc:0x2
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 sendmsg: 141 of 141
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:2400
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:2541
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic congestion send if:2541
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic path limit 1200 - 1059
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer: 9, old:
> 863483412, new: 863483412
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic lost timer pto:997
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 event timer add: 9:
> 997:863424409
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic state: send:60000 pto:997
> close:60000
>
> 2024/01/11 21:32:36 [debug] 33853#33853: quic recvmsg on [::]:443, ready: 0
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic recvmsg: fd:9 n:1200
>
> 2024/01/11 21:32:36 [debug] 33853#33853: *1 quic input handler
>
>
>
>
>
> Вы писали 11 января 2024 г., 16:59:54:
>
>
>
> 9 раз вызвался ?
> есть подозрение, что произошла ошибка и перешли на sendmsg.
> попробуйте в дебаге, в прилагаемом патче есть ngx_log_debug0(...)
>
>>
>
> --
> С уважением,
>  Izorkin                          mailto:izorkin на gmail.com
> <izorkin на gmail.com>
> _______________________________________________
> nginx-ru mailing list
> nginx-ru на nginx.org
> https://mailman.nginx.org/mailman/listinfo/nginx-ru
>
----------- следующая часть -----------
Вложение в формате HTML было извлечено…
URL: <http://mailman.nginx.org/pipermail/nginx-ru/attachments/20240111/41a32a94/attachment-0001.htm>


Подробная информация о списке рассылки nginx-ru