jueves, 18 de agosto de 2016

Registrar consultas - ¿Cómo? - LOGGING QUERIES – HOW?

Esta entrada es una traducción de https://www.depesz.com/2010/07/22/logging-queries-how/
La traducción puede contener errores.
This entry is a translation of https://www.depesz.com/2010/07/22/logging-queries-how/
The translation may contain errors.

Una de las preguntas que saltan frecuentemente en el IRC es cómo ver las consultas que se ejecutan ahora en el servidor, y qué consultas lo fueron antes.
Teóricamente la respuesta a esto es simple - pg_stat_activity y log_min_duration_statement. O log_statment. ¿Cuál es la diferencia? Esto es exactamente por qué estoy escribiendo este post.
Lo primero de todo - para ver qué está ocurriendo en la base de datos justo ahora - tú puedes usar:

$ select * from pg_stat_activity ;
-[ RECORD 1 ]----+---------------------------------
datid            | 16398
datname          | depesz
procpid          | 28765
usesysid         | 16387
usename          | depesz
application_name | psql
client_addr      | [null]
client_port      | -1
backend_start    | 2010-07-21 15:44:08.017051+02
xact_start       | 2010-07-21 15:46:13.92332+02
query_start      | 2010-07-21 15:46:13.92332+02
waiting          | f
current_query    | select * from pg_stat_activity ;


La descripción exacta de qué es qué, tú la puedes encontrar en el bonito manual.

Hay un par de cosas importante, aunque:
current_query recorta las consultas largas a algún tamaño (no recuerdo cómo de grandes están ok, y es seguro que más grandes que las consultas usadas habitualmente, pero el límite existe)
A veces el campo "current_query" puede contener la cadena " - esto ocurre cuando tú estás consultando pg_stat_activvity desde no superusuario, y algunas consultas son ejecutadas por un usuario diferente que el usuario con el que tú has iniciado sesión.
Aparte de estos pequeños casos, esta es perfectamente la forma buena para ver el estado actual del sistema. Especialmente cuando añadiendo where para filtrar conexiones desocupadas. Mi consulta favorita para esta vista es:

SELECT
    now() - query_start as runtime,
    case when waiting then 'WAIT' else '' end as wait,
    current_query
FROM
    pg_stat_activity
WHERE
    current_query <> '<IDLE>'
ORDER BY 1 DESC

Esto muestra las consultas que están trabajando, no desocupadas, con su correspondiente tiempo de ejecución, ordenadas por el tiempo de ejecución mayor, con información si la consulta está esperando por algo.

Ahora, ¿qué hay sobre ver todas las consultas?
Bien, nosotros necesitamos usar una de las GUCS (N. del T.: GUCS es el acrónimo de Grand Unified Configuration Setting): log_statement o log_min_duration_statement.
Lo primero, veamos log_statement. Puede tener 4 valores: none, ddl, mod y all.
Estos significan:
none - ninguna sentencia será registrada (por los mecanismos de log_statement - pueden aún ser registradas por alguna otra cosa)
ddl - sentencias como create, alter y drop serán registradas - es decir, todo lo que cambia el esquema de la base de datos
mod - registra todas las consultas que "ddl" registraría, más las sentencias insert, update, delete, truncate y "copy from"
all – registra todas las consultas

Hay también algunas observaciones importantes:
si tú llamas a una función (select function()) y ella internamente hace algunas modificaciones - no será registrado con log_statement <> all
las consultas son registradas antes de que ellas sean realmente ejecutadas (lo cual es muy guay, aunque es importante observar la diferencia desde la forma descrita abajo)
Vamos a ver cómo se muestra (estos son registros csv, desplázate a la derecha para ver las partes importantes):

2010-07-21 21:54:16.135 CEST,"depesz","depesz",18160,"[local]",4c475062.46f0,3,"idle",2010-07-21 21:54:10 CEST,2/4,0,LOG,00000,"statement: create table x (i int4);",,,,,,,,,"psql"
2010-07-21 21:54:21.344 CEST,"depesz","depesz",18160,"[local]",4c475062.46f0,4,"idle",2010-07-21 21:54:10 CEST,2/5,0,LOG,00000,"statement: insert into x (i) values (123);",,,,,,,,,"psql"
2010-07-21 21:54:24.094 CEST,"depesz","depesz",18160,"[local]",4c475062.46f0,5,"idle",2010-07-21 21:54:10 CEST,2/6,0,LOG,00000,"statement: select * from x;",,,,,,,,,"psql"

