Flask + SQLAlchemy + MariaDB profilering
Het controleren van de timing is een andere manier om naar fouten te zoeken.
Prestatie is een nooit eindigend verhaal. Op een gegeven moment viel het me op dat het op het scherm zetten van de startpagina zo'n 370 milliseconden in beslag nam door gebruik te maken van de Flask ontwikkelingsserver met getoonde debugberichten. Dat leek veel te lang! Hoe heb ik dit opgemerkt? Omdat ik onderaan elke pagina laat zien hoeveel tijd het kost om een pagina te genereren. Let op: de onderstaande tijden zijn van een meer geoptimaliseerde versie van het blog_referentiemodel, waar ik een index aan het naamveld heb toegevoegd.
Het tonen van pagina generatie tijd
Dit wordt gemeten met behulp van Flask's voor_verzoek en na_verzoekers.
@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
Dit zal uw pagina een beetje vertragen, want nadat de pagina is weergegeven wordt de REQUEST_TIME met behulp van een string vervangen.
SQLAlchemy met ApacheBench test- en aansluitingsfouten
Ik vind het leuk ApacheBench, het is gemakkelijk te gebruiken en geeft snel een indicatie van de responstijden en storingen. Voor een gelijktijdigheid van 1 is het commando:
ab -n 100 -c 1 http://127.0.0.1:8000/
Het resultaat:
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)
Belangrijk: controleer altijd of Failed requests 0 is! Controleer ook de documentlengte. Met een gelijktijdigheid van 10, kreeg ik mislukte verzoeken:
ab -n 100 -c 10 http://127.0.0.1:8000/
SQLAlchemy heeft standaard 10 aansluitingen, dus ik heb dit verhoogd naar 50 met een maximum van 60 aansluitingen:
engine = create_engine(os.getenv('SQLALCHEMY_DATABASE_URI'), pool_size=50, max_overflow=60, pool_pre_ping=True, echo=True)
U kunt het aantal verbindingen niet steeds verder uitbreiden. MariaDB/MySQL heeft een maximum aantal verbindingen, controleer dit door de databaseconsole in te typen:
show variables like 'max_connections';
Voor mij was dit 100. De pool_pre_ping parameter wordt gebruikt om het verbreken van de database te voorkomen, zie ook de links hieronder. Ik heb dit toegevoegd na willekeurige mislukkingen. Met de pool_size ingesteld op 50, verschenen de Failed requests niet meer.
De oorzaak van de langzame paginageneratie opsporen
Ik kon kijken naar de SQLAlchemy profilering, maar was meer geïnteresseerd in wat er gebeurde in de weergavefunctie die de startpagina toont. Eerst heb ik de timercode toegevoegd aan het begin en einde van delen van de home page view functie:
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() } )
...
Ten tweede heb ik de volgende 'show timers' code toegevoegd aan het einde van de home page view functie:
# 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))
Deze code geeft de tijd van alle onderdelen weer. Het beheren van de homepage van de website gaf de volgende debuginformatie:
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
Dit toonde aan dat de post_id2references query niet was zoals verwacht. Toen ik de vraag inspecteerde merkte ik dat ik een query conditie vergat.... :-( Na het repareren van deze was de prestatie veel beter!
MariaDB / MySQL query-profilering
Daarna heb ik de vraag ook gecontroleerd in MariaDB. Dit is gemakkelijk te doen. Met behulp van de databaseterminal moet eerst de profilering mogelijk worden gemaakt:
SET profiling = 1;
Om de cache van de database-engine leeg te maken:
RESET QUERY CACHE
Om de tijden van het type zoekopdracht weer te geven:
SHOW PROFILES
Dit geeft een lijst zoals:
+----------+------------+--------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+
| 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)
Je kunt zien dat na een RESET QUERY CACHE de query echt wordt uitgevoerd, de tijd gaat van 0,07 milliseconden tot ongeveer 1,3 milliseconden. Dit betekent dat MariaDB/MySQL query caching uitvoert.
Omdat de query's in de MariaDB Query Cache cache zijn ingewreven, is het niet mogelijk om te zien welke query's er in de cache zitten. Maar het is nog steeds mogelijk om te controleren of SQLAlchemy queries daadwerkelijk gebruik maken van de resultaten van query's in het cachegeheugen door de MariaDB Query Cache status te onderzoeken:
SHOW STATUS LIKE 'Qcache%';
De uitvoer van dit commando is:
+-------------------------+----------+
| 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 |
+-------------------------+----------+
Nu vernieuwen we de home page en draaien ApacheBench, -n 100 -c 1, om 100 home page requests te genereren. Daarna voeren we het Query Cache statuscommando opnieuw uit en vergelijken we de Qcache_hits en andere gegevens:
+-------------------------+----------+
| 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 |
+-------------------------+----------+
Ik weet dat de homepage 5 tot 6 queries gebruikt. Het aantal _hits Qcacheis gestegen van 23366 naar 23870 = 504, wat erg redelijk lijkt.
Na een paar uur heb ik het gevoel dat de SQL Alchemy veel langzamer vraagt dan ruwe sql. Voorlopig is het goed genoeg. Ik denk dat het geen zin heeft om in SQLAlchemy dogpile te kijken omdat ik de frontend over meerdere servers wil schalen.
Links / credits
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
Lees meer
Flask MariaDB Profiling SQLAlchemy
Recent
- Database UUID primaire sleutels van je webapplicatie verbergen
- Don't Repeat Yourself (DRY) met Jinja2
- SQLAlchemy, PostgreSQL, maximum aantal rijen per user
- Toon de waarden in SQLAlchemy dynamische filters
- Veilige gegevensoverdracht met Public Key versleuteling en pyNaCl
- rqlite: een alternatief voor SQLite met hoge beschikbaarheid en distributed
Meest bekeken
- Met behulp van Python's pyOpenSSL om SSL-certificaten die van een host zijn gedownload te controleren
- Gebruik van UUIDs in plaats van Integer Autoincrement Primary Keys met SQLAlchemy en MariaDb
- Maak verbinding met een dienst op een Docker host vanaf een Docker container
- PyInstaller en Cython gebruiken om een Python executable te maken
- SQLAlchemy: Gebruik van Cascade Deletes om verwante objecten te verwijderen
- Flask RESTful API verzoekparametervalidatie met Marshmallow-schema's