simpleadmin 19 июл 2021 в 10:49

Nginx. Трассировка. Взгляд землекопа

10 мин

4.4K

Настройка Linux*Системное администрирование*Nginx**nix*

Nginx состоит из модулей и именно они выполняют всю реальную работу. Стандартные модули позволяют решить большинство задач, но наступает момент, когда необходимо осуществить какие-то нетипичные действия и тогда мы либо берем сторонний модуль, либо пишем свой собственный.

При этом, даже если модуль давно написан и имеет хорошие отзывы, нет никакой гарантии, что его работа не вызовет проблем, причем, возможно, исключительно в нашей конфигурации или сборке. А Nginx, как известно, рождён для производительности, и, добавляя модули, мы не хотим этой производительности потерять. Поэтому каждая новая сборка должна завершаться отладкой и профилированием.

В недавней статье мы сняли верхний слой грунта, но чтобы локализовать возможную проблему нам придётся копать намного глубже. В самом Nginx есть режим отладки, и он действительно помогает выявлять проблемы, но в качестве профилировщика не годится, так как сам вносит приличную задержку. Поэтому нам потребуется сторонний инструмент и тут, как нельзя лучше, подойдёт dtrace.

Вообще, настоящие экскаваторщики готовят dtrace вот так. Но этот подход, из-за тьмы перекрестных зависимостей, требует либо включения множества файлов заголовков, либо ручного определения структур и типов. Мы, простые чернорабочие, поступаем проще.

Для начала попросим Nginx работать с одним рабочим процессом

worker_processes 1;

и создадим простейшую конфигурацию:

server {
  root /www/example_com;
  index index.html;
  listen       *:80;
  server_name  .example.com;
  location / {
  }
}

Посмотрим какой путь проходит наш запрос, создав сценарий на языке D (который не стоит путать с языком D). Для этого воспользуемся опцией flowindent, чтобы построить дерево вызовов.

#!/usr/sbin/dtrace -s
#pragma D option flowindent

pid$1::ngx_http_init_connection:entry
{
  self->traceme = 1;
}

pid$1:nginx:ngx_http*:entry
{
}

pid$1:nginx:ngx_http*:return
{
}

pid$1::ngx_http_finalize_request:return
{
  trace(arg1);
  self->traceme = 0;
  exit(0);
}

Исполнив сценарий, мы получим симпатичное дерево иллюстрирующее путь нашего запроса.

Аккуратно, 169 строк

