Lors de l’écriture de l’agent AllDB pour PostgreSQL je me suis pas mal frotté avec les solutions de remontée de requêtes lentes donc je me suis dit qu’un petit post sur le sujet ne ferait pas de mal.
En gros il y a 2 façons de récupérer les requêtes ‘consommatrices’ sous PostgreSQL, via un log ou via une extension.
Via le log général:
C’est un peu le même fonctionnement que sous MySQL où on va indiquer une durée de requête minimale et toutes les requêtes au-dessus de ce seuil seront loggées dans le fichier de log de l’instance PG.
On active ce principe via un paramètre instance dans postgresl.conf:
– log_min_duration_statement = <valeur en ms>
0 pour tout récupérer, -1 par défaut pour ne rien récupérer, ou tout autre valeur en millisecondes.
(postgres@[local]:5432) [postgres] > \x Expanded display is on. (postgres@[local]:5432) [postgres] > select * from pg_settings where name = 'log_min_duration_statement' ; -[ RECORD 1 ]---------------------------------------------------------------------- name | log_min_duration_statement setting | -1 unit | ms category | Reporting and Logging / When to Log short_desc | Sets the minimum execution time above which statements will be logged. extra_desc | Zero prints all queries. -1 turns this feature off. context | superuser vartype | integer source | default min_val | -1 max_val | 2147483647 enumvals | NULL boot_val | -1 reset_val | -1 sourcefile | NULL sourceline | NULL
Par exemple:
(postgres@[local]:5432) [FRCITY] > SET log_min_duration_statement = 30 ; SET Time: 0.901 ms (postgres@[local]:5432) [FRCITY] > select * from towns ; (...) (36684 rows) Time: 56.471 ms
Et dans le fichier de log (sous $PGDATA/pg_log) par défaut:
(...) 2016-05-18 11:15:52 CEST LOG: duration: 56.297 ms statement: select * from towns ; (...)
La différence de temps vient du fait que dans le log n’est reporté que le temps passé dans le postmaster, alors que le temps remonté par psql est logiquement le temps serveur + client.
On peut continuer de jouer en modifiant log_line_prefix pour enrichir le contenu de la ligne qui est loggée. Par contre il faut modifier dans le fichier postgresql.conf et reloader via pg_ctl reload ou pg_reload_conf():
log_line_prefix = '%t [%p]: [%l-1] db=%d,user=%u,app=%a,client=%h '
Résultat dans le fichier:
16-05-18 11:26:49 CEST [22945]: [3-1] db=FRCITY,user=postgres,app=psql.bin,client=[local] LOG: duration: 62.788 ms statement: select * from towns ;
C’est un peu mieux mais quand on vient d’Oracle ou SQL Server, on reste un peu sur sa faim (pas de nombre de blocs logiques / physiques lus, de nombre de lignes, de temps CPU vs elapsed, etc…)
Via pg_stat_statements:
Pour trouver une alternative, on devra se tourner vers des extensions.
Pg_stat_statements (pgss pour faire court) est une extension native qui est livrée sous la forme d’une librairie dynamique (pg_stat_statements.so). Elle logge en fonction de la version différents aspects opérationnels de l’exécution des requêtes, comme le nombre de lignes, le nombre d’appels, le nombre de blocs lus par type, etc… Ces données sont cumulées sur la durée de vie de l’instance, et peuvent être même réinitialisées à la main via une fonction pg_stat_statements_reset().
Si elle ne se trouve pas dans $(pg_config –libdir)/postgresql , il faut installer les contribs. Par exemple en 9.4:
$ yum search postgresql | grep contrib Repo rhel-7-server-rpms forced skip_if_unavailable=True due to: /etc/pki/entitlement/1652329269877919303-key.pem postgresql-contrib.x86_64 : Extension modules distributed with PostgreSQL postgresql94-contrib.x86_64 : Contributed source and binaries distributed with $ yum install postgresql94-contrib.x86_64 (...)
$ ls -lrat /opt/PostgreSQL/9.4/lib/postgresql/pg_stat_statements.so -rwxr-xr-x. 1 postgres postgres 26298 Oct 6 2015 /opt/PostgreSQL/9.4/lib/postgresql/pg_stat_statements.so
Plusieurs lignes à ajouter dans postgresql.conf:
#----------------------------------------------------------- shared_preload_libraries = '$libdir/pg_stat_statements.so' (...) #----------------------------------------------------------- custom_variable_classes = 'pg_stat_statements' pg_stat_statements.max = 4000 pg_stat_statements.track = all pg_stat_statements.track_utility = on pg_stat_statements.save = on
Sachant que depuis la 9.2 custom_variable_classes n’est plus nécessaire. Shared_preload_libraries impose un restart de l’instance. Concernant les paramètres:
- .max : indique le nombre de lignes contenues dans la table. Lorsque le nombre de lignes atteint cette valeur, chaque exécution provoque une expiration des lignes les plus anciennes, on verra que ce n’est pas sans conséquences un peu plus loin.
- .track : [ top | all | none ], top permet de tracer les requêtes ad-hoc, all permet de tout tracer y compris les requêtes contenues dans le corps des fonctions, et none désactive.
- .utility : [ on | off ] permet de tracer aussi les commandes hors SELECT / UPDATE / INSERT / DELETE.
- .save : permet d’assurer la persistance du contenu de la pseudo-table pg_stat_statements après un restart de l’instance.
Une fois l’instance redémarrée on peut créer l’extension (dans la base postgres):
(postgres@[local]:5432) [postgres] > create extension pg_stat_statements ; CREATE EXTENSION Time: 273.357 ms
Définition en 9.1 :
(postgres@[local]:5432) [postgres] > \d pg_stat_statements
View "public.pg_stat_statements"
Column | Type | Modifiers
---------------------+------------------+-----------
userid | oid |
dbid | oid |
query | text |
calls | bigint |
total_time | double precision |
rows | bigint |
shared_blks_hit | bigint |
shared_blks_read | bigint |
shared_blks_written | bigint |
local_blks_hit | bigint |
local_blks_read | bigint |
local_blks_written | bigint |
temp_blks_read | bigint |
temp_blks_written | bigint |Définition en 9.4:
(postgres@[local]:5432) [postgres] > \d pg_stat_statements
View "public.pg_stat_statements"
Column | Type | Modifiers
---------------------+------------------+-----------
userid | oid |
dbid | oid |
queryid | bigint |
query | text |
calls | bigint |
total_time | double precision |
rows | bigint |
shared_blks_hit | bigint |
shared_blks_read | bigint |
shared_blks_dirtied | bigint |
shared_blks_written | bigint |
local_blks_hit | bigint |
local_blks_read | bigint |
local_blks_dirtied | bigint |
local_blks_written | bigint |
temp_blks_read | bigint |
temp_blks_written | bigint |
blk_read_time | double precision |
blk_write_time | double precision |Je vous renvoie à la doc en ligne pour la description de chaque colonne. A noter la savoureuse modification faite en 9.2 où les unités de total_time passent de seconde à milliseconde. Quelques colonnes apparaissent en 9.2 comme les colonnes dirtied et les blk_read_time et blk_write_time, qui seront renseignées si track_io_timing est à on.
En 9.5, 4 nouvelles colonnes font leur apparition, permettant de mieux évaluer les variations en temps d’exécution de chaque requête:
min_time double precision Minimum time spent in the statement, in milliseconds max_time double precision Maximum time spent in the statement, in milliseconds mean_time double precision Mean time spent in the statement, in milliseconds stddev_time double precision Population standard deviation of time spent in the statement, in milliseconds
Quant à la 9.6, il ne semble pas y avoir eu de modif de faite, le fichier de contrôle est toujours en 1.3 entre la 9.5.3 et la 9.6b1.
Un autre fait intéressant, jusqu’en 9.1 inclue, il n’y a pas encore de notion de queryid. La même requête avec des littéraux différents sera donc loggée plusieurs fois.
En 9.2, Tom Lane intègre la notion de requête représentative, où les littéraux sont remplacés par des ‘?’, ce qui permet d’agréger sur un même identifiant, dans la même veine que le sql_id chez Oracle ou le query_hash chez SQL Server. Avant la 9.2, on peut s’inspirer du code de Jehan-Guillaume de Rorthais (qui s’inspire de pgbadger au passage) pour normaliser:
CREATE OR REPLACE FUNCTION Qnorm(IN TEXT, OUT TEXT) AS
$body$
SELECT
regexp_replace(
regexp_replace(
regexp_replace(
regexp_replace(
regexp_replace(
regexp_replace(
regexp_replace(
regexp_replace(
/*****************************************************************
On remplace par un espace simple ' ' :
- les espaces supplémentaires
- les caractères new line
- les tabulations
*/
lower($1),'\s+',' ','g'
),
/*****************************************************************
On remplace ce qui se trouve en quotes par 'XXX'
*/
$$\\'$$,'','g'
),
$$'[^']*'$$, $$'XXX'$$, 'g'
),
$$''('')+$$, $$''$$, 'g'
),
/*****************************************************************
On remplace la chaîne '=NULL' ou '= NULL' par '=O'
*/
'=\s*NULL', '=0', 'g'
),
/*****************************************************************
On remplace les nombres par 9999
*/
'([^a-z_$-])-?([0-9]+)', '\1'||'9999', 'g'
),
/*****************************************************************
On remplace les nombres en hexa par 0xFFFFFFFF
*/
'([^a-z_$-])0x[0-9a-f]{1,10}', '\1'||'0xFFFFFFFF', 'g'
),
/*****************************************************************
On remplace les litéraux passés dans les clauses IN par IN (BLA,BLA,BLA)
*/
-- Remove IN values
'in\s*\([''0x,\s]*\)', 'IN (BLA,BLA,BLA)', 'g'
) ;
$body$
LANGUAGE SQL;Et du même coup calculer un md5 de la forme normalisée pour arriver à un queryid:
postgres@[local]:5432) [postgres] > \x Expanded display is on. (postgres@[local]:5432) [postgres] > select query, Qnorm(query), md5(Qnorm(query)) as "queryId" from pg_stat_statements limit 1 ; -[ RECORD 1 ]---+-------------------------------------------------------------------------- query | UPDATE pgbench_accounts SET abalance = abalance + 4875 WHERE aid = 67347; normalize_query | update pgbench_accounts set abalance = abalance + 9999 where aid = 9999; queryId | 11ff394897d09d426e19dbb68c586bb2
A partir de là, on peut commencer à remonter les requêtes lentes :
SELECT DB.datname as DatabaseId ,md5(alldb.normalize_query(ST.query)) as QueryId ,alldb.normalize_query(ST.query) as NQuery ,sum(total_time) as totaltime ,sum(rows) as totalrows ,sum(calls) as totalcalls ,sum(ST.shared_blks_hit) as totalshhits ,sum(ST.shared_blks_read) as totalshread ,sum(ST.shared_blks_written) as totalshwritten FROM pg_stat_statements ST JOIN pg_database DB on DB.oid = ST.dbid GROUP BY 1,2,3 having sum(ST.shared_blks_hit) > 1500 order by 4 desc LIMIT 10 ;
Evidemment toute cette cuisine n’est plus nécessaire en version 9.2 et supérieure dans la mesure où un queryId est immédiatement disponible et que les données sont déjà agrégées… Mais bon, côté Cap Data l’agent ALlDB pour PostgreSQL supporte toujours la 9.1, donc on fonctionne en calculant un queryid de facto.
Caveats…
Ce qu’il faut toutefois garder à l’esprit quand on décide de se construire un outil basé sur cette interface, c’est qu’il n’y a pas de collecteur, la collecte est réalisée à chaque appel à pg_stat_statements. Il faudra donc à intervalle régulier effectuer un sample du contenu de pgss et le copier dans des tables de travail sur lesquelles on pourra ensuite calculer des différences.
Autre détail qui a son importance, c’est que tout le code est exécuté à chaque fois, y compris la routine d’éviction lorsque pg_stat_statements.max est atteint. Ce qui veut dire que dans le cas soit d’une valeur trop faible du .max soit d’une activité élevée sur l’instance, une exécution manuelle de pgss entre 2 snapshots automatisés par exemple peut évincer des lignes qui ne seront pas vues dans le second snapshot. La solution de fortune étant soit de mettre une valeur suffisamment élevée pour .max, soit de faire des clichés rapprochés, soit les deux.
Dernier problème rencontré avec cette extension, c’est qu’il est possible de réinitialiser les compteurs via pg_stat_statements_reset(). Mais contraitement à d’autres vues de stats comme pg_stat_database ou pg_stat_bgwriter qui intègrent un timestamp de reset, ce n’est pas le cas ici et c’est franchement dommage, car entre deux samples il faut tester le signe de la différence entre (val2 – val1) pour savoir si une réinitialisation est survenue. C’est probablement la raison pour laquelle la plupart des outils type pgbadger ne se basent que sur log_min_duration_statement et le log.
A suivre:
Continuez votre lecture sur le blog :
- Nouveautés pg_stat_statements avec PostgreSQL 15 (David Baffaleuf) [PostgreSQL]
- AWS RDS : les extensions PostgreSQL (Emmanuel RAMI) [AWSPostgreSQL]
- DMV et problème de tri (David Baffaleuf) [SQL Server]
- PostgreSQL : planifier une tâche avec pg_cron (Emmanuel RAMI) [Non classéPostgreSQL]
- ERROR: XX000: cache lookup failed for function 1 avec CREATE EXTENSION (David Baffaleuf) [PostgreSQL]