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 строк
Так как данная конфигурация не подразумевает никаких перенаправлений, мы рассчитываем, что запрос прошел именно тот простейший путь, который определен фазами 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 и только потом начнется этап записи в лог.
Соотнесем наши результаты со списком фаз:
Так как обычно модуль работает в какой-то одной фазе, то её пробу нам и нужно делать. Для примера возьмем 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 вообще, то, по крайней мере, к использованию его с крайней осторожностью и после тщательного тестирования, как, впрочем, и любой другой сборки или модуля.
Источник статьи: https://habr.com/ru/post/567978/
При этом, даже если модуль давно написан и имеет хорошие отзывы, нет никакой гарантии, что его работа не вызовет проблем, причем, возможно, исключительно в нашей конфигурации или сборке. А 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 строк
Так как данная конфигурация не подразумевает никаких перенаправлений, мы рассчитываем, что запрос прошел именно тот простейший путь, который определен фазами 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 |
#!/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 вообще, то, по крайней мере, к использованию его с крайней осторожностью и после тщательного тестирования, как, впрочем, и любой другой сборки или модуля.
Источник статьи: https://habr.com/ru/post/567978/