CPU FUNCTION
  3  -> ngx_http_init_connection
  3  <- ngx_http_init_connection
  3  -> ngx_http_wait_request_handler
  3    -> ngx_http_alloc_request
  3    <- ngx_http_alloc_request
  3  <- ngx_http_wait_request_handler
  3  -> ngx_http_process_request_line
  3    -> ngx_http_read_request_header
  3    <- ngx_http_read_request_header
  3    -> ngx_http_parse_request_line
  3    <- ngx_http_parse_request_line
  3    -> ngx_http_process_request_uri
  3    <- ngx_http_process_request_uri
  3    -> ngx_http_process_request_headers
  3      -> ngx_http_read_request_header
  3      <- ngx_http_read_request_header
  3      -> ngx_http_parse_header_line
  3      <- ngx_http_parse_header_line
  3      -> ngx_http_process_header_line
  3      <- ngx_http_process_header_line
  3      -> ngx_http_parse_header_line
  3      <- ngx_http_parse_header_line
  3      -> ngx_http_process_connection
  3      <- ngx_http_process_connection
  3      -> ngx_http_parse_header_line
  3      <- ngx_http_parse_header_line
  3      -> ngx_http_process_host
  3        -> ngx_http_validate_host
  3        <- ngx_http_validate_host
  3        -> ngx_http_set_virtual_server
  3          -> ngx_http_find_virtual_server
  3          <- ngx_http_find_virtual_server
  3        <- ngx_http_set_virtual_server
  3      <- ngx_http_process_host
  3      -> ngx_http_parse_header_line
  3      <- ngx_http_parse_header_line
  3      -> ngx_http_process_user_agent
  3      <- ngx_http_process_user_agent
  3      -> ngx_http_parse_header_line
  3      <- ngx_http_parse_header_line
  3      -> ngx_http_process_request_header
  3      <- ngx_http_process_request_header
  3      -> ngx_http_process_request
  3        -> ngx_http_handler
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_realip_handler
  3            <- ngx_http_realip_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_rewrite_phase
  3            -> ngx_http_rewrite_handler
  3            <- ngx_http_rewrite_handler
  3          <- ngx_http_core_rewrite_phase
  3          -> ngx_http_core_find_config_phase
  3            -> ngx_http_core_find_location
  3              -> ngx_http_core_find_location
  3              <- ngx_http_core_find_location
  3            <- ngx_http_core_find_location
  3            -> ngx_http_update_location_config
  3            <- ngx_http_update_location_config
  3          <- ngx_http_core_find_config_phase
  3          -> ngx_http_core_rewrite_phase
  3            -> ngx_http_rewrite_handler
  3            <- ngx_http_rewrite_handler
  3          <- ngx_http_core_rewrite_phase
  3          -> ngx_http_core_post_rewrite_phase
  3          <- ngx_http_core_post_rewrite_phase
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_realip_handler
  3            <- ngx_http_realip_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_limit_req_handler
  3            <- ngx_http_limit_req_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_limit_conn_handler
  3            <- ngx_http_limit_conn_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_access_phase
  3            -> ngx_http_access_handler
  3            <- ngx_http_access_handler
  3          <- ngx_http_core_access_phase
  3          -> ngx_http_core_access_phase
  3            -> ngx_http_auth_basic_handler
  3            <- ngx_http_auth_basic_handler
  3          <- ngx_http_core_access_phase
  3          -> ngx_http_core_access_phase
  3            -> ngx_http_auth_request_handler
  3            <- ngx_http_auth_request_handler
  3          <- ngx_http_core_access_phase
  3          -> ngx_http_core_post_access_phase
  3          <- ngx_http_core_post_access_phase
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_try_files_handler
  3            <- ngx_http_try_files_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_generic_phase
  3            -> ngx_http_mirror_handler
  3            <- ngx_http_mirror_handler
  3          <- ngx_http_core_generic_phase
  3          -> ngx_http_core_content_phase
  3            -> ngx_http_index_handler
  3            <- ngx_http_index_handler
  3          <- ngx_http_core_content_phase
  3          -> ngx_http_core_content_phase
  3            -> ngx_http_autoindex_handler
  3            <- ngx_http_autoindex_handler
  3          <- ngx_http_core_content_phase
  3          -> ngx_http_core_content_phase
  3            -> ngx_http_gzip_static_handler
  3            <- ngx_http_gzip_static_handler
  3          <- ngx_http_core_content_phase
  3          -> ngx_http_core_content_phase
  3            -> ngx_http_static_handler
  3              -> ngx_http_map_uri_to_path
  3              <- ngx_http_map_uri_to_path
  3              -> ngx_http_set_disable_symlinks
  3              <- ngx_http_set_disable_symlinks
  3              -> ngx_http_discard_request_body
  3              <- ngx_http_discard_request_body
  3              -> ngx_http_set_etag
  3              <- ngx_http_set_etag
  3              -> ngx_http_set_content_type
  3              <- ngx_http_set_content_type
  3              -> ngx_http_send_header
  3                -> ngx_http_not_modified_header_filter
  3                  -> ngx_http_headers_filter
  3                    -> ngx_http_userid_filter
  3                      -> ngx_http_sub_header_filter
  3                        -> ngx_http_charset_header_filter
  3                          -> ngx_http_ssi_header_filter
  3                            -> ngx_http_gzip_header_filter
  3                              -> ngx_http_range_header_filter
  3                                -> ngx_http_chunked_header_filter
  3                                  -> ngx_http_header_filter
  3                                    -> ngx_http_time
  3                                    <- ngx_http_time
  3                                    -> ngx_http_write_filter
  3                                    <- ngx_http_write_filter
  3                                  <- ngx_http_header_filter
  3                                <- ngx_http_charset_header_filter
  3                              <- ngx_http_headers_filter
  3                              -> ngx_http_output_filter
  3                                -> ngx_http_range_body_filter
  3                                  -> ngx_http_copy_filter
  3                                    -> ngx_http_trailers_filter
  3                                      -> ngx_http_sub_body_filter
  3                                        -> ngx_http_charset_body_filter
  3                                          -> ngx_http_ssi_body_filter
  3                                            -> ngx_http_postpone_filter
  3                                              -> ngx_http_gzip_body_filter
  3                                                -> ngx_http_chunked_body_filter
  3                                                  -> ngx_http_write_filter
  3                                                    -> ngx_http_complex_value_size
  3                                                    <- ngx_http_complex_value_size
  3                                                  <- ngx_http_write_filter
  3                                                <- ngx_http_chunked_body_filter
  3                                              <- ngx_http_gzip_body_filter
  3                                            <- ngx_http_ssi_body_filter
  3                                          <- ngx_http_charset_body_filter
  3                                        <- ngx_http_trailers_filter
  3                                      <- ngx_http_copy_filter
  3                                    <- ngx_http_output_filter
  3                                  <- ngx_http_static_handler
  3                                  -> ngx_http_finalize_request
  3                                   | ngx_http_finalize_request:return
  3                                  <- ngx_http_finalize_request       34399759824

