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 97725 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 2441361.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 вообще, то, по крайней мере, к использованию его с крайней осторожностью и после тщательного тестирования, как, впрочем, и любой другой сборки или модуля.
ссылка на оригинал статьи https://habr.com/ru/post/567978/
Добавить комментарий