http://habrahabr.ru/post/237317/

Это шестнадцатая статья в серии, где я описываю свой опыт написания веб-приложения на Python с использованием микрофреймворка Flask.

Цель данного руководства — разработать довольно функциональное приложение-микроблог, которое я за полным отсутствием оригинальности решил назвать microblog.



Наше скромное приложение начинает подавать признаки готовности к релизу, так что настало время привести его в порядок настолько, насколько это возможно. Не так давно один из читателей этого блога (привет, Джордж!) сообщил о странном поведении базы данных, которое мы сегодня и постараемся отладить. Это должно помочь нам осознать, что независимо от того как внимательно мы писали код и как часто его тестировали, некоторые ошибки порой остаются незамеченными. К сожалению, обычно их обнаруживают именно конечные пользователи.

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

В первой части этой статьи мы рассмотрим отладку и я покажу вам некоторые приёмы и техники, которые я применяю при отладке сложных проблем.

Позже, мы увидим как можно оценить эффективность нашей стратегии тестирования. Мы измерим, какую часть нашего кода покрывают наши unit тесты, это то, что называют покрытие тестами.

И в заключении, мы поразмышляем о другом классе проблем с которыми часто сталкиваются многие приложения — о недостаточной производительность. Мы рассмотрим техники профилирования чтобы найти медленные части нашего приложения.

Звучит неплохо? Тогда давайте начнём.

Ошибка

Проблема была обнаружена читателем этого блога, после реализации им новой функции, позволяющей пользователям удалять свои записи. Официальная версия microblog-а не включает в себя эту функцию, поэтому мы по-быстрому её реализуем, чтобы иметь возможность отладить.
Функция представления, удаляющая посты (файл app/views.py):

@app.route('/delete/<int:id>')
@login_required
def delete(id):
    post = Post.query.get(id)
    if post == None:
        flash('Post not found.')
        return redirect(url_for('index'))
    if post.author.id != g.user.id:
        flash('You cannot delete this post.')
        return redirect(url_for('index'))
    db.session.delete(post)
    db.session.commit()
    flash('Your post has been deleted.')
    return redirect(url_for('index'))

Чтобы задействовать эту функцию, мы добавим ссылку удаления ко всем постам, принадлежащим текущему пользователю (файл app/templates/post.html):

{% if post.author.id == g.user.id %}
<div><a href="{{ url_for('delete', id = post.id) }}">{{ _('Delete') }}</a></div>
{% endif %}

Здесь нет ничего нового для нас, мы делали это неоднократно и ранее.

Давайте двинемся дальше и запустим наше приложение с отключенным режимом отладки (debug=False), чтобы посмотреть на него глазами пользователя.
Пользователи Linux и Mac, выполните в консоли:

$ ./runp.py

Пользователи Windows, запустите эту команду в командной оболочке:

flask/Scripts/python runp.py

Теперь, находясь в роли пользователя, создайте пост, а затем попытайтесь удалить его. И как только вы кликнете по ссылке удаления… Бац!

Мы получили краткое сообщение о том, что произошла некоторая ошибка и администратор будет уведомлен о ней. На самом деле, это сообщение является нашим шаблоном 500.html. С отключенным режимом отладки, Flask на все ошибки, произошедшие во время обработки запроса, возвращает этот шаблон. Т.к. мы находимся в «продакшн» режиме, мы не увидим ни реального сообщения об ошибке, ни стэка вызовов.

Отладка проблемы «в поле»

Если вы помните статью посвященную unit тестированию, мы активировали несколько сервисов отладки для запуска в «продакшн» версии нашего приложения. Тогда мы создали логгер, пишущий ошибки и диагностические сообщения в лог-файл во время работы приложения. Flask сам записывает стэк вызовов любого произошедшего и не обработанного, до завершения запроса, исключения. Кроме того, у нас настроен логгер, отправляющий всем членам списка администраторов, сообщения по email при записи ошибки в лог.

Так что, при возникновении ошибки вроде произошедшей выше, у нас будет некоторая информация о её природе сразу в двух местах: в лог-файле и в электронном письме.

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