Так как данная конфигурация не подразумевает никаких перенаправлений, мы рассчитываем, что запрос прошел именно тот простейший путь, который определен фазами Nginx. Убедимся в этом:

$ cat /tmp/tree.txt | grep -F phase | grep "\->" | uniq | awk '{print $3}'
ngx_http_core_generic_phase
ngx_http_core_rewrite_phase
ngx_http_core_find_config_phase
ngx_http_core_rewrite_phase
ngx_http_core_post_rewrite_phase
ngx_http_core_generic_phase
ngx_http_core_access_phase
ngx_http_core_post_access_phase
ngx_http_core_generic_phase
ngx_http_core_content_phase

Фаз обработки запроса 11, а здесь отобразилось 10 этапов. В этом нет никакой ошибки, так как мы закончили трассировку на этапе завершения запроса, а логирование произойдет только после закрытия соединения, то есть ещё исполнятся ngx_http_finalize_connection, ngx_http_free_request и только потом начнется этап записи в лог.

Соотнесем наши результаты со списком фаз:

1	NGX_HTTP_POST_READ_PHASE	ngx_http_core_generic_phase
2	NGX_HTTP_SERVER_REWRITE_PHASE	ngx_http_core_rewrite_phase
3	NGX_HTTP_FIND_CONFIG_PHASE	ngx_http_core_find_config_phase
4	NGX_HTTP_REWRITE_PHASE	ngx_http_core_rewrite_phase
5	NGX_HTTP_POST_REWRITE_PHASE	ngx_http_core_post_rewrite_phase
6	NGX_HTTP_PREACCESS_PHASE	ngx_http_core_generic_phase
7	NGX_HTTP_ACCESS_PHASE	ngx_http_core_access_phase
8	NGX_HTTP_POST_ACCESS_PHASE	ngx_http_core_post_access_phase
9	NGX_HTTP_PRECONTENT_PHASE	ngx_http_core_generic_phase
10	NGX_HTTP_CONTENT_PHASE	ngx_http_core_content_phase
11	NGX_HTTP_LOG_PHASE	ngx_http_core_generic_phase

Так как обычно модуль работает в какой-то одной фазе, то её пробу нам и нужно делать. Для примера возьмем NGX_HTTP_POST_ACCESS_PHASE и посмотрим сколько времени занимает её обработка:

#!/usr/sbin/dtrace -s

pid$1::ngx_http_init_connection:entry
{
    printf("init\n");
    elapsed_post_access = 0;
}

pid$1::ngx_http_core_post_access_phase:entry
{
    begin_post_access = timestamp;
    printf("begin (post_access): %d\n", begin_post_access);
}