Y finalmente, log_min_duration_statement. Esta es (en mi opinión) la más útil de todas ellas. Si yo la activo (es decir, establecida a valor >=0), y ejecuto las mismas consultas, en los registros yo puedo ver:

2010-07-21 22:03:27.690 CEST,"depesz","depesz",18723,"[local]",4c475288.4923,4,"CREATE TABLE",2010-07-21 22:03:20 CEST,2/0,0,LOG,00000,"duration: 45.924 ms  statement: create table x (i int4);",,,,,,,,,"psql"
2010-07-21 22:03:31.236 CEST,"depesz","depesz",18723,"[local]",4c475288.4923,5,"INSERT",2010-07-21 22:03:20 CEST,2/0,0,LOG,00000,"duration: 12.251 ms  statement: insert into x (i) values (123);",,,,,,,,,"psql"
2010-07-21 22:03:33.724 CEST,"depesz","depesz",18723,"[local]",4c475288.4923,6,"SELECT",2010-07-21 22:03:20 CEST,2/0,0,LOG,00000,"duration: 0.307 ms  statement: select * from x;",,,,,,,,,"psql"

Añadido importante: duration: ... elementos, que muestran cuanto tiempo tomó la sentencia.

Esto significa que las sentencias (y las duraciones) registradas por log_min_duration_statement pueden ser registradas sólo después de la ejecución. En la otra cara, log_min_duration te da la capacidad para registrar consultas que tomaron más allá de un tiempo definido - por ejemplo 5ms, o 15 segundos, así que tú puedes ajustarlo para registrar lo que es demasiado largo para tu aplicación.

Una nota sin embargo. Si tú activaras ambos log_statment (a algún valor) y log_min_duration_statement, y alguna consulta coincidiera en ambos casos, tú verás:

2010-07-21 22:12:58.423 CEST,"depesz","depesz",19197,"[local]",4c4754c6.4afd,5,"idle",2010-07-21 22:12:54 CEST,2/3,0,LOG,00000,"statement: create table x (i int4);",,,,,,,,,"psql"
2010-07-21 22:12:58.437 CEST,"depesz","depesz",19197,"[local]",4c4754c6.4afd,6,"CREATE TABLE",2010-07-21 22:12:54 CEST,2/0,0,LOG,00000,"duration: 14.017 ms",,,,,,,,,"psql"
2010-07-21 22:13:00.253 CEST,"depesz","depesz",19197,"[local]",4c4754c6.4afd,7,"idle",2010-07-21 22:12:54 CEST,2/4,0,LOG,00000,"statement: insert into x (i) values (123);",,,,,,,,,"psql"
2010-07-21 22:13:00.255 CEST,"depesz","depesz",19197,"[local]",4c4754c6.4afd,8,"INSERT",2010-07-21 22:12:54 CEST,2/0,0,LOG,00000,"duration: 2.140 ms",,,,,,,,,"psql"
2010-07-21 22:13:04.594 CEST,"depesz","depesz",19197,"[local]",4c4754c6.4afd,9,"SELECT",2010-07-21 22:12:54 CEST,2/0,0,LOG,00000,"duration: 0.285 ms  statement: select * from x;",,,,,,,,,"psql"

Esto es - si la consulta no será registrada por "log_statment" y sólo por log_min_duration_statement - será registradas como "duration:... ms statement: ...".
Aunque, si la consulta es registrada por los mecanismos de "log_statment" (como los create table o insert de arriba) - la línea registrada por log_min_duration_statment contendrá sólo la duración, y no la sentencia en sí misma. La razón es muy simple - no repetir la misma inforamción.
Esto desafortunadamente significa que si tú usas ambos log_statement y log_min_duration_statement - tú necesita alguna forma para unir estas líneas - con PID o session id. Cuando tú usas el registro normal stderr - tú necesitas añadir esta información de coincidencia a log_line_prefix, aunque cuando se usa csvlog - esto ya está allí.
Considerándolo todo - dominar estas configuraciones es la forma de comprender qué está ocurriendo con tu servidor. pg_stat_activity para comprobaciones rápidas de estado "aquí y ahora", y log_* para el análisis de largo plazo.


No hay comentarios:

Publicar un comentario