127.0.0.1 - - [03/Mar/2013 23:57:39] "GET /delete/12 HTTP/1.1" 500 -
Traceback (most recent call last):
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1701, in __call__
    return self.wsgi_app(environ, start_response)
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1689, in wsgi_app
    response = self.make_response(self.handle_exception(e))
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1687, in wsgi_app
    response = self.full_dispatch_request()
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1360, in full_dispatch_request
    rv = self.handle_user_exception(e)
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1358, in full_dispatch_request
    rv = self.dispatch_request()
  File "/home/microblog/flask/lib/python2.7/site-packages/flask/app.py", line 1344, in dispatch_request
    return self.view_functions[rule.endpoint](**req.view_args)
  File "/home/microblog/flask/lib/python2.7/site-packages/flask_login.py", line 496, in decorated_view
    return fn(*args, **kwargs)
  File "/home/microblog/app/views.py", line 195, in delete
    db.session.delete(post)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 114, in do
    return getattr(self.registry(), name)(*args, **kwargs)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1400, in delete
    self._attach(state)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1656, in _attach
    state.session_id, self.hash_key))
InvalidRequestError: Object '<Post at 0xff35e7ac>' is already attached to session '1' (this is '3')

Если вы уже занимались чтением подобных сообщений об ошибках при использовании других языков программирования, то имейте в виду, что Python показывает стэк вызовов в обратном порядке, т. е. фрэйм вызвавший ошибку, находится в самом низу.

Как же нам теперь в этом разобраться?

Судя по распечатке стэка вызовов, исключение было выброшено кодом обработки сессии SQLAlchemy, находящимся в файле sqlalchemy/orm/session.py.

При работе со стэком вызовов всегда полезно найти последнее выполненное выражение из нашего собственного кода. Если мы начнем снизу и будем постепенно, фрэйм за фрэймом, подниматься вверх по трассе, мы обнаружим четвертый фрэйм в нашем файле app/views.py, а точнее в выражении db.session.delete(post) нашей функции представления delete().

Теперь мы знаем, что SQLAlchemy не может удалить этот пост в текущей сессии базы данных. Но мы по-прежнему не знаем, почему.

Если взглянуть на текст исключения в самом низу, то кажется, что проблема в том, что объект Post принадлежит сессии «1», а мы пытаемся присоединить тот же объект другой сессии «3».

Если вы попросите помощи у Google, вы обнаружите, что большинство подобных проблем возникают при использовании многопоточных вэб серверов, которые выполняют два запроса пытаясь присоединить объект сразу к двум разным сессиям одновременно. Но мы-то используем однопоточный отладочный сервер Python-а, так что это не наш случай. Значит существует какая-то другая проблема, создающая две активные сессии вместо одной.

Чтобы узнать больше о проблеме, мы должны попытаться повторить ошибку в более контролируемом окружении. К счастью, эта ошибка проявляется и на «development» версии нашего приложения, а это несколько лучше, т. к. дает нам доступ к вэб версии стэка вызовов, предоставляемой самим Flask-ом вместо шаблона 500.html.

Вэб версия стэка вызовов примечательна тем, что дает нам увидеть код и тут же посмотреть на результат выполнения выражений и всё это прямо из браузера. Не имея достаточно глубокого понимания происходящего в коде, мы догадываемся что существует сессия '1' (мы может только предположить, что это самая первая созданная сессия) которая, по каким-то причинам, не была удалена как любая обычная сессия при завершении запроса создавшего эту сессию. Итак, для движения вперед в решении проблемы, было бы неплохо узнать кто создает эту незакрываемую сессию.

Использование отладчика Python

Самый простой способ узнать кто создает объект — установить точку останова в конструкторе объекта. Точка останова — это команда, приостанавливающая выполнение программы при выполнении некоторого условия. И потом в этой точке есть возможность исследовать программу, просмотреть стэк вызовов в данной конкретный точке выполнения, просмотреть и даже изменить содержимое переменных и т. д. Точки останова одна из базовых возможностей отладчиков. На этот раз мы используем отладчик, поставляемый вместе с интерпретатором Python, именуемый pdb.

Но какой класс мы ищем? Давайте вернемся назад, к вэб версии трассы и оглядимся. В нижней части каждого фрэйма трассы есть ссылки на просмотрщик кода и на консоль Python (иконки расположена справа и становятся видны при наведении мышки на фрэйм) при помощи которой мы можем отыскать класс, использующий сессии. На панели кода мы видим, что находимся внутри класса Session, который, судя по всему, является базовым классом для сессий работы с базой данных SQLAlchemy. Поскольку контекст нижнего фрэйма стэка находится внутри объекта сессии, мы можем получить фактический класс сессии в консоли:

