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
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 вообще, то, по крайней мере, к использованию его с крайней осторожностью и после тщательного тестирования, как, впрочем, и любой другой сборки или модуля.
dmitry_rozhkov
Отличная статья. Спасибо за пример с dtrace!