Flask + SQLAlchemy + MariaDB Profilerstellung
Die Überprüfung des Timings ist eine weitere Möglichkeit, nach Fehlern zu suchen.
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
Mehr erfahren
Flask MariaDB Profiling SQLAlchemy
Neueste
- Ausblenden der Primärschlüssel der Datenbank UUID Ihrer Webanwendung
- Don't Repeat Yourself (DRY) mit Jinja2
- SQLAlchemy, PostgreSQL, maximale Anzahl von Zeilen pro user
- Anzeige der Werte in den dynamischen Filtern SQLAlchemy
- Sichere Datenübertragung mit Public Key Verschlüsselung und pyNaCl
- rqlite: eine hochverfügbare und distverteilte SQLite -Alternative
Meistgesehen
- Verwendung von Pythons pyOpenSSL zur Überprüfung von SSL-Zertifikaten, die von einem Host heruntergeladen wurden
- Verwendung von UUIDs anstelle von Integer Autoincrement Primary Keys mit SQLAlchemy und MariaDb
- Verbindung zu einem Dienst auf einem Docker -Host von einem Docker -Container aus
- PyInstaller und Cython verwenden, um eine ausführbare Python-Datei zu erstellen
- SQLAlchemy: Verwendung von Cascade Deletes zum Löschen verwandter Objekte
- Flask RESTful API Validierung von Anfrageparametern mit Marshmallow-Schemas