pid$1::ngx_http_core_post_access_phase:return
/begin_post_access > 0/
{
    elapsed_post_access += timestamp - begin_post_access;
    begin_post_access = 0;
    printf("elapsed (post_access): %d\n", elapsed_post_access);
}

pid$1::ngx_http_finalize_request:return
/elapsed_post_access > 0/
{
    printf("final (post_access)\n");
    @elapsed_post_access = avg(elapsed_post_access);
    elapsed_post_access = 0;
    exit(0);
}

# dtrace -s ./post_access.d `pgrep -f 'nginx: worker process'`
dtrace: script './post_access.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
  7  71748   ngx_http_init_connection:entry init

  7  71754 ngx_http_core_post_access_phase:entry begin (post_access): 18833138568826655

  7  71755 ngx_http_core_post_access_phase:return elapsed (post_access): 3543

  7  71751 ngx_http_finalize_request:return final (post_access)


             3543

Этот же подход можно применять ещё более точечно, например, копаясь в фильтрах тела запроса. Попробуем сделать практический анализ эффективности двух различных модулей, решающих одну и ту же задачу, для этого в качестве index.html используем страничку rfc2822, и соберем Nginx c поддержкой родного http_sub_module и стороннего ngx_http_substitutions_filter_module.

Соответственно, для теста мы имеем две конфигурации:

  location / {
    sub_filter 'span'  'div';
    sub_filter_once off;    
  }

  location / {
    subs_filter 'span'  'div';
  }

И два сценария dtrace:

sub

#!/usr/sbin/dtrace -s

pid$1::ngx_http_init_connection:entry
{
    printf("init\n");
    elapsed_sub_filter = 0;
}

pid$1::ngx_http_sub_body_filter:entry
{
    begin_sub_filter = timestamp;
    printf("begin (sub_filter): %d\n", begin_sub_filter);
}

pid$1::ngx_http_sub_body_filter:return
/begin_sub_filter > 0/
{
    elapsed_sub_filter += timestamp - begin_sub_filter;
    begin_sub_filter = 0;
    printf("elapsed (sub_filter): %d\n", elapsed_sub_filter);
}

pid$1::ngx_http_finalize_request:return
/elapsed_sub_filter > 0/
{
    exit(0);
}

subs

#!/usr/sbin/dtrace -s

pid$1::ngx_http_init_connection:entry
{
    printf("init\n");
    elapsed_subs_filter = 0;
}

pid$1::ngx_http_subs_body_filter:entry
{
    begin_subs_filter = timestamp;
    printf("begin (subs_filter): %d\n", begin_subs_filter);
}

pid$1::ngx_http_subs_body_filter:return
/begin_subs_filter > 0/
{
    elapsed_subs_filter += timestamp - begin_subs_filter;
    begin_subs_filter = 0;
    printf("elapsed (subs_filter): %d\n", elapsed_subs_filter);
}

pid$1::ngx_http_finalize_request:return
/elapsed_subs_filter > 0/
{
   exit(0);
}

# dtrace -s ./sub_filter.d `pgrep -f 'nginx: worker process'`
dtrace: script './sub_filter.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
  2  71748   ngx_http_init_connection:entry init

  2  71752   ngx_http_sub_body_filter:entry begin (sub_filter): 19078115202094268

  2  71753  ngx_http_sub_body_filter:return elapsed (sub_filter): 58548

  2  71752   ngx_http_sub_body_filter:entry begin (sub_filter): 19078115202360871

  2  71753  ngx_http_sub_body_filter:return elapsed (sub_filter): 118098

  2  71752   ngx_http_sub_body_filter:entry begin (sub_filter): 19078115202697212

  2  71753  ngx_http_sub_body_filter:return elapsed (sub_filter): 169395

  2  71752   ngx_http_sub_body_filter:entry begin (sub_filter): 19078115202919509

  2  71753  ngx_http_sub_body_filter:return elapsed (sub_filter): 225577

  2  71752   ngx_http_sub_body_filter:entry begin (sub_filter): 19078115203186481

  2  71753  ngx_http_sub_body_filter:return elapsed (sub_filter): 256872

  2  71751 ngx_http_finalize_request:return

