Log de SQLs y de SQLs lentas en MySQL y PostgreSQL

Escrito por el .
planeta-codigo programacion
Comentarios

MySQL
PotgreSQL

La información generalmente y en la mayoría de los casos es de las cosas más importantes de una aplicación. Para guardarla se suelen emplear bases de datos relacionales por sus propiedades de consistencia, transaccionalidad y propiedades ACID aunque más recientemente se ha popularizado otros sistemas no SQL como Redis o Mongo para diferentes casos de uso.

Dos de las bases de datos relacionales más usadas son PostgreSQL y MySQL. El rendimiento de una aplicación en buena parte depende del acceso a la base de datos relacional. Por ello conviene saber cuáles, cuántas consultas se están lanzando al servidor y el tiempo tardan, además suele ser útil monitorizar especialmente las consultas que consideramos lentas al superar cierto umbral de tiempo. Con la información de que consultas, cuantas y las lentas se toman tomar acciones asegurar el buen funcionamiento del sistema, para mejorar el rendimiento de la aplicación optimizando las consultas lentas u optimizando la aplicación para que realice menos consultas al servidor de base de datos si es que hay un problema de 1+N típico en las librerías ORM como Hibernate.

Que una SQL tarde mucho en ejecutarse y consuma muchos recursos del sistema en CPU o memoria potencialmente es un problema grave que posiblemente afecte a funcionalidades importantes de una aplicación, será más acusado si hay un volumen relevante de usuarios usando el sistema simultáneamente. Las consecuencias van desde la caída del servicio hasta tiempos de respuesta elevados.

MySQL

Para activar la generación de logs y de SQLs lentas en MySQL hay que añadir la siguiente configuración a MySQL. Las sentencias lentas que superan cierto tiempo de ejecución son emitidas al archivo mysql-slow.log, según la configuración indicada aquellas que superen 10 segundos. Dado que el ejemplo de consulta es sencilla y la base de datos no es grande la sentencia no aparece en el log de SQLs lentas.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
version: '3'

services:
  mysql:
    image: mysql:8
    volumes:
      - ./configuration/:/etc/mysql/conf.d
      - ./scripts/:/scripts/
      - mysql-data:/var/lib/mysql
      - mysql-log:/var/log/mysql
    environment:
      MYSQL_ROOT_PASSWORD: root
      MYSQL_DATABASE: blogbitix
    entrypoint: ''
    command: bash -c "chown -R mysql:mysql /var/log/mysql && exec /entrypoint.sh mysqld"

volumes:
  mysql-data:
  mysql-log:
1
2
3
4
5
6
7
[mysqld]
general_log=1
general_log_file=/var/log/mysql/mysql.log

slow_query_log=1
long_query_time=10
slow_query_log_file=/var/log/mysql/mysql-slow.log
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
CREATE TABLE IF NOT EXISTS Persons (
    person_id int NOT NULL AUTO_INCREMENT PRIMARY KEY,
    last_name varchar(255),
    first_name varchar(255)
);

INSERT INTO Persons (last_name, first_name) values
    ('Last name 1', 'First name 1'),
    ('Last name 2', 'First name 2'),
    ('Last name 3', 'First name 3'),
    ('Last name 4', 'First name 4'),
    ('Last name 5', 'First name 5'),
    ('Last name 6', 'First name 6'),
    ('Last name 7', 'First name 7'),
    ('Last name 8', 'First name 8'),
    ('Last name 9', 'First name 9'),
    ('Last name 10', 'First name 10');
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
$ docker-compose up
$ docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES
8d7d4953cb39        mysql:latest        "bash -c chown…"         10 seconds ago      Up 15 seconds       3306/tcp            msqsql_msqsql_1
$ docker exec -it 8d7d4953cb39 bash
root@8d7d4953cb39:/# mysql -uroot -proot blogbitix < /scripts/database.sql
root@8d7d4953cb39:/# mysql -uroot -proot
mysql> show databases;
+--------------------+
| Database           |
+--------------------+
| blogbitix          |
| information_schema |
| mysql              |
| performance_schema |
| sys                |
+--------------------+
5 rows in set (0.00 sec)

mysql> use blogbitix;
Database changed

mysql> select * from Persons;
+-----------+--------------+---------------+
| person_id | last_name    | first_name    |
+-----------+--------------+---------------+
|         1 | Last name 1  | First name 1  |
|         2 | Last name 2  | First name 2  |
|         3 | Last name 3  | First name 3  |
|         4 | Last name 4  | First name 4  |
|         5 | Last name 5  | First name 5  |
|         6 | Last name 6  | First name 6  |
|         7 | Last name 7  | First name 7  |
|         8 | Last name 8  | First name 8  |
|         9 | Last name 9  | First name 9  |
|        10 | Last name 10 | First name 10 |
+-----------+--------------+---------------+
10 rows in set (0.00 sec)

root@8d7d4953cb39:/# tail -20 /var/log/mysql/mysql.log 
2019-02-04T13:26:48.414716Z     19 Connect    root@localhost on  using Socket
2019-02-04T13:26:48.414911Z     19 Query  select @@version_comment limit 1
2019-02-04T13:26:53.629645Z     19 Query  show databases
2019-02-04T13:26:58.847307Z     19 Query  SELECT DATABASE()
2019-02-04T13:26:58.847709Z     19 Init DB    blogbitix
2019-02-04T13:26:58.851495Z     19 Query  show databases
2019-02-04T13:26:58.853238Z     19 Query  show tables
2019-02-04T13:26:58.858211Z     19 Field List Persons 
2019-02-04T13:27:03.463610Z     19 Query  show tables
2019-02-04T13:28:20.522918Z     19 Query  select * from Persons
2019-02-04T13:28:35.275031Z     19 Quit   

