Flask + SQLAlchemy + MariaDB Profilerstellung

Performance ist eine unendliche Geschichte. Zu einem bestimmten Zeitpunkt bemerkte ich, dass das Setzen der Homepage auf den Bildschirm etwa 370 Millisekunden dauerte, wenn man den Flask Entwicklungsserver mit angezeigten Debug-Meldungen benutzte. Das schien viel zu lang zu sein! Wie habe ich das bemerkt? Denn am Ende jeder Seite zeige ich die Zeit, die benötigt wird, um eine Seite zu generieren. Bitte beachten Sie, dass die folgenden Zeitangaben aus einer optimierteren Version des blog_reference-Modells stammen, bei der ich dem Namensfeld einen Index hinzugefügt habe.

Anzeige der Zeit für die Seitenerstellung

Dies wird mit den FlaskHandlern before_request und after_request gemessen.

    @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

Dies wird Ihre Seite ein wenig verlangsamen, denn nachdem die Seite gerendert wurde, wird die REQUEST_TIME mit einem Zeichenkettenersatz eingefügt.

SQLAlchemy mit ApacheBench Test- und Verbindungsausfällen

Ich mag ApacheBench, es ist einfach zu bedienen und gibt einen schnellen Überblick über Reaktionszeiten und Ausfälle. Bei einer Gleichzeitigkeit von 1 ist der Befehl:

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

Das Ergebnis:

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)

Wichtig: Überprüfen Sie immer, ob Failed Requests 0 sind! Überprüfen Sie auch die Dokumentlänge. Bei einer Gleichzeitigkeit von 10 erhielt ich Failed Requests:

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

SQLAlchemy hat eine Voreinstellung von 10 Verbindungen, also habe ich diese auf 50 mit einem Maximum von 60 erhöht:

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

Sie können die Anzahl der Verbindungen nicht ständig erhöhen. MariaDB/MySQL hat eine maximale Anzahl von Verbindungen, überprüfen Sie dies durch Eingabe in der Datenbankkonsole:

show variables like 'max_connections';

Für mich waren es 100. Der Parameter pool_pre_ping dient dazu, Datenbanktrennungen zu verhindern, siehe auch Links unten. Ich habe dies nach zufälligen Fehlern hinzugefügt. Wenn die pool_size auf 50 gesetzt ist, wurden die fehlgeschlagenen Anfragen nicht mehr angezeigt.

Auffinden der Ursache für die langsame Seitengenerierung

Ich konnte mir das SQLAlchemy Profiling ansehen, war aber mehr daran interessiert zu sehen, was in der View-Funktion passiert ist, die die Homepage anzeigt. Zuerst habe ich den Timercode am Anfang und Ende von Teilen der Homepageansicht hinzugefügt:

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

Zweitens habe ich den folgenden Code "Timer anzeigen" am Ende der Homepageansicht hinzugefügt:

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

Dieser Code druckt die Uhrzeit aller Teile. Beim Ausführen der Homepage der Website wurden die folgenden Debug-Informationen ausgegeben:

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

Dies zeigte, dass die Abfrage post_id2references nicht wie erwartet war. Als ich die Abfrage untersuchte, bemerkte ich, dass ich eine Abfragebedingung vergessen habe... :-( Nachdem ich diese behoben hatte, war die Leistung viel besser!

MariaDB / MySQL Abfrage-Profiling

Danach habe ich auch die Abfrage eingecheckt MariaDB. Das ist einfach zu tun. Aktivieren Sie mithilfe des Datenbankterminals zunächst die Profilerstellung:

SET profiling = 1;

Um den Cache der Datenbankmaschine zu leeren:

RESET QUERY CACHE

Um die Timings der Abfragen anzuzeigen, geben Sie Folgendes ein:

SHOW PROFILES

Dies gibt eine Liste wie folgt an:

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

Sie können sehen, dass nach einem RESET QUERY CACHE die Abfrage tatsächlich ausgeführt wird, die Zeitspanne reicht von 0,07 Millisekunden bis zu einigen 1,3 Millisekunden. Das bedeutet, dass MariaDB/MySQL Query Caching durchführt.

Da Abfragen im MariaDB Query Cache Hash-Speicher abgelegt sind, ist es nicht möglich zu sehen, welche Abfragen sich im Cache befinden. Es ist jedoch immer noch möglich, anhand des MariaDB Query Cache Status zu überprüfen, ob SQLAlchemy Abfragen tatsächlich gecachte Abfrageergebnisse verwenden:

SHOW STATUS LIKE 'Qcache%';

Die Ausgabe dieses Befehls ist:

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

Jetzt aktualisieren wir die Homepage und führen ApacheBench-n 100 -c 1 aus, um 100 Homepage-Anfragen zu generieren. Dann führen wir den Query Cache Statusbefehl erneut aus und vergleichen die Qcache_Hits und andere Daten:

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

Ich weiß, dass die Homepage 5 bis 6 Abfragen verwendet, die Anzahl der _Hits Qcacheist von 23366 auf 23870 = 504 gestiegen, was sehr vernünftig aussieht.

Nach ein paar Stunden habe ich das Gefühl, dass die SQL Alchemie viel (?) langsamer fragt als raw sql. Im Moment ist es gut genug. Ich glaube, es ist sinnlos, sich mit SQLAlchemy Dogpile zu beschäftigen, weil ich das Frontend über mehrere Server skalieren möchte.

Links / Impressum

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