>>> print self
<flask_sqlalchemy._SignallingSession object at 0xff34914c>

Теперь мы знаем, что используемые нами сессии определены в Flask-SQLAlchemy, т. к. похоже это расширение определяет собственный класс сессий, наследующий класс Session пакета SQLAlchemy.

Теперь мы можем исследовать исходный код расширения Flask-SQLAlchemy расположенный в файле flask/lib/python2.7/site-packages/flask_sqlalchemy.py и найти там конструктор __init__() класса _SignallingSession. Теперь мы полностью готовы к отладке.

Существует несколько способов установить точку останова в python приложение. Наиболее простым является добавление следующего кода в том месте, где мы хотим остановить программу:

import pdb; pdb.set_trace()

Что мы и сделаем, временно добавив точку останова в конструктор класса _SignallingSession (файл flask/lib/python2.7/site-packages/flask_sqlalchemy.py):

class _SignallingSession(Session):

    def __init__(self, db, autocommit=False, autoflush=False, **options):
        import pdb; pdb.set_trace() # <-- this is temporary!
        self.app = db.get_app()
        self._model_changes = {}
        Session.__init__(self, autocommit=autocommit, autoflush=autoflush,
                         extension=db.session_extensions,
                         bind=db.engine,
                         binds=db.get_binds(self.app), **options)

    # ...

Теперь давайте снова запустим приложение и посмотрим что из этого выйдет:

$ ./run.py
> /home/microblog/flask/lib/python2.7/site-packages/flask_sqlalchemy.py(198)__init__()
-> self.app = db.get_app()
(Pdb)

Т.к. сообщение «Running on...» так и не появилось, мы понимаем, что сервер еще до конца не запустился. Выполнение программы прервалось, т. к. в некоторой части кода некто запросил создание нашей «таинственной» сессии!

Наиболее важный вопрос на который мы должны ответить немедленно — где в приложении мы сейчас находимся, т. к. это должно подсказать нам, кто же запросил создание той самой сессии '1' от которой позднее в ходе выполнения программы мы никак не можем избавиться. Мы применим команду bt (сокращение для backtrace) для получения содержимого стэка вызовов:

(Pdb) bt
  /home/microblog/run.py(2)<module>()
-> from app import app
  /home/microblog/app/__init__.py(44)<module>()
-> from app import views, models
  /home/microblog/app/views.py(6)<module>()
-> from forms import LoginForm, EditForm, PostForm, SearchForm
  /home/microblog/app/forms.py(4)<module>()
-> from app.models import User
  /home/microblog/app/models.py(92)<module>()
-> whooshalchemy.whoosh_index(app, Post)
  /home/microblog/flask/lib/python2.6/site-packages/flask_whooshalchemy.py(168)whoosh_index()
-> _create_index(app, model))
  /home/microblog/flask/lib/python2.6/site-packages/flask_whooshalchemy.py(199)_create_index()
