Мега-Підручник Flask, Частина 16: Налагодження, тестування і профілювання

Це шістнадцята стаття в серії, де я описую свій досвід написання веб-додатки на Python з використанням микрофреймворка Flask.

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

ЗмістЧастина 1: Привіт, Світ!
Частина 2: Шаблони
Частина 3: Форми
Частина 4: База даних
Частина 5: Вхід користувачів
Частина 6: Сторінка профілю і аватари
Частина 7: Unit-тестування
Частина 8: Передплатники, контакти і друзі
Частина 9: Пагинация
Частина 10: Повнотекстовий пошук
Частина 11: Підтримка e-mail
Частина 12: Реконструкція
Частина 13: Дата і час
Частина 14: I18n and L10n
Частина 15: Ajax
Частина 16: Налагодження, тестування і профілювання(дана стаття)
Частина 17: Розгортання на Linux (і навіть на Raspberry Pi!)
Частина 18: Розгортання на Heroku Cloud


Наше скромне додаток починає подавати ознаки готовності до релізу, так що настав час привести його в порядок настільки, наскільки це можливо. Не так давно один з читачів цього блогу (привіт, Джордж!) повідомив про дивну поведінку бази даних, яке ми сьогодні і спробуємо налагодити. Це має допомогти нам усвідомити, що незалежно від того, як уважно ми писали код і як часто його тестували, деякі помилки деколи залишаються непоміченими. На жаль, зазвичай їх виявляють саме кінцеві користувачі.

Замість того, щоб просто виправити цю помилку і чекати виявлення наступної, ми зробимо деякі превентивні заходи, щоб бути готовими до виявлення можливих помилок.

У першій частині цієї статті ми розглянемо налаштування і я покажу вам деякі прийоми і техніки, які я застосовую при налагодженні складних проблем.

Пізніше, ми побачимо як можна оцінити ефективність нашої стратегії тестування. Ми виміряємо, яку частину нашого коду покривають наші 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 app import
/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 app import

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 seconds 0.202

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.001 0.000 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 query database 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

Джерело: Хабрахабр

0 коментарів

Тільки зареєстровані та авторизовані користувачі можуть залишати коментарі.