Requêtes consommatrices sous PostgreSQL (épisode 1)

Mardi, mai 24, 2016
By David Baffaleuf in PostgreSQL (dbaffaleuf@capdata-osmozium.com) [70 article(s)]

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
(...)
A partir de là, on retrouve la librairie :
$ 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:

Dans le prochain épisode, on récupère les plans d’exécution avec l’extension de 2ndQuadrant, pg_stat_plans.
A+

Continuez votre lecture sur le blog :




Cliquer pour partager cet article sur Viadeo
Cliquer sur "CAPTURER" pour sauvegarder cet article dans Evernote Clip to Evernote

Tags:

Leave a Reply