-> model.query = _QueryProxy(model.query, primary_key,
  /home/microblog/flask/lib/python2.6/site-packages/flask_sqlalchemy.py(397)__get__()
-> return type.query_class(mapper, session=self.sa.session())
  /home/microblog/flask/lib/python2.6/site-packages/sqlalchemy/orm/scoping.py(54)__call__()
-> return self.registry()
  /home/microblog/flask/lib/python2.6/site-packages/sqlalchemy/util/_collections.py(852)__call__()
-> return self.registry.setdefault(key, self.createfunc())
> /home/microblog/flask/lib/python2.6/site-packages/flask_sqlalchemy.py(198)__init__()
-> self.app = db.get_app()
(Pdb)

Как и раньше, мы начинаем снизу и продвигаемся вверх в поисках нашего кода. И это оказывается строка 92 в нашем файле моделей models.py, в которой инициализируется наш полнотекстовой поиск:

whooshalchemy.whoosh_index(app, Post)

Странно. Мы не создаем сессию базы данных и не делаем ничего, что должно было бы создать эту сессию, но, похоже, что сама по себе инициализация Flask-WhooshAlchemy создает сессию.

Создается ощущение, что это не наша ошибка, а скорее какой-то конфликт между расширениями-обертками для SQLAlchemy и Whoosh. Мы могли бы остановиться здесь и просто попросить помощи у разработчиков этих двух замечательных расширений или у их сообществ. Или же мы можем продолжить отладку и посмотреть, получится ли решить проблему здесь и сейчас. Итак, я продолжу отладку, а вы, если вам не интересно, можете свободно переходить к следующему разделу.

Давайте еще раз взглянем на стэк вызовов. Мы вызываем call whoosh_index(), которая, в свою очередь, вызывает _create_index(). Конкретная строка _create_index() выглядит так:

model.query = _QueryProxy(model.query, primary_key,
            searcher, model)

Переменная model в этом контексте представляет наш класс Post, и её мы передаем в качестве аргумента в функцию whoosh_index(). Учитывая это, похоже, что Flask-WhooshAlchemy создает обертку Post.query, которая принимает исходный Post.query в качестве аргумента плюс некоторый Whoosh-специфичный контент. А вот это уже интересно. Судя по трассе представленной выше, следующей функцией в очереди является __get__(), один из методов-дескрипторов языка python.

Метод __get__() используется для реализации дескрипторов, представляющих собой аттрибут имеющий определенное поведение, помимо значения. Каждый раз при упоминании дескриптора, вызывается функция __get__(). Затем функция должна вернуть значение аттрибута. Единственный аттрибут, упоминаемый в этой строке кода — это query, так что теперь мы знаем, что внешне простой аттрибут, который мы ранее использовали для генерации запросов к базе данных, на самом деле является дескриптором а не аттрибутом. Остаток стэка вызовов занимается вычислением значения выражения model.query, готовясь к созданию конструктора объекта _QueryProxy.

Теперь давайте спустимся по стэку немного ниже, чтобы посмотреть что происходит далее. Инструкция из метода __get__() представлена ниже:

return type.query_class(mapper, session=self.sa.session())

И это довольно любопытный участок кода. Когда мы вызываем, к примеру, User.query.get(id) мы косвенно вызываем метод __get__() для получения объекта запроса, а вместе с ним получаем и сессию!

Когда Flask-WhooshAlchemy выполняет model.query, то создается сессия и привязывается к объекту запроса. Но объект запроса, запрошенный Flask-WhooshAlchemy не такой недолговечный как те, что мы запускаем внутри наших функций предсталвения. Flask-WhooshAlchemy оборачивает этот объект запроса в свой собственный объект запроса, который сохраняется обратно в model.query. Т.к. метода __set__() не существует, новый объект сохраняется в виде аттрибута. Для нашего класса Post это означает, что после завершения инициализации Flask-WhooshAlchemy, у нас будет присутствовать дескриптор и аттрибут с одинаковыми именами. В соответствии с приоритетом, в этом случае выигрывает аттрибут, что вполне ожидаемо, потому что если бы это было не так, наш построенный на Whoosh поиск не работал бы.

Важной деталью этого является то, что приведенный код устанавливает постоянный аттрибут, содежащий внутри сессию '1'. Даже несмотря на то, что первый запрос обработанный приложением использует эту сессию и забудет о ней сразу по окончании, сама сессию никуда не денется т. к. на неё продолжает ссылаться аттрибут Post.query. Это и есть та самая ошибка!
Эта ошибка вызвана запутанной (на мой взгляд) природой дескрипторов. Они выглядят как обычные аттрибуты и люди их так и используют. Разработчик Flask-WhooshAlchemy просто хотел создать расширенный объект запроса для хранения некоторой полезной, для выполнения своих запросов, информации, но не осознавал до конца, что использование аттрибута модели query, делает несколько больше чем кажется, т. к. имеет скрытое поведение, открывающее сессию с базой данных.

Регресионные тесты

Для многих, скоре всего, наиболее логичным шагом в этой ситуации кажется исправить ошибку Flask-WhooshAlchemy и двигаться дальше. Но если мы так поступим, что гарантирует нам отсутствие подобной ошибки в будущем? Например, что произойдет если через год мы решим обновить Flask-WhooshAlchemy до новой версии и забудем о нашей правке?

Оптимальным вариантом при обнаружении любой ошибки, является создание unit теста для неё, чтобы не допустить повторное возникновение ошибки (так называемой регрессии) в будущем.

Однако есть некоторая сложность в создании теста для этой ошибки, т. к. мы должны эмулировать два запроса внутри одного теста. Первый запрос будет обращаться к объекту Post, эмулируя запрос, который мы производим для отображения данных на странице. И так как это первый запрос, он будет использовать сессию '1'. Затем мы должны забыть эту сессию и создать новую точно так, как поступает Flask-SQLAlchemy. Попытка удаления объекта Post во второй сессии должна возбудить снова эту ошибку, т. к. первая сессия не окончена, как ожидалось.

Заглянув в исходный код Flask-SQLAlchemy еще раз, мы видим что новые сессии создаются функцией db.create_scoped_session(), и после завершения запроса сессия уничтожается вызовом функции db.session.remove(). Зная это, довольно просто написать тест для этой ошибки:

def test_delete_post(self):
    # create a user and a post
    u = User(nickname = 'john', email = 'john@example.com')
    p = Post(body = 'test post', author = u, timestamp = datetime.utcnow())
    db.session.add(u)
    db.session.add(p)
    db.session.commit()
    # query the post and destroy the session
    p = Post.query.get(1)
    db.session.remove()
    # delete the post using a new session
    db.session = db.create_scoped_session()
    db.session.delete(p)
    db.session.commit()

И, естественно, при запуске тестов мы получим сообщение о проваленном тесте:

$ ./tests.py
.E....
======================================================================
ERROR: test_delete_post (__main__.TestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "./tests.py", line 133, in test_delete_post
    db.session.delete(p)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/scoping.py", line 114, in do
    return getattr(self.registry(), name)(*args, **kwargs)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1400, in delete
    self._attach(state)
  File "/home/microblog/flask/lib/python2.7/site-packages/sqlalchemy/orm/session.py", line 1656, in _attach
    state.session_id, self.hash_key))