PostgreSQL

En el caso de PostgeSQL el archivo de log se ubica según el valor de la propiedad log_directory y log_filename. Se activa el log con la propiedad logging_collector. Las sentencias con errores también se incluyen en el mismo archivo. Para obtener los tiempos que tardan las sentencias en ejecutarse hay que establecer un umbral en milisegundos para que la sentencia sea incluida en el log, con el valor 0 se incluyen todas las sentencias en el log en la propiedad log_min_duration_statement.

 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
version: '3'

services:
  postgres:
    image: postgres:11
    volumes:
      - ./configuration/postgresql.conf:/etc/postgresql/postgresql.conf
      - ./scripts/:/scripts/
      - postgres-data:/var/lib/postgresql/data
      - postgres-log:/var/log/postgres
    environment:
      POSTGRES_PASSWORD: postgres
      POSTGRES_DB: blogbitix
    command: postgres -c config_file=/etc/postgresql/postgresql.conf

volumes:
  postgres-data:
  postgres-log:
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
...

#------------------------------------------------------------------------------
# REPORTING AND LOGGING
#------------------------------------------------------------------------------

# - Where to Log -

log_destination = 'stderr'      # Valid values are combinations of
                    # stderr, csvlog, syslog, and eventlog,
                    # depending on platform.  csvlog
                    # requires logging_collector to be on.

# This is used when logging to stderr:
logging_collector = on      # Enable capturing of stderr and csvlog
                    # into log files. Required to be on for
                    # csvlogs.
                    # (change requires restart)

# These are only used if logging_collector is on:
log_directory = 'log'           # directory where log files are written,
                    # can be absolute or relative to PGDATA
log_filename = 'postgresql-%Y-%m-%d_%H%M%S.log' # log file name pattern,
                    # can include strftime() escapes
...

# - When to Log -

...

log_min_duration_statement = 0  # -1 is disabled, 0 logs all statements
                    # and their durations, > 0 logs only
                    # statements running at least this number
                    # of milliseconds


# - What to Log -

...
log_statement = 'all'           # none, ddl, mod, all
...
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
CREATE TABLE IF NOT EXISTS Persons (
    person_id SERIAL PRIMARY KEY,
    last_name varchar(255),
    first_name varchar(255)
);

INSERT INTO Persons (last_name, first_name) values
    ('Last name 1', 'First name 1'),
    ('Last name 2', 'First name 2'),
    ('Last name 3', 'First name 3'),
    ('Last name 4', 'First name 4'),
    ('Last name 5', 'First name 5'),
    ('Last name 6', 'First name 6'),
    ('Last name 7', 'First name 7'),
    ('Last name 8', 'First name 8'),
    ('Last name 9', 'First name 9'),
    ('Last name 10', 'First name 10');
 1
 2
 3
 4
 5
 6
 7
 8
 9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
$ docker-compose up
$ docker ps
CONTAINER ID        IMAGE               COMMAND                  CREATED             STATUS              PORTS               NAMES
448b3ab5684d        postgres:latest     "docker-entrypoint.s…"   6 seconds ago       Up 5 seconds        5432/tcp            postgresql_postgres_1
$ docker exec -it 448b3ab5684d bash
root@448b3ab5684d:/# psql -U postgres -d blogbitix -f /scripts/database.sql
CREATE TABLE
INSERT 0 10
root@448b3ab5684d:/# psql -U postgres
psql (11.1 (Debian 11.1-3.pgdg90+1))
Type "help" for help.

postgres=# \l
                                 List of databases
   Name    |  Owner   | Encoding |  Collate   |   Ctype    |   Access privileges   
-----------+----------+----------+------------+------------+-----------------------
 blogbitix | postgres | UTF8     | en_US.utf8 | en_US.utf8 | 
 postgres  | postgres | UTF8     | en_US.utf8 | en_US.utf8 | 
 template0 | postgres | UTF8     | en_US.utf8 | en_US.utf8 | =c/postgres          +
           |          |          |            |            | postgres=CTc/postgres
 template1 | postgres | UTF8     | en_US.utf8 | en_US.utf8 | =c/postgres          +
           |          |          |            |            | postgres=CTc/postgres
(4 rows)

postgres=# \connect blogbitix
You are now connected to database "blogbitix" as user "postgres".

blogbitix=# select * from Persons;
 person_id |  last_name   |  first_name   
-----------+--------------+---------------
         1 | Last name 1  | First name 1
         2 | Last name 2  | First name 2
         3 | Last name 3  | First name 3
         4 | Last name 4  | First name 4
         5 | Last name 5  | First name 5
         6 | Last name 6  | First name 6
         7 | Last name 7  | First name 7
         8 | Last name 8  | First name 8
         9 | Last name 9  | First name 9
        10 | Last name 10 | First name 10
(10 rows)

root@005d4f42cf44:/# tail /var/lib/postgresql/data/log/postgresql-2019-02-04_151958.log 
2019-02-04 15:19:58.980 GMT [25] LOG:  database system was shut down at 2019-02-04 15:19:57 GMT
2019-02-04 15:19:58.990 GMT [1] LOG:  database system is ready to accept connections
2019-02-04 15:20:13.526 GMT [46] LOG:  statement: select * from Persons;
2019-02-04 15:20:13.527 GMT [46] LOG:  duration: 1.555 ms

Como los archivos de log de sentencias ejecutadas potencialmente serán grandes hay que rotarlos y monitorizar o limitar su tamaño. En PostgreSQL usando las directivas de configuración, log_rotation_age o log_rotation_size, en MySQL posiblemente con el comando logrotate.