Оптимизация обработки шаблонов

На практике пришлось столкнутся с некоторыми не очевидными особенностями производительности обработки шаблонов. Изучение вопроса породило небольшое исследование, результатами которого спешу поделиться.

Предыстория

В настоящее время я занимаюсь разработкой достаточно большого проекта на Django. Проект большой, разрабатываю я его фактически один, соответственно вопрос оптимизации возникает только тогда, когда совсем припекло. Общая техническая информация по проекту:
Размер проекта: около 70к строк
Django: 1.4.3
Окружение: apache2+mod_wsgi+virtualenv, python2.6, mysql, выделенный сервер. Проект на сервере не единственный.

Оценка проблемы

Я любитель изобретения велосипедов, по этому декоратором с представления собрал время исполнения, имя модуля, имя функции, пользователя и ключевой параметр и сохранил все в БД.

Итог — среднее время выполнения одного из основных представлений составило 1200мс, что крайне печально.

Оптимизация работы с базой данных

Первое что приходит на ум — это конечно неффективная работа с БД. Был проведен достаточно большой объем работы, который уменьшил количество запросов к БД вдвое, их сложность(и время исполнения) еще вдвое. Предполагалось что это исправит ситуацию, но результат оказался совсем не впечатляющим. Время исполнения упало «всего» на 100мс и составило 1100мс, что не сделало погоды. Запас оптимизации БД еще оставался, да есть и множество других способов, но стало ясно, что проблема явно не в работе с базой данных. Более детальное профилирование функции представления показало, что около 80-90% времени исполняется строчка, которую привыкаешь не замечать:

return direct_to_template(request, template_name, locals()) 

В качестве шаблонизатора в проекте используется hamlpy, который сам по себе не быстр. Сами шаблоны достаточно сложны — включают двойное наследование, несколько include, циклы, достаточно много логики, связанной с отображением. Тем не менее 950мс для рендеринга это слишком.

Обновление hamlpy до последней версии выиграло еще около 50мс. Рендеринг шаблона все равно занимает в среднем 900мс.

Более подробное изучение вопроса позволило узнать о том, что джанго умеет кешировать шаблоны, и это надо настраивать отдельно:

TEMPLATE_LOADERS = (     ('django.template.loaders.cached.Loader', (         'hamlpy.template.loaders.HamlPyFilesystemLoader',         'hamlpy.template.loaders.HamlPyAppDirectoriesLoader',         'django.template.loaders.filesystem.Loader',         'django.template.loaders.app_directories.Loader',     )), ) 

Время обработки шаблона заметно упало, до 500-600мс, но все еще осталось значительным. При этом появился неприятный эффект — изменения в шаблонах, что логично, перестали цепляться на лету. Так что под DEBUG от кеширования лучше отказаться.

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

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

Возвращаясь к кешированию, его график распределения выглядит так:

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

WSGIDaemonProcess mysite threads=5 maximum-requests=5

Это переводит жизненный цикл потоков из ведения апача в mod_wsgi и задает продолжительность жизни потока в 5 запросов. Получаем следующий график:

Как видно пик справа стал меньше. Потоки стали умирать реже, эффективность кеширования выросла, среднее время выполнения — упало. Путь явно правильный, но график хорошо работающего кеширования очевидно должен выглядеть не так. Увеличиваем время жизни до 10 запросов:

Уже неплохо. Время исполнения заметно упало до приемлемого значения в 230мс. Лучшее — враг хорошего, а продолжительность жизни потока — не ерунда. Изучение потребления памяти через top не выявило ощутимых проблем, так что увеличиваем продолжительность жизни до 15:

Такой график выглядит правдоподобно — не кешированные запросы перестали быть статистически значимыми, а значит дальнейшее увеличение жизни потоков не даст ощутимого результата. Итоговое достигнутое время исполнения — 190мс. Само время исполнения представления упало с 900 до 290мс, что уже гораздо лучше.

Выводы

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