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

2024-01-11 Пенетрантность Илья Шипицин
чт, 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

2024-01-11 Пенетрантность izorkin
Добрый вечер, Илья.

Судя по логам все попытки успешны.
Там все сообщения идентичны:
[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

2024-01-11 Пенетрантность izorkin
Добрый вечер, Илья.

Да, только 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

2024-01-11 Пенетрантность izorkin
Добрый вечер, Илья.

В логах не обнаружил сообщений 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

2024-01-11 Пенетрантность Илья Шипицин
чт, 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

2024-01-11 Пенетрантность izorkin
Добрый день, Илья.

Может требуется ещё и поддержка 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

2024-01-11 Пенетрантность Илья Шипицин
из интересного, в 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