Flask + SQLAlchemy + MariaDB профилирование
Проверка времени является еще одним способом поиска ошибок
Выступление - это бесконечная история. В какой-то момент я заметил, что размещение главной страницы на экране занимает около 370 миллисекунд, используя сервер Flask разработки с отладочными сообщениями. Это казалось слишком длинным! Как я это заметил? Потому что внизу каждой страницы я показываю время, необходимое для создания страницы. Обратите внимание, что приведенные ниже тайминги взяты из более оптимизированной версии модели blog_reference, где я добавил индекс в поле имени.
Показать время генерации страницы
Это измеряется с помощью обработчиков Flask's до_запроса и после_запроса.
@app.before_request
def before_request():
app.logger.debug(fname + ': before_request')
# start time of request
g.start = time.time()
...
@app.after_request
def after_request(response):
if ((response.response) and (200 <= response.status_code < 300) and (response.content_type.startswith('text/html'))):
diff_milliseconds = int( (time.time() - g.start) * 1000 )
response.set_data(response.get_data().replace(b'47', bytes(str(diff_milliseconds), 'utf-8')))
return response
Это немного замедлит работу вашей страницы, так как после отрисовки страницы REQUEST_TIME вставляется с помощью замены строки.
SQLAlchemy с помощью теста ApacheBench и сбоев в соединениях.
Мне нравится ApacheBench, он прост в использовании и дает быстрое представление о времени отклика и сбоях. Для совпадения 1, команда есть:
ab -n 100 -c 1 http://127.0.0.1:8000/
Результат:
This is ApacheBench, Version 2.3 <$Revision: 1807734 $>
Copyright 1996 Adam Twiss, Zeus Technology Ltd, http://www.zeustech.net/
Licensed to The Apache Software Foundation, http://www.apache.org/
Benchmarking 127.0.0.1 (be patient)...
..done
Server Software: Werkzeug/0.14.1
Server Hostname: 127.0.0.1
Server Port: 8000
Document Path: /
Document Length: 25160 bytes
Concurrency Level: 1
Time taken for tests: 6.897 seconds
Complete requests: 100
Failed requests: 0
Total transferred: 2539800 bytes
HTML transferred: 2516000 bytes
Requests per second: 14.50 [#/sec] (mean)
Time per request: 68.972 [ms] (mean)
Time per request: 68.972 [ms] (mean, across all concurrent requests)
Transfer rate: 359.61 [Kbytes/sec] received
Connection Times (ms)
min mean[+/-sd] median max
Connect: 0 0 0.0 0 0
Processing: 64 69 4.1 68 81
Waiting: 64 69 4.0 68 81
Total: 64 69 4.1 68 81
Percentage of the requests served within a certain time (ms)
50% 68
66% 70
75% 71
80% 73
90% 76
95% 78
98% 80
99% 81
100% 81 (longest request)
Важно: всегда проверяйте, что Failed requests is 0! Также проверьте длину документа. Одновременно с 10, я получил неудачные запросы:
ab -n 100 -c 10 http://127.0.0.1:8000/
SQLAlchemy имеет 10 соединений по умолчанию, поэтому я увеличил их до 50 с максимум 60:
engine = create_engine(os.getenv('SQLALCHEMY_DATABASE_URI'), pool_size=50, max_overflow=60, pool_pre_ping=True, echo=True)
Вы не можете продолжать увеличивать количество подключений. MariaDB/MySQL имеет максимальное количество подключений, проверьте его, введя в консоль базы данных:
show variables like 'max_connections';
Для меня это было 100. Параметр pool_pre_ping используется для предотвращения отключения базы данных, см. также ссылки ниже. Я добавил это после случайных неудач. Когда размер pool_size установлен на 50, неудачные запросы больше не отображаются.
Определение причины медленной генерации страниц
Я мог бы просмотреть SQLAlchemy профиль, но мне было больше интересно посмотреть, что происходит в функции просмотра, отображающей главную страницу. Во-первых, я добавил код таймера в начало и конец функции просмотра домашней страницы:
query_timers = []
...
query_timers.append( {'query': 'post_id2authors', 'time_start': datetime.datetime.now() } )
post_id2authors=get_blog_post_authors(post_ids),
query_timers.append( {'query': 'post_id2authors', 'time_end': datetime.datetime.now() } )
...
query_timers.append( {'query': 'post_id2tags', 'time_start': datetime.datetime.now() } )
post_id2tags=get_blog_post_tags(post_ids),
query_timers.append( {'query': 'post_id2tags', 'time_end': datetime.datetime.now() } )
...
Во-вторых, я добавил следующий код 'show Timers' в конце функции просмотра домашней страницы:
# timer: get queries
query_timers_queries = []
query_timer_query2time_start_time_ends = {}
for query_timer in query_timers:
query = query_timer['query']
if query not in query_timer_query2time_start_time_ends:
query_timer_query2time_start_time_ends[query] = { 'time_start': 0, 'time_end': 0 }
if 'time_start' in query_timer:
query_timer_query2time_start_time_ends[query]['time_start'] = query_timer['time_start']
if 'time_end' in query_timer:
query_timer_query2time_start_time_ends[query]['time_end'] = query_timer['time_end']
# timer: loop through queries
current_app.logger.debug(fname + ': len(query_timer_query2time_start_time_ends) = {}'.format(len(query_timer_query2time_start_time_ends)))
current_app.logger.debug(fname + ': query_timer_query2time_start_time_ends = {}'.format(query_timer_query2time_start_time_ends))
for query in query_timer_query2time_start_time_ends:
if query_timer_query2time_start_time_ends[query]['time_start'] != 0 and query_timer_query2time_start_time_ends[query]['time_end']:
delta = query_timer_query2time_start_time_ends[query]['time_end'] - query_timer_query2time_start_time_ends[query]['time_start']
current_app.logger.debug(fname + ': query = {}, delta = {}'.format(query, delta))
Данный код выводит время всех деталей. Запуск домашней страницы сайта дал следующую отладочную информацию:
peterspython_container_web | [2019-07-29 18:33:17,932] DEBUG in views: homepage: query = select_posts, delta = 0:00:00.009654
peterspython_container_web | [2019-07-29 18:33:17,932] DEBUG in views: homepage: query = post_id2authors, delta = 0:00:00.007860
peterspython_container_web | [2019-07-29 18:33:17,933] DEBUG in views: homepage: query = post_id2categories, delta = 0:00:00.011795
peterspython_container_web | [2019-07-29 18:33:17,933] DEBUG in views: homepage: query = post_id2tags, delta = 0:00:00.009891
peterspython_container_web | [2019-07-29 18:33:17,933] DEBUG in views: homepage: query = post_id2references, delta = 0:00:00.042603
peterspython_container_web | [2019-07-29 18:33:17,933] DEBUG in views: homepage: query = render_template, delta = 0:00:00.019005
Это показало, что запрос post_id2references оказался не таким, как ожидалось. Проверяяя запрос, я заметил, что забыл условие запроса ... :-( После исправления этого, производительность была намного лучше!
MariaDB / Профилирование MySQL запросов
После этого я также проверил запрос в MariaDB. Это легко сделать. Используя терминал базы данных, сначала включите профилирование:
SET profiling = 1;
Для очистки кэша механизма базы данных:
RESET QUERY CACHE
Для отображения таймингов типа запросов:
SHOW PROFILES
Это дает список вроде
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| Query_ID | Duration | Query |
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 1 | 0.00007394 | SELECT blog_post.id AS blog_post_id, blog_reference.id AS blog_reference_id, blog_reference.site_id AS blog_reference_site_id, blog_reference.deleted AS blog_reference_deleted, blog_reference.deleted_on AS blog_reference_deleted_on, blog_reference.status AS blog_reference_status, blog_reference.crea |
| 2 | 0.00005384 | RESET QUERY CACHE |
| 3 | 0.00133299 | SELECT blog_post.id AS blog_post_id, blog_reference.id AS blog_reference_id, blog_reference.site_id AS blog_reference_site_id, blog_reference.deleted AS blog_reference_deleted, blog_reference.deleted_on AS blog_reference_deleted_on, blog_reference.status AS blog_reference_status, blog_reference.crea |
| 4 | 0.00006290 | RESET QUERY CACHE |
| 5 | 0.00154395 | SELECT blog_post.id AS blog_post_id, blog_reference.id AS blog_reference_id, blog_reference.site_id AS blog_reference_site_id, blog_reference.deleted AS blog_reference_deleted, blog_reference.deleted_on AS blog_reference_deleted_on, blog_reference.status AS blog_reference_status, blog_reference.crea |
| 6 | 0.00175268 | describe blog_reference |
| 7 | 0.00013651 | RESET QUERY CACHE |
| 8 | 0.00223707 | SELECT blog_post.id AS blog_post_id, blog_reference.id AS blog_reference_id, blog_reference.site_id AS blog_reference_site_id, blog_reference.deleted AS blog_reference_deleted, blog_reference.deleted_on AS blog_reference_deleted_on, blog_reference.status AS blog_reference_status, blog_reference.crea |
| 9 | 0.00008391 | SELECT blog_post.id AS blog_post_id, blog_reference.id AS blog_reference_id, blog_reference.site_id AS blog_reference_site_id, blog_reference.deleted AS blog_reference_deleted, blog_reference.deleted_on AS blog_reference_deleted_on, blog_reference.status AS blog_reference_status, blog_reference.crea |
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
9 rows in set (0.00 sec)
Вы видите, что после выполнения запроса RESET QUERY CACHE действительно выполняется, время идет от 0,07 миллисекунд до 1,3 миллисекунд. Это означает, что MariaDB/MySQL выполняет кэширование запросов.
Потому что запросы хэшируются в кэше MariaDB Query Cache , нет способа увидеть, какие запросы находятся в кэше. Но все же можно проверить, действительно ли в SQLAlchemy запросах используются кэшированные результаты запроса, изучив MariaDB Query Cache статус:
SHOW STATUS LIKE 'Qcache%';
Вывод этой команды таков:
+-------------------------+----------+
| Variable_name | Value |
+-------------------------+----------+
| Qcache_free_blocks | 7 |
| Qcache_free_memory | 66685576 |
| Qcache_hits | 23370 |
| Qcache_inserts | 2873 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 29673 |
| Qcache_queries_in_cache | 62 |
| Qcache_total_blocks | 152 |
+-------------------------+----------+
Теперь мы обновляем домашнюю страницу и запускаем ApacheBench, -n 100 -c 1, для генерации 100 запросов на домашней странице. Затем мы снова выполним команду Query Cache status и сравним Qcache_hits и другие данные:
+-------------------------+----------+
| Variable_name | Value |
+-------------------------+----------+
| Qcache_free_blocks | 7 |
| Qcache_free_memory | 66685576 |
| Qcache_hits | 23870 |
| Qcache_inserts | 2873 |
| Qcache_lowmem_prunes | 0 |
| Qcache_not_cached | 29873 |
| Qcache_queries_in_cache | 62 |
| Qcache_total_blocks | 152 |
+-------------------------+----------+
Я знаю, что на главной странице используется от 5 до 6 запросов, количество _hits Qcacheувеличилось с 23366 до 23870 = 504, что выглядит очень разумно.
Через несколько часов я чувствую, что SQL Алхимия запрашивает намного (?) медленнее, чем сырая площадь. На данный момент это достаточно хорошо. Я считаю, что не стоит заглядывать в собачьи SQLAlchemy запасы, потому что я могу захотеть масштабировать фронтенд на несколько серверов.
Ссылки / кредиты
Calculate execution time for every page in Python's Flask
https://stackoverflow.com/questions/12273889/calculate-execution-time-for-every-page-in-pythons-flask
Clear MySQL query cache without restarting server
https://stackoverflow.com/questions/5231678/clear-mysql-query-cache-without-restarting-server
Connection Pooling
https://docs.sqlalchemy.org/en/13/core/pooling.html
Dealing with Disconnects
https://docs.sqlalchemy.org/en/13/core/pooling.html?highlight=disconnects#dealing-with-disconnects
How can I profile a SQLAlchemy powered application?
https://docs.sqlalchemy.org/en/13/faq/performance.html
How to increase MySQL connections(max_connections)?
https://stackoverflow.com/questions/22297773/how-to-increase-mysql-connectionsmax-connections
Query Cache
https://mariadb.com/kb/en/library/query-cache/
SHOW PROFILE Syntax
https://dev.mysql.com/doc/refman/5.5/en/show-profile.html
Подробнее
Flask MariaDB Profiling SQLAlchemy
Недавний
- Скрытие первичных ключей базы данных UUID вашего веб-приложения
- Don't Repeat Yourself (DRY) с Jinja2
- SQLAlchemy, PostgreSQL, максимальное количество строк для user
- Показать значения в динамических фильтрах SQLAlchemy
- Безопасная передача данных с помощью шифрования Public Key и pyNaCl
- rqlite: альтернатива dist с высокой степенью готовности и SQLite
Большинство просмотренных
- Используя Python pyOpenSSL для проверки SSL-сертификатов, загруженных с хоста
- Использование UUID вместо Integer Autoincrement Primary Keys с SQLAlchemy и MariaDb
- Использование PyInstaller и Cython для создания исполняемого файла Python
- Подключение к службе на хосте Docker из контейнера Docker
- SQLAlchemy: Использование Cascade Deletes для удаления связанных объектов
- Flask Удовлетворительный запрос API проверка параметров запроса с помощью схем Маршмэллоу