Re: nginxQuic: скорость загрузки при активации kTLS
чт, 11 янв. 2024 г. в 20:25, : > Добрый вечер, Илья. > > > В логах не обнаружил сообщений sendmsg() и sendmmsg(). > т.е. все попытки успешны ? а вот эта часть есть в логах ? +ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, + "sendmmsg: %z of %ui msg of size %uz", n, nmsg, len); > > > Вы писали 11 января 2024 г., 22:11:56: > > > > я имею в виду вот этот код > > +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(>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, > чтобы удобнее было искать > > в том, что вы прислали, я не вижу такого патерна > > > -- > С уважением, > Izorkin mailto:izor...@gmail.com > > ___ > nginx-ru mailing list > nginx-ru@nginx.org > https://mailman.nginx.org/mailman/listinfo/nginx-ru > ___ nginx-ru mailing list nginx-ru@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: nginxQuic: скорость загрузки при активации kTLS
Добрый вечер, Илья. Судя по логам все попытки успешны. Там все сообщения идентичны: [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size 69087 ... [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size 70287 ... [debug] 33853#33853: *1 sendmmsg: 2 of 2 msg of size 84687 ... Почти все сообщения sendmmsg: Вы писали 11 января 2024 г., 23:04:40: > т.е. все попытки успешны ? > а вот эта часть есть в логах ? > + ngx_log_debug3(NGX_LOG_DEBUG_EVENT, c->log, 0, > + "sendmmsg: %z of %ui msg of size %uz", n, nmsg, len); -- С уважением, Izorkin mailto:izor...@gmail.com___ nginx-ru mailing list nginx-ru@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: nginxQuic: скорость загрузки при активации kTLS
Добрый вечер, Илья. Да, только 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. Что там искать, на что обратить внимание? 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 0001a00183bd407243b7f2011ca86733 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 6741DE771C80 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:6 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
Re: nginxQuic: скорость загрузки при активации kTLS
Добрый вечер, Илья. В логах не обнаружил сообщений sendmsg() и sendmmsg(). Вы писали 11 января 2024 г., 22:11:56: > я имею в виду вот этот код > + 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(>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, чтобы > удобнее было искать > в том, что вы прислали, я не вижу такого патерна -- С уважением, Izorkin mailto:izor...@gmail.com___ nginx-ru mailing list nginx-ru@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: nginxQuic: скорость загрузки при активации kTLS
чт, 11 янв. 2024 г. в 20:00, : > Добрый вечер, Илья. > > > Да, только 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(>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 > 0001a00183bd407243b7f2011ca86733 > > 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 6741DE771C80 > > 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
Re: nginxQuic: скорость загрузки при активации kTLS
Добрый день, Илья. Может требуется ещё и поддержка recvmmsg()? Может поэтому не работает sendmmsg()? -- С уважением, Izorkin mailto:izor...@gmail.com___ nginx-ru mailing list nginx-ru@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-ru
Re: nginxQuic: скорость загрузки при активации kTLS
из интересного, в openssl master есть вот такое https://github.com/openssl/openssl/blob/master/doc/designs/quic-design/dgram-api.md пн, 8 янв. 2024 г. в 14:18, : > Добрый день, Роман. > > В среднем чуть-чуть лучше результат, скорость иногда выше на > 5-10 МБайт/сек. Иногда на одном уровне держится. > > По профилю видно, что sendmmsg()практически не используется: > 626 31.3% 31.3% 626 31.3% __sendmsg > 546 27.3% 58.7% 546 27.3% _aesni_ctr32_ghash_6x > 279 14.0% 72.7% 279 14.0% __libc_pread64 > 174 8.7% 81.4% 174 8.7% __memmove_avx_unaligned_erms > 64 3.2% 84.6% 64 3.2% epoll_wait > 42 2.1% 86.7% 42 2.1% __recvmsg > 11 0.6% 87.2% 115 5.8% ngx_quic_write_buffer > 10 0.5% 87.7% 116 5.8% ngx_quic_recvmsg >9 0.5% 88.2%9 0.5% __sendmmsg > 9 раз вызвался ? есть подозрение, что произошла ошибка и перешли на sendmsg. попробуйте в дебаге, в прилагаемом патче есть ngx_log_debug0(...) >9 0.5% 88.6%9 0.5% ngx_quic_alloc_buf >9 0.5% 89.1% 92 4.6% ngx_quic_create_frame >8 0.4% 89.5%8 0.4% aesni_ctr32_encrypt_blocks >8 0.4% 89.9%8 0.4% ngx_quic_free_chain >7 0.4% 90.2%7 0.4% __strcmp_avx2 >7 0.4% 90.6% 1360 68.1% ngx_quic_output >7 0.4% 90.9%7 0.4% ngx_quic_parse_frame >6 0.3% 91.2%6 0.3% aesni_encrypt >6 0.3% 91.5%6 0.3% evp_cipher_init_internal >6 0.3% 91.8% 431 21.6% ngx_output_chain >5 0.3% 92.1% 581 29.1% gcm_cipher_internal >5 0.3% 92.3%5 0.3% gcm_ghash_avx >5 0.3% 92.6% 573 28.7% generic_aes_gcm_cipher_update >5 0.3% 92.8%5 0.3% ngx_alloc_chain_link >5 0.3% 93.1% 141 7.1% ngx_http_image_body_filter >4 0.2% 93.3% 17 0.9% EVP_CIPHER_CTX_ctrl >4 0.2% 93.5%9 0.5% EVP_EncryptFinal_ex >4 0.2% 93.7%4 0.2% _init > > > Вы писали 8 января 2024 г., 15:18:45: > > > У вас quic_gso включен? Если нет, попробуйте включить: > > > quic_gso on; > > > Также попробуйте приаттаченный патч, добавляющий поддержку sendmmsg() > > (quic_gso при этом оставьте включенным). nginx будет надо > переконфигурить > > перед сборкой. > > > Интересно посмотреть, как изменятся цифры. > > > -- > > Roman Arutyunyan > > > > -- > С уважением, > Izorkin mailto:izor...@gmail.com > ___ > nginx-ru mailing list > nginx-ru@nginx.org > https://mailman.nginx.org/mailman/listinfo/nginx-ru > ___ nginx-ru mailing list nginx-ru@nginx.org https://mailman.nginx.org/mailman/listinfo/nginx-ru