Flask + SQLAlchemy + MariaDB profilage

La performance est une histoire sans fin. A un certain moment, j'ai remarqué que mettre la page d'accueil à l'écran prenait environ 370 millisecondes en utilisant le serveur de Flask développement avec les messages de débogage affichés. Ça m'a paru beaucoup trop long ! Comment l'ai-je remarqué ? Parce qu'en bas de chaque page je montre le temps qu'il faut pour générer une page. Veuillez noter que les horaires ci-dessous proviennent d'une version plus optimisée du modèle blog_reference où j'ai ajouté un index au champ nom.

Affichage du temps de génération des pages

Ceci est mesuré à l'aide Flaskdes gestionnaires's before_request et after_request'.

    @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

Cela ralentira un peu votre page, car une fois que la page a été rendue, le REQUEST_TIME est inséré en utilisant un remplacement de chaîne.

SQLAlchemy avec des échecs de ApacheBench test et de connexion

J'aime ApacheBench, il est facile à utiliser et donne une indication rapide des temps de réponse et des pannes. Pour une concomitance de 1, la commande est :

ab -n 100 -c 1 http://127.0.0.1:8000/

Le résultat :

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)

Important : vérifiez toujours que le nombre de demandes échouées est 0 ! Vérifiez également la longueur du document. Avec une concomitance de 10, j'ai des demandes échouées :

ab -n 100 -c 10 http://127.0.0.1:8000/

SQLAlchemy a une valeur par défaut de 10 connexions, donc j'ai augmenté ce chiffre à 50 avec un maximum de 60 :

engine = create_engine(os.getenv('SQLALCHEMY_DATABASE_URI'), pool_size=50, max_overflow=60, pool_pre_ping=True, echo=True)

Vous ne pouvez pas continuer à augmenter le nombre de connexions. MariaDB/MySQL a un nombre maximum de connexions, vérifiez le en tapant dans la console de base de données :

show variables like 'max_connections';

Pour moi, c'était 100. Le paramètre pool_pre_ping est utilisé pour empêcher les déconnexions de la base de données, voir aussi les liens ci-dessous. J'ai ajouté ceci après des échecs aléatoires. Avec le pool_size réglé à 50, les requêtes échouées n'apparaissaient plus.

Localiser la cause de la lenteur de la génération des pages

J'ai pu me pencher sur le SQLAlchemy profilage, mais j'étais plus intéressé à voir ce qui se passait dans la fonction de vue montrant la page d'accueil. Tout d'abord, j'ai ajouté le code de la minuterie au début et à la fin de certaines parties de la fonction d'affichage de la page d'accueil :

    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() } )
    ...

Deuxièmement, j'ai ajouté le code suivant'show timers' code à la fin de la fonction d'affichage de la page d'accueil :

    # 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))

Ce code imprime l'heure de toutes les pièces. L'exécution de la page d'accueil du site Web a donné les informations de débogage suivantes :

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

Ceci a montré que la requête post_id2references n'était pas comme prévu. En inspectant la requête, j'ai remarqué que j'avais oublié une condition de requête... :-( Après l'avoir réparée, les performances étaient bien meilleures !

MariaDB / profilage de MySQL requête

Ensuite, j'ai également vérifié la requête dans MariaDB. C'est facile à faire. A l'aide du terminal de base de données, activez d'abord le profilage :

SET profiling = 1;

Pour effacer le cache du moteur de base de données :

RESET QUERY CACHE

Pour afficher les temporisations du type de requête :

SHOW PROFILES

Cela donne une liste comme :

+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 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)

Vous pouvez voir qu'après une RESET QUERY CACHE la requête est réellement exécutée, le temps passe de 0,07 millisecondes à environ 1,3 millisecondes. Cela signifie que MariaDB/MySQL effectue la mise en cache des requêtes.

Parce que les requêtes sont hachées dans le cache, MariaDB Query Cache il n'y a aucun moyen de voir quelles requêtes sont dans le cache. Mais il est toujours possible de vérifier si SQLAlchemy les requêtes utilisent réellement les résultats des requêtes en cache en examinant l' MariaDB Query Cache état :

SHOW STATUS LIKE 'Qcache%';

La sortie de cette commande est :

+-------------------------+----------+
| 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      |
+-------------------------+----------+

Maintenant, nous rafraîchissons la page d'accueil et lançons ApacheBench, -n 100 -c 1, pour générer 100 requêtes sur la page d'accueil. Ensuite, nous exécutons à nouveau la commande Query Cache status et comparons les Qcache_hits et autres données :

+-------------------------+----------+
| 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      |
+-------------------------+----------+

Je sais que la page d'accueil utilise 5 à 6 requêtes, le nombre de _visites Qcacheest passé de 23366 à 23870 = 504, ce qui semble très raisonnable.

Après quelques heures, j'ai l'impression que l' SQL alchimie interroge beaucoup ( ?) beaucoup plus lent que sql brut. Pour l'instant, c'est suffisant. Je crois qu'il n'est pas utile de regarder dans SQLAlchemy dogpile parce que je peux vouloir mettre à l'échelle le frontend sur plusieurs serveurs.

Liens / crédits

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