Flask + SQLAlchemy + MariaDB profilering

Het controleren van de timing is een andere manier om naar fouten te zoeken.

29 juli 2019

In Flask, MariaDB, Profiling, SQLAlchemy

Original photo unsplash.com/@elmeng.

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

Flask + SQLAlchemy + MariaDB profilering

Het tonen van pagina generatie tijd

SQLAlchemy met ApacheBench test- en aansluitingsfouten

De oorzaak van de langzame paginageneratie opsporen

MariaDB / MySQL query-profilering

Links / credits

Lees meer

Flask MariaDB Profiling SQLAlchemy

Laat een reactie achter

Opmerkingen

Laat een antwoord achter

Recent

Meest bekeken

Tags