InvalidRequestError: Object '<Post at 0xff09b7ac>' is already attached to session '1' (this is '3')

----------------------------------------------------------------------
Ran 6 tests in 3.852s

FAILED (errors=1)

Исправление

Для решения этой проблемы, мы должны найти альтернативный способ привязки объекта запроса Flask-WhooshAlchemy к модели.

В документации Flask-SQLAlchemy упоминается аттрибут model.query_class, содержащий класс применяемый для выполнения запросов. На самом деле, это гораздо более прозрачный и понятный способ заставить Flask-SQLAlchemy использовать модифицированный класс запроса, чем используемый Flask-WhooshAlchemy. Если мы настроим Flask-SQLAlchemy на создание запросов с использованием класса запроса Whoosh (который наследует класс BaseQuery из состава Flask-SQLAlchemy), тогда результат не изменится, но пропадет ошибка.

Я создал форк проекта Flask-WhooshAlchemy на github где реализовал эти изменения. Если вы желаете ознакомиться с изменениями, вы можете посмотреть github diff моего коммита, или можете скачать исправленное расширение целиком и заменить им оригинальный файл flask_whooshalchemy.py.

Я отправил внесенные мной изменения разработчику Flask-WhooshAlchemy, и теперь смею надеяться, что со временем они будут включены в официальную версию.

Покрытие тестами

Одним из способов критически снизить вероятность появления ошибки после развертывания нашего приложения на сервере, является плотное покрытие тестами. У нас уже имеется тестировочный фрэймворк, но как нам узнать какая часть приложения на самом деле подвергается тестированию при его использовании?

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

У python имеется свой инструмент измерения покрытия тестами, с простым именем coverage. Давайте установим его:

flask/bin/pip install coverage

Этот инструмент можно задействовать из командной строки или встроить вызов прямо в скрипт. Чтобы случайно не забыть запустить его, мы выберем последний вариант.

Вот изменения, которые нужно добавить к нашим тестам, чтобы сгенерировать отчет (файл tests.py):

from coverage import coverage
cov = coverage(branch = True, omit = ['flask/*', 'tests.py'])
cov.start()

# ...

if __name__ == '__main__':
    try:
        unittest.main()
    except:
        pass
    cov.stop()
    cov.save()
    print "\n\nCoverage Report:\n"
    cov.report()
    print "HTML version: " + os.path.join(basedir, "tmp/coverage/index.html")
    cov.html_report(directory = 'tmp/coverage')
    cov.erase()

Мы начинаем с инициализации модуля coverage в начале скрипта. Параметр branch = True указывает на необходимость проведения анализа ветвей исполнения в дополнение к обычной построчной проверке покрытия. Параметр omit необходим, чтобы исключить из проверки все сторонние модули, установленные в нашем виртуальном окружении и сам тестировочный фрэймворк, так как нас интересует анализ кода только нашего приложения.

