На что расходуется время http-запроса?

Question

[Алексей]

Не понимаю, что происходит!
Очень медленно обрабатываются запросы к web-серверу. Исходные данные: Ubuntu server + Nginx + UWSGI + Python
Пример. Браузер посылает запрос, ответ приходит через 723 ms. Смотрю логи nginx:

request_time = 0.728
upstream_response_time = 0.723

Т.е. nginx обработал запрос "мгновенно", и все 723 ms ушли на обработку uwsgi-сервером.
Смотрю код приложения, обрабатывающий запрос. В коде выполнения запроса:
- одна строка, дающая SQL-запрос
- несколько строк его обработки перед отдачей
SQL выполняется за 66 ms
Обработка результата - 0.1 ms
Т.е. код отработал за 66 ms.
Смотрю лог uwsgi. Там сказано: generated 53 bytes in 722 msecs
Это что получается, что 722 - 66 = накладные расходы uwsgi? Капец! Как узнать, где именно, и как с этим бороться?

Comments

[Алексей]

1. как мерили?

В логах указано время, поставил в коде дополнительно вывод в лог в критичных местах.

насколько в этот момент нагружен сервер?

50 -350 http-запросов в сек. Загрузка процессора ~0.25

это один запрос? а если подряд несколько делать, меняться время? а в логах еще что-то есть?

Пробовал подряд несколько, такой же результат. В логах больше ничего, что могло бы помочь.
И да: приложение крутится на Flask, а сам сервер - VDS-хостинг.
Такое началось сравнительно недавно, но точно сказать, что повлияло, не могу. В целом увеличилась нагрузка, запросов стало больше, но если смотреть, например, на графики в Zabbix, то картина вполне спокойная. Более того, иногда при "тишине" на графиках запросы очень тормозят. В эти моменты и запросов мало, и нагрузка на проц небольшая.
Попробую профайлером.

[Алексей]

Dr. Bacon, а как убедиться в том, что имеет место быть ожидание в очереди на обработку? Где посмотреть?

[Алексей]

Пробовал играться с настройками uwsgi, не помогло.
Вот инфа из профайлера, первые несколько строк:

25707 function calls (25166 primitive calls) in 0.522 seconds
   Ordered by: internal time, call count
   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
       26    0.383    0.015    0.383    0.015 {method 'recv' of '_socket.socket' objects}
        4    0.054    0.013    0.054    0.013 {function execute at 0x7f8a41c29500}
        1    0.014    0.014    0.014    0.014 {psycopg2._psycopg._connect}
        4    0.010    0.002    0.014    0.003 /usr/lib/python2.7/collections.py:305(namedtuple)
       26    0.006    0.000    0.006    0.000 {method 'sendall' of '_socket.socket' objects}
      504    0.004    0.000    0.011    0.000 {method 'sort' of 'list' objects}

Можете что-то сказать по первой строке? Имею ввиду

26    0.383    0.015    0.383    0.015 {method 'recv' of '_socket.socket' objects}

[Алексей]

4 ядра, 4 Гига

Вот конфиг uwsgi:

[uwsgi]
base_dir = /var/www/my_app
gid = www-data
uid = www-data
vhost = true
socket = /tmp/flask.sock
stats = /tmp/flask_stats.sock
venv = %(base_dir)/venv
chdir = %(base_dir)
module = myapp
callable = app
touch-reload=%(base_dir)/touch-reload
master = true
processes = 15
threads = 5
enable-threads = True
buffer-size = 65535
harakiri = 600
shared-pyimport = _strptime
ignore-sigpipe = True
die-on-term = true

[Алексей]

Dr. Bacon, Пробовал, не помогает.

[Алексей]

Насчёт очередей. Вот сегодня выбрал время, когда активность на сервере минимальная (до 5 запросов в МИНУТУ), и получил тот же результат. Т.е. странное дело - очередей быть не должно, но время upstream_response_time не меняется, и такое же огромное, т.е. на запрос, вытягивающий из БД несколько записей за время ~0.05 сек, накручивается сверху 0.7 сек.
Пользую uwsgitop, кстати. И он тоже не показывает особой активности.

[Алексей]

Dr. Bacon, На всех запросах.

[Алексей]

Dr. Bacon, Попробую сейчас в принципе заменить uwsgi на что-то другое. Например, на gunicorn.

[Алексей]

Dr. Bacon, В общем, на производственной среде поставил в параллель со своим сайтом такой же, и навесил его на gunicorn. Условия совпадают идеально. Никакой разницы в итоге по производительности между gunicorn и uwsgi не обнаружилось. Та же потеря 3/4 времени ответа от сервера, которая приходится на ... что?
Так и не понял, кто у кого в очереди стоит))

[Everything_is_not_so_bad]

Каковы итоги, находки?

[Алексей]

Роман Мирр, по существу никаких находок. В итоге удалось слегка повысить производительность путём оптимизации кода. Но это не решение, к сожалению.

Answer 1

[Vadim Priluzkiy]

Может поможет, но вот тут на него ругаются.
Ну и вообще говоря запрос в гугле «uwsgi настройка производительности» даёт энное количество результатов.

Comments

[Алексей]

Спасибо, интересная статья!