# dtrace -s ./subs_filter.d `pgrep -f 'nginx: worker process'`
dtrace: script './subs_filter.d' matched 4 probes
CPU     ID                    FUNCTION:NAME
  2  71748   ngx_http_init_connection:entry init

  2  71749  ngx_http_subs_body_filter:entry begin (subs_filter): 19078177580261158

  2  71750 ngx_http_subs_body_filter:return elapsed (subs_filter): 195538

  2  71749  ngx_http_subs_body_filter:entry begin (subs_filter): 19078177580467254

  2  71750 ngx_http_subs_body_filter:return elapsed (subs_filter): 336789

  2  71749  ngx_http_subs_body_filter:entry begin (subs_filter): 19078177580616159

  2  71750 ngx_http_subs_body_filter:return elapsed (subs_filter): 484982

  2  71749  ngx_http_subs_body_filter:entry begin (subs_filter): 19078177580772832

  2  71750 ngx_http_subs_body_filter:return elapsed (subs_filter): 623289

  2  71749  ngx_http_subs_body_filter:entry begin (subs_filter): 19078177580916291

  2  71750 ngx_http_subs_body_filter:return elapsed (subs_filter): 700474

  2  71751 ngx_http_finalize_request:return final

Не будем доверять штучному тесту и выполним миллион запросов, собрав значения в агрегирующую функцию:

sub_filter_avg.d

#!/usr/sbin/dtrace -s

pid$1::ngx_http_init_connection:entry
{
    elapsed_sub_filter = 0;
}

pid$1::ngx_http_sub_body_filter:entry
{
    begin_sub_filter = timestamp;
}

pid$1::ngx_http_sub_body_filter:return
/begin_sub_filter > 0/
{
    elapsed_sub_filter += timestamp - begin_sub_filter;
    begin_sub_filter = 0;
}

pid$1::ngx_http_finalize_request:return
/elapsed_sub_filter > 0/
{
    @elapsed_sub_filter = avg(elapsed_sub_filter);
}

$ ab -k -c1 -n1000000 'example.com/index.html'

# dtrace -s ./sub_filter_avg.d `pgrep -f 'nginx: worker process'`
dtrace: script './sub_filter_avg.d' matched 4 probes
^C

           245971

# dtrace -s ./subs_filter_avg.d `pgrep -f 'nginx: worker process'`
dtrace: script './subs_filter_avg.d' matched 4 probes
^C

           651586

С одной стороны, преимущество в 2.6 раза, с другой - разница в 400 микросекунд не так уж и критична. Но по крайней мере без использования regex, использование стороннего модуля не даёт преимуществ.

Бытует мнение, что с веток 1.9+ sub_filter существенно ускорился. Ради интереса я откатился до более ранних версий

1.8.1:

# dtrace -s ./sub_filter_avg.d `pgrep -f 'nginx: worker process'`
dtrace: script './sub_filter_avg.d' matched 4 probes
^C

           244136

1.6.3:

# dtrace -s ./sub_filter_avg.d `pgrep -f 'nginx: worker process'`
dtrace: script './sub_filter_avg.d' matched 4 probes
^C

           240079

но на этих простых задачах ускорения не заметил.

Подводя итоги. На самом деле, хотя OpenResty и не упоминается в статье, всё вышесказанное было написано с целью ответа на комментарий к предыдущей публикации. Я не ответил на него прямо, так как это потребовало бы подтверждений, которых у меня сейчас нет, но не ответить совсем не мог, поэтому хотя бы показал тот путь, который привел меня к отказу, если не от OpenResty вообще, то, по крайней мере, к использованию его с крайней осторожностью и после тщательного тестирования, как, впрочем, и любой другой сборки или модуля.

Теги:

Хабы:

Nginx. Трассировка. Взгляд землекопа

Публикации

Истории

Работа

Ближайшие события