Для сбора статистики покрытия, мы вызываем cov.start(), а затем запускаем наши unit тесты. Мы должны перехватывать и пропускать возникшие исключения в нашем тестировочном фрэймворке, потому что в противном случае скрипт завершится без генерации отчета о покрытии тестами. После окончания тестов, мы останавливаем coverage при помощи cov.stop(), и записываем результаты при помощи cov.save(). В конце, cov.report() выводит статистику в консоль, cov.html_report() генерирует более привлекательный HTML отчет с теми же данными, а cov.erase() удаляет файл данных.

Вот пример запуска тестов с активированной генерацией отчета (заметьте, я оставил падающий тест):

$ ./tests.py
.....F
    ======================================================================
FAIL: test_translation (__main__.TestCase)
----------------------------------------------------------------------
Traceback (most recent call last):
  File "./tests.py", line 143, in test_translation
    assert microsoft_translate(u'English', 'en', 'es') == u'Inglés'
AssertionError

----------------------------------------------------------------------
Ran 6 tests in 3.981s

FAILED (failures=1)

Coverage Report:

Name             Stmts   Miss Branch BrMiss  Cover   Missing
------------------------------------------------------------
app/__init__        39      0      6      3    93%
app/decorators       6      2      0      0    67%   5-6
app/emails          14      6      0      0    57%   9, 12-15, 21
app/forms           30     14      8      8    42%   15-16, 19-30
app/models          63      8     10      1    88%   32, 37, 47, 50, 53, 56, 78, 90
app/momentjs        12      5      0      0    58%   5, 8, 11, 14, 17
app/translate       33     24      4      3    27%   10-36, 39-56
app/views          169    124     46     46    21%   16, 20, 24-30, 34-37, 41, 45-46, 53-67, 75-81, 88-109, 113-114, 120-125, 132-143, 149-164, 169-183, 188-198, 203-205, 210-211, 218
config              22      0      0      0   100%
------------------------------------------------------------
TOTAL              388    183     74     61    47%

HTML version: /home/microblog/tmp/coverage/index.html

Согласно отчету, мы покрыли тестами 47% нашего приложения. А также мы получили список строк, не запускавшихся нашими тестами, а значит нам нужно просмотреть эти строки и подумать над тем, какими тестами можно их покрыть.

Также мы узнали, что покрытие модуля app/models.py довольно высокое (88%), т. к. мы в основном сфокусировались на тестировании наших моделей. Покрытие модуля app/views.py сравнительно низкое (21%) т. к. мы на данный момент не выполняем функции представлений в наших тестах.

В дополнение к пропущенным тестами строкам, этот инструмент предоставляет информацию о покрытии ветвей исполнения в столбцах Branch и BrMiss. Рассмотрим следующий пример скрипта:

def f(x):
    if x >= 0:
        x = x + 1
    return x

f(1)

Если мы запустим coverage для этой простой функции, мы получим 100% покрытия, т. к. получая на входе 1, функция выполняет все 3 строки. Но мы не выполняли эту функцию с аргументом меньшим 0, а это может привести к иному поведению. В более сложных случаях, это может стать причиной ошибки.

Проверка покрытия ветвей исполнения сообщит нам как много ветвей исполнения мы пропустили и это еще один повод подумать о тестах, которых, возможно, нам не хватает.

Модуль coverage также генерирует симпатичный HTML отчет, отображающий исходный код с отмеченными цветом строками и ветвями исполнения покрытыми тестами и пропущенными.

Продолжая придерживаться нашей стратегии, ориентированной в основном на тесты моделей, мы можем рассмотреть участки нашего файла app/models.py которые не покрываются тестами. Это очень просто сделать, используя HTML отчет, из которого мы получаем следующий список:

• User.make_valid_nickname()
• User.is_authenticated()
• User.is_active()
• User.is_anonymous()
• User.get_id()
• User.__repr__()
• Post.__repr__()

User.make_unique_nickname() (только для ветви исполнения, когда полученное имя уникально и не требует преобразований)

Мы можем объединить первые пять фрагментов в следующем тесте:

def test_user(self):
    # make valid nicknames
    n = User.make_valid_nickname('John_123')
    assert n == 'John_123'
    n = User.make_valid_nickname('John_[123]\n')
    assert n == 'John_123'
    # create a user
    u = User(nickname = 'john', email = 'john@example.com')
    db.session.add(u)
    db.session.commit()
    assert u.is_authenticated() == True
    assert u.is_active() == True
    assert u.is_anonymous() == False
    assert u.id == int(u.get_id())

