angle-uparrow-clockwisearrow-counterclockwisearrow-down-uparrow-leftatcalendarcard-listchatcheckenvelopefolderhouseinfo-circlepencilpeoplepersonperson-fillperson-plusphoneplusquestion-circlesearchtagtrashx

Flask + SQLAlchemy + MariaDB elaboración de perfiles

Comprobar la sincronización es otra forma de buscar errores

29 julio 2019
post main image
Original photo unsplash.com/@elmeng.

La actuación es una historia interminable. En un momento dado me di cuenta de que poner la página de inicio en la pantalla me llevó unos 370 milisegundos usar el servidor de Flask desarrollo con los mensajes de depuración mostrados. Parecía demasiado tiempo! ¿Cómo me di cuenta de esto? Porque al final de cada página muestro el tiempo que se tarda en generar una página. Por favor, tenga en cuenta que los siguientes tiempos son de una versión más optimizada del modelo blog_reference donde agregué un índice al campo de nombre.

Mostrando el tiempo de generación de páginas

Esto se mide usando los handlers 's before_request y 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

Esto ralentizará un poco su página, porque después de que la página haya sido renderizada el REQUEST_TIME se inserta usando una cadena de texto reemplazada.

SQLAlchemy con fallos de ApacheBench prueba y conexión

Me gusta ApacheBench, es fácil de usar y da una rápida indicación de los tiempos de respuesta y fallos. Para una concurrencia de 1, el comando es:

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

El resultado:

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)

Importante: compruebe siempre que las peticiones fallidas sean 0! Compruebe también la longitud del documento. Con una concurrencia de 10, tengo peticiones fallidas:

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

SQLAlchemy tiene un valor por defecto de 10 conexiones, así que lo aumenté a 50 con un máximo de 60:

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

No puede seguir aumentando el número de conexiones. MariaDB/MySQL tiene un número máximo de conexiones, compruébelo escribiendo en la consola de la base de datos:

show variables like 'max_connections';

Para mí eran 100. El parámetro pool_pre_ping se utiliza para evitar desconexiones de la base de datos; véase también los enlaces siguientes. Añadí esto después de fracasos aleatorios. Con el pool_size configurado en 50, las peticiones fallidas ya no se mostraban.

Localización de la causa de la lentitud en la generación de la página

Podía mirar en la creación de SQLAlchemy perfiles, pero estaba más interesado en ver lo que ocurría en la función de vista que mostraba la página de inicio. Primero, añadí el código del temporizador al principio y al final de algunas partes de la función de vista de página de inicio:

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

En segundo lugar, he añadido el siguiente código 'show timers' al final de la función de vista de página de inicio:

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

Este código imprime la hora de todas las piezas. Al ejecutar la página de inicio del sitio web se obtiene la siguiente información de depuración:

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

Esto mostró que la consulta post_id2references no era la esperada. Inspeccionando la consulta me di cuenta de que se me olvidó una condición de consulta... :-( Después de arreglar esto, el rendimiento fue mucho mejor!

MariaDB / perfil de MySQL consulta

Después de eso, también verifiqué la consulta en MariaDB. Esto es fácil de hacer. Usando la terminal de base de datos, primero habilite la creación de perfiles:

SET profiling = 1;

Para borrar la caché del motor de base de datos:

RESET QUERY CACHE

Para mostrar los tiempos de las consultas escriba:

SHOW PROFILES

Esto da una lista como:

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

Puede ver que después de un RESET QUERY CACHE la consulta se ejecuta realmente, el tiempo pasa de 0,07 milisegundos a unos 1,3 milisegundos. Esto significa que MariaDB/MySQL realiza el cacheo de consultas.

Debido a que las consultas se han convertido en hash en la MariaDB Query Cache caché, no hay forma de ver qué consultas están en la caché. Sin embargo, aún es posible comprobar si las SQLAlchemy consultas utilizan realmente los resultados de las consultas en caché examinando el MariaDB Query Cache estado:

SHOW STATUS LIKE 'Qcache%';

La salida de este comando es:

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

Ahora refrescamos la página de inicio y ejecutamos ApacheBench, -n 100 -c 1, para generar 100 peticiones de página de inicio. Luego volvemos a ejecutar el comando de Query Cache estado y comparamos los Qcache_hits y otros datos:

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

Sé que la página de inicio utiliza de 5 a 6 consultas, el número de _hits Qcacheha aumentado de 23366 a 23870 = 504, lo que parece muy razonable.

Después de unas horas siento que la SQL Alquimia consulta mucho (?) más lento que el sql en bruto. Por el momento es suficiente. Creo que no sirve de nada mirar en la pila de SQLAlchemy perros porque puede que quiera escalar la interfaz a través de múltiples servidores.

Enlaces / créditos

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

Deje un comentario

Comente de forma anónima o inicie sesión para comentar.

Comentarios

Deje una respuesta.

Responda de forma anónima o inicie sesión para responder.