Flask + SQLAlchemy + MariaDB профилирование

Проверка времени является еще одним способом поиска ошибок

29 июля 2019

Original photo unsplash.com/@elmeng.

Выступление - это бесконечная история. В какой-то момент я заметил, что размещение главной страницы на экране занимает около 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

Оставить комментарий

Комментируйте анонимно или войдите в систему, чтобы прокомментировать.

Flask + SQLAlchemy + MariaDB профилирование

Показать время генерации страницы

SQLAlchemy с помощью теста ApacheBench и сбоев в соединениях.

Определение причины медленной генерации страниц

MariaDB / Профилирование MySQL запросов

Ссылки / кредиты

Подробнее

Flask MariaDB Profiling SQLAlchemy

Оставить комментарий

Комментарии

Оставьте ответ

Недавний

Большинство просмотренных

Теги