Функции __repr__() предназначены только для внутреннего использования, поэтому нам нет необходимости тестировать их. А значит, мы можем отметить их как игнорируемые:

def __repr__(self): # pragma: no cover
    return '<User %r>' % (self.nickname)

И наконец, при написании теста для make_unique_nickname() мы сосредоточились на обработке конфликтов имен, но забыли добавить тест для случая когда имя уникально и не требует обработки. Мы можем расширить наш существующий тест для покрытия и этого случая:

def test_make_unique_nickname(self):
    # create a user and write it to the database
    u = User(nickname = 'john', email = 'john@example.com')
    db.session.add(u)
    db.session.commit()
    nickname = User.make_unique_nickname('susan')
    assert nickname == 'susan'
    nickname = User.make_unique_nickname('john')
    assert nickname != 'john'
    #...

И благодаря этим простым поправкам, мы получаем покрытие 100% нашего файла моделей models.py.

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

Профилирование производительности

Следующей темой дня является производительность. Нет ничего более ужасного для пользователя любого сайта, чем долгая загрузка страниц. Мы хотим убедиться что наше приложение работает так быстро, как это только возможно, поэтому мы должны принять ряд мер чтобы быть готовым к решению проблем производительности.

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

Python поставляется с приличным профайлером cProfile. Мы могли бы встроить этот профайлер прямо в наше приложение, но прежде чем делать это, стоит поискать готовое решение. Быстрый поиск по фразе «Flask profiler» подскажет нам, что Werkzeug, используемый Flask-ом, поставляется с готовым к использованием модулем профайлера, так что нам остается только использовать его.

Для активации профайлера Werkzeug, мы можем создать другой стартовый сценарий подобный run.py. Давайте назовем его profile.py:

#!flask/bin/python
from werkzeug.contrib.profiler import ProfilerMiddleware
from app import app

app.config['PROFILE'] = True
app.wsgi_app = ProfilerMiddleware(app.wsgi_app, restrictions = [30])
app.run(debug = True)

Запуск приложения при помощи этого скрипта позволит профайлеру отображать 30 наиболее длительных функций для каждого запроса (об аргументе restrictions можно подробнее узнать в документации).

Когда приложение запущено, каждый запрос будет показывать информацию профилировщика. Вот пример:

--------------------------------------------------------------------------------
PATH: '/'
         95477 function calls (89364 primitive calls) in 0.202 seconds

   Ordered by: internal time, call count
   List reduced from 1587 to 30 due to restriction <30>

   ncalls  tottime  percall  cumtime  percall filename:lineno(function)
        1    0.061    0.061    0.061    0.061 {method 'commit' of 'sqlite3.Connection' objects}
        1    0.013    0.013    0.018    0.018 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/pysqlite.py:278(dbapi)
    16807    0.006    0.000    0.006    0.000 {isinstance}
     5053    0.006    0.000    0.012    0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:163(iter_child_nodes)
8746/8733    0.005    0.000    0.005    0.000 {getattr}
      817    0.004    0.000    0.011    0.000 flask/lib/python2.7/site-packages/jinja2/lexer.py:548(tokeniter)
        1    0.004    0.004    0.004    0.004 /usr/lib/python2.7/sqlite3/dbapi2.py:24(<module>)
        4    0.004    0.001    0.015    0.004 {__import__}
        1    0.004    0.004    0.009    0.009 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/__init__.py:7(<module>)
   1808/8    0.003    0.000    0.033    0.004 flask/lib/python2.7/site-packages/jinja2/visitor.py:34(visit)
     9013    0.003    0.000    0.005    0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:147(iter_fields)
     2822    0.003    0.000    0.003    0.000 {method 'match' of '_sre.SRE_Pattern' objects}
      738    0.003    0.000    0.003    0.000 {method 'split' of 'str' objects}
     1808    0.003    0.000    0.006    0.000 flask/lib/python2.7/site-packages/jinja2/visitor.py:26(get_visitor)
     2862    0.003    0.000    0.003    0.000 {method 'append' of 'list' objects}
  110/106    0.002    0.000    0.008    0.000 flask/lib/python2.7/site-packages/jinja2/parser.py:544(parse_primary)
       11    0.002    0.000    0.002    0.000 {posix.stat}
        5    0.002    0.000    0.010    0.002 flask/lib/python2.7/site-packages/sqlalchemy/engine/base.py:1549(_execute_clauseelement)
        1    0.002    0.002    0.004    0.004 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/base.py:124(<module>)
  1229/36    0.002    0.000    0.008    0.000 flask/lib/python2.7/site-packages/jinja2/nodes.py:183(find_all)
    416/4    0.002    0.000    0.006    0.002 flask/lib/python2.7/site-packages/jinja2/visitor.py:58(generic_visit)
   101/10    0.002    0.000    0.003    0.000 flask/lib/python2.7/sre_compile.py:32(_compile)
       15    0.002    0.000    0.003    0.000 flask/lib/python2.7/site-packages/sqlalchemy/schema.py:1094(_make_proxy)
        8    0.002    0.000    0.002    0.000 {method 'execute' of 'sqlite3.Cursor' objects}
        1    0.002    0.002    0.002    0.002 flask/lib/python2.7/encodings/base64_codec.py:8(<module>)
        2    0.002    0.001    0.002    0.001 {method 'close' of 'sqlite3.Connection' objects}
        1    0.001    0.001    0.001    0.001 flask/lib/python2.7/site-packages/sqlalchemy/dialects/sqlite/pysqlite.py:215(<module>)
        2    0.001    0.001    0.002    0.001 flask/lib/python2.7/site-packages/wtforms/form.py:162(__call__)
      980    0.001    0.000    0.001    0.000 {id}
  936/127    0.001    0.000    0.008    0.000 flask/lib/python2.7/site-packages/jinja2/visitor.py:41(generic_visit)

--------------------------------------------------------------------------------

127.0.0.1 - - [09/Mar/2013 19:35:49] "GET / HTTP/1.1" 200 -

Столбцы в этом отчете означают следующее:

• ncalls: сколько раз была вызвана функция.
• tottime: время, проведенное внутри функции.
• percall: значение tottime деленное на ncalls.
• cumtime: общее время проведенное в функции и функциях вызываемых из неё.
• percall: cumtime деленное на ncalls.
• filename:lineno(function): имя функции и её номер строки в исходном коде.

Примечательно, что наши шаблоны также встречаются здесь в виде функций. Это происходит потому, что Jinja2 кёомпилирует шаблоны в код на языке Python. Это означает, что профайлер будет сообщать нам не только о медленном коде, но и о медленных шаблонах!

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

По мере роста приложения, будет полезно запускать иногда новые добавленные запросы при помощи профайлера чтобы убедиться, что мы на правильном пути.

Производительность базы данных

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

В документации Flask-SQLAlchemy упоминается функция get_debug_queries, которая возвращает список выполненных запросов с временем их выполнения.

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

Для использования этого свойства в продакшне, мы должны прямо разрешить его в конфигурационном файле (файл config.py):

SQLALCHEMY_RECORD_QUERIES = True

Кроме того, мы должны установить предел длительности выполнения запроса, чтобы все что выполняется дольше, считалось «медленным» (файл config.py):

# slow database query threshold (in seconds)
DATABASE_QUERY_TIMEOUT = 0.5

Для проверки необходимости отправить сигнал, мы добавим проверку после каждого запроса. При помощи Flask это просто, нужно лишь настроить обработчик after_request (файл app/views.py):

from flask.ext.sqlalchemy import get_debug_queries
from config import DATABASE_QUERY_TIMEOUT

@app.after_request
def after_request(response):
    for query in get_debug_queries():
        if query.duration >= DATABASE_QUERY_TIMEOUT:
            app.logger.warning("SLOW QUERY: %s\nParameters: %s\nDuration: %fs\nContext: %s\n" % (query.statement, query.parameters, query.duration, query.context))
    return response

Таким образом, в лог попадут все запросы, выполняющиеся дольше половины секунды. Информация в логе будет содержать SQL выражение, реальные использованные параметры, длительность и место в исходном коде, откуда был вызван этот запрос.

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

Заключение

Сегодня мы совершили ряд серьезных шагов, которые кроме того, весьма важны для любого надежного приложения. Код обновленного приложения вы можете скачать по адресу:

Скачать microblog-0.16.zip.

Читатели знакомые с GitHub, могут получить новую версию тут.

Создается ощущение, что мы неумолимо приближаемся к концу этой серии, т. к. у меня закончились идеи о чем еще можно поведать. В следующей, и вероятно, последней части мы рассмотрим процесс развертывания приложения как традиционного так и в облаке.
Если у вас есть мысли о том, какие проблемы мы упустили в этой серии статей, дайте мне знать ниже в комментариях.

Увидимся!

Miguel