Avec le concours de Rémi Vidier.
| Disclaimer : Attention cet article utilise des outils de débogage qui sont intrusifs, et qui stoppent notamment l’exécution du processus qui est tracé, donc A NE PAS UTILISER EN PRODUCTION !!! |
Cette semaine nous devions déployer notre solution d’administration à distance AllDB sur une instance PostgreSQL 11.5 chez un de nos clients. La partie qui gère ce que l’on appelle en interne le ‘palmarès‘ des requêtes lentes se base sur l’extension pg_stat_statements, ce qui implique l’installation des contribs en prérequis.
Lorsque nous avons voulu créer l’extension après avoir ajouté les différents paramètres dans postgresql.conf:
(...) shared_preload_libraries = '/usr/pgsql-11/lib/pg_stat_statements.so' # (change requires restart) pg_stat_statements.max = 4000 pg_stat_statements.track = all pg_stat_statements.track_utility = on pg_stat_statements.save = on track_activity_query_size = 4096 (...)
…le CREATE EXTENSION est sorti en erreur:
postgres=# create extension pg_stat_statements ; ERROR: XX000: cache lookup failed for function 1 LOCATION: fmgr_info_cxt_security, fmgr.c:181
On s’est rapidement rendu compte qu’en fait le problème n’était pas lié à l’extension en elle-même, car toutes les extensions des contribs étaient concernées:
postgres=# create extension hstore ; ERROR: XX000: cache lookup failed for function 1 LOCATION: fmgr_info_cxt_security, fmgr.c:181 Time: 10.104 ms
OK, donc cette fonction fmgr_info_cxt_security() doit vérifier que l’oid d’une fonction non built-in qui lui est passée en argument se trouve bien dans pg_proc, sinon cette erreur est renvoyée:
fmgr_info_cxt_security(Oid functionId, FmgrInfo *finfo, MemoryContext mcxt,
bool ignore_security)
{ (...)
if ((fbp = fmgr_isbuiltin(functionId)) != NULL)
{
/*
* Fast path for builtin functions: don't bother consulting pg_proc
*/
finfo->fn_nargs = fbp->nargs;
finfo->fn_strict = fbp->strict;
finfo->fn_retset = fbp->retset;
finfo->fn_stats = TRACK_FUNC_ALL; /* ie, never track */
finfo->fn_addr = fbp->func;
finfo->fn_oid = functionId;
return;
}
/* Otherwise we need the pg_proc entry */
procedureTuple = SearchSysCache1(PROCOID, ObjectIdGetDatum(functionId));
if (!HeapTupleIsValid(procedureTuple))
elog(ERROR, "cache lookup failed for function %u", functionId);
procedureStruct = (Form_pg_proc) GETSTRUCT(procedureTuple);
(...)
Dans notre cas l’oid passé en argument est 1, ce qui effectivement n’existe pas dans pg_proc, d’où l’erreur.
Si on s’intéresse à la séquence lors de laquelle cet oid=1 est remonté, il nous faut attacher gdb à l’exécution du backend qui génère l’erreur. Il porte le PID 9599, on s’attache et on pose un bp sur errfinish pour stopper l’exécution sur notre erreur:
root@centos7 ~]# ps -fu postgres UID PID PPID C STIME TTY TIME CMD postgres 2821 2820 0 oct.07 pts/1 00:00:00 -bash postgres 3234 1 0 oct.07 ? 00:00:01 /usr/pgsql-11/bin/postmaster -D /var/lib/pgsql/11/data/ postgres 3236 3234 0 oct.07 ? 00:00:00 postgres: logger postgres 3512 3234 0 oct.07 ? 00:00:00 postgres: checkpointer postgres 3513 3234 0 oct.07 ? 00:00:01 postgres: background writer postgres 3514 3234 0 oct.07 ? 00:00:01 postgres: walwriter postgres 3515 3234 0 oct.07 ? 00:00:01 postgres: autovacuum launcher postgres 3516 3234 0 oct.07 ? 00:00:02 postgres: stats collector postgres 3517 3234 0 oct.07 ? 00:00:00 postgres: logical replication launcher postgres 9598 2821 0 14:44 pts/1 00:00:00 psql postgres 9599 3234 0 14:44 ? 00:00:00 postgres: postgres postgres [local] idle root@centos7 ~]# gdb -p 9599 GNU gdb (GDB) Red Hat Enterprise Linux 7.6.1-115.el7 Copyright (C) 2013 Free Software Foundation, Inc. License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html> This is free software: you are free to change and redistribute it. There is NO WARRANTY, to the extent permitted by law. Type "show copying" and "show warranty" for details. This GDB was configured as "x86_64-redhat-linux-gnu". For bug reporting instructions, please see: <http://www.gnu.org/software/gdb/bugs/>. Attaching to process 9599 Reading symbols from /usr/pgsql-11/bin/postgres...Reading symbols from /usr/lib/debug/usr/pgsql-11/bin/postgres.debug...done. done. (gdb) set pagination off (gdb) set logging file debug.log (gdb) set logging on Copying output to debug.log. (gdb) break errfinish Breakpoint 1 at 0x84e250: file elog.c, line 414. (gdb) cont Continuing.
Une fois le bp posé, dans le backend on force l’erreur à nouveau, et avec les symboles de PG11 installés (postgresql11-debuginfo.x86_64) on récupère la backtrace suivante :
Breakpoint 1, errfinish (dummy=dummy@entry=0) at elog.c:414 414 elog.c: Aucun fichier ou dossier de ce type. (gdb) ^CQuit (gdb) bt #0 errfinish (dummy=dummy@entry=0) at elog.c:414 #1 0x0000000000851fa8 in elog_finish (elevel=elevel@entry=20, fmt=fmt@entry=0x898698 "cache lookup failed for function %u") at elog.c:1376 #2 0x0000000000853fce in fmgr_info_cxt_security (functionId=1, functionId@entry=42165528, finfo=finfo@entry=0x7fff47c08f80, mcxt=<optimized out>, ignore_security=ignore_security@entry=false) at fmgr.c:181 #3 0x0000000000855532 in fmgr_info (finfo=0x7fff47c08f80, functionId=42165528) at fmgr.c:126 #4 OidFunctionCall1Coll (functionId=functionId@entry=1, collation=collation@entry=0, arg1=arg1@entry=24583) at fmgr.c:1411 #5 0x000000000053ba61 in ProcedureCreate (procedureName=<optimized out>, procNamespace=procNamespace@entry=2200, replace=<optimized out>, returnsSet=returnsSet@entry=false, returnType=returnType@entry=2278, proowner=10, languageObjectId=languageObjectId@entry=13, languageValidator=languageValidator@entry=1, prosrc=prosrc@entry=0x282b830 "pg_stat_statements_reset", probin=probin@entry=0x282b938 "$libdir/pg_stat_statements", prokind=prokind@entry=102 'f', security_definer=security_definer@entry=false, isLeakProof=isLeakProof@entry=false, isStrict=isStrict@entry=false, volatility=volatility@entry=118 'v', parallel=parallel@entry=115 's', parameterTypes=parameterTypes@entry=0x2836500, allParameterTypes=allParameterTypes@entry=0, parameterModes=parameterModes@entry=0, parameterNames=parameterNames@entry=0, parameterDefaults=parameterDefaults@entry=0x0, trftypes=trftypes@entry=0, proconfig=proconfig@entry=0, procost=procost@entry=1, prorows=prorows@entry=0) at pg_proc.c:703 #6 0x00000000005b0460 in CreateFunction (pstate=pstate@entry=0x2836350, stmt=stmt@entry=0x282d080) at functioncmds.c:1094 #7 0x000000000074a267 in ProcessUtilitySlow (pstate=pstate@entry=0x2836350, pstmt=pstmt@entry=0x282b2c8, queryString=queryString@entry=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=context@entry=PROCESS_UTILITY_QUERY, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x0, dest=0xcf13a0 <donothingDR>) at utility.c:1473 #8 0x0000000000749356 in standard_ProcessUtility (pstmt=pstmt@entry=0x282b2c8, queryString=queryString@entry=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=context@entry=PROCESS_UTILITY_QUERY, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, dest=dest@entry=0xcf13a0 <donothingDR>, completionTag=completionTag@entry=0x0) at utility.c:923 #9 0x00007fddf8482025 in pgss_ProcessUtility (pstmt=0x282b2c8, queryString=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"..., context=PROCESS_UTILITY_QUERY, params=0x0, queryEnv=0x0, dest=0xcf13a0 <donothingDR>, completionTag=0x0) at pg_stat_statements.c:1005 #10 0x00000000005a708c in execute_sql_string (filename=0x281d7f0 "/usr/pgsql-11/share/extension/pg_stat_statements--1.4.sql", sql=0x2831398 "/* contrib/pg_stat_statements/pg_stat_statements--1.4.sql */\n\n-- complain if script is sourced in psql, rather than via CREATE EXTENSION\n\n\n-- Register functions.\nCREATE FUNCTION pg_stat_statements_res"...) at extension.c:763 #11 execute_extension_script (extensionOid=extensionOid@entry=24582, control=control@entry=0x282d2b0, from_version=from_version@entry=0x0, version=version@entry=0x281d368 "1.4", requiredSchemas=requiredSchemas@entry=0x0, schemaName=schemaName@entry=0x282ac68 "public", schemaOid=<optimized out>) at extension.c:924 #12 0x00000000005a7b0d in CreateExtensionInternal (extensionName=0x275c0c8 "pg_stat_statements", schemaName=0x282ac68 "public", schemaName@entry=0x0, versionName=0x281d368 "1.4", versionName@entry=0x0, oldVersionName=oldVersionName@entry=0x0, cascade=<optimized out>, parents=parents@entry=0x0, is_create=is_create@entry=true) at extension.c:1536 #13 0x00000000005a8017 in CreateExtension (pstate=pstate@entry=0x2814940, stmt=stmt@entry=0x275c0f8) at extension.c:1725 #14 0x000000000074a617 in ProcessUtilitySlow (pstate=pstate@entry=0x2814940, pstmt=pstmt@entry=0x275c1a8, queryString=queryString@entry=0x275b6e0 "create extension pg_stat_statements ;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, completionTag=completionTag@entry=0x7fff47c0a8d0 "", dest=0x275c468) at utility.c:1392 #15 0x0000000000749356 in standard_ProcessUtility (pstmt=pstmt@entry=0x275c1a8, queryString=queryString@entry=0x275b6e0 "create extension pg_stat_statements ;", context=context@entry=PROCESS_UTILITY_TOPLEVEL, params=params@entry=0x0, queryEnv=queryEnv@entry=0x0, dest=dest@entry=0x275c468, completionTag=completionTag@entry=0x7fff47c0a8d0 "") at utility.c:923 #16 0x00007fddf8482025 in pgss_ProcessUtility (pstmt=0x275c1a8, queryString=0x275b6e0 "create extension pg_stat_statements ;", context=PROCESS_UTILITY_TOPLEVEL, params=0x0, queryEnv=0x0, dest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pg_stat_statements.c:1005 #17 0x0000000000746b96 in PortalRunUtility (portal=0x27c4860, pstmt=0x275c1a8, isTopLevel=<optimized out>, setHoldSnapshot=<optimized out>, dest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pquery.c:1178 #18 0x00000000007475e7 in PortalRunMulti (portal=portal@entry=0x27c4860, isTopLevel=isTopLevel@entry=true, setHoldSnapshot=setHoldSnapshot@entry=false, dest=dest@entry=0x275c468, altdest=altdest@entry=0x275c468, completionTag=completionTag@entry=0x7fff47c0a8d0 "") at pquery.c:1331 #19 0x00000000007481d5 in PortalRun (portal=<optimized out>, count=9223372036854775807, isTopLevel=<optimized out>, run_once=<optimized out>, dest=0x275c468, altdest=0x275c468, completionTag=0x7fff47c0a8d0 "") at pquery.c:799 #20 0x0000000000744287 in exec_simple_query (query_string=<optimized out>) at postgres.c:1145 #21 0x0000000000745552 in PostgresMain (argc=<optimized out>, argv=<optimized out>, dbname=<optimized out>, username=<optimized out>) at postgres.c:4182 #22 0x0000000000480571 in BackendRun (port=0x277ad80) at postmaster.c:4358 #23 BackendStartup (port=0x277ad80) at postmaster.c:4030 #24 ServerLoop () at postmaster.c:1707 #25 0x00000000006d8639 in PostmasterMain (argc=argc@entry=3, argv=argv@entry=0x2756280) at postmaster.c:1380 #26 0x00000000004813cf in main (argc=3, argv=0x2756280) at main.c:228 (gdb) detach Detaching from program: /usr/pgsql-11/bin/postgres, process 9599
On retrouve bien fmgr_info_cxt_security() sur le haut de la pile. Regardons de près la séquence ProcedureCreate() -> OidFunctionCall1Coll(), dans le code l’appel se passe de la manière suivante (pg_proc.c):
ObjectAddress
ProcedureCreate(const char *procedureName,
(...)
OidFunctionCall1(languageValidator, ObjectIdGetDatum(retval));
(...)
OidFunctionCall1() est un alias pointant sur OidFunctionCall1Coll() dans fmgr.h:
(...)
#define OidFunctionCall1(functionId, arg1) \
OidFunctionCall1Coll(functionId, InvalidOid, arg1)
(...)
et dans OidFunctionCall1Coll() dans fmgr.c, l’appel à fmgr_info() qui déclenche l’exception finale:
Datum
OidFunctionCall1Coll(Oid functionId, Oid collation, Datum arg1)
{
FmgrInfo flinfo;
fmgr_info(functionId, &flinfo);
return FunctionCall1Coll(&flinfo, collation, arg1);
}
Donc l’argument Oid functionId qui est égal à 1 et fait planter notre CREATE EXTENSION est une référence au départ à languageValidator, qui est une colonne de pg_language.
Dans les faits dans le catalogue système, la valeur de lanvalidator pour le langage ‘c’ qui est le langage de nos extensions, est à 1:
postgres=# select * from pg_language ; lanname | lanowner | lanispl | lanpltrusted | lanplcallfoid | laninline | lanvalidator | lanacl ----------+----------+---------+--------------+---------------+-----------+--------------+-------- internal | 10 | f | f | 0 | 0 | 2246 | NULL sql | 10 | f | t | 0 | 0 | 2248 | NULL plpgsql | 10 | t | t | 13868 | 13869 | 13870 | NULL c | 10 | f | f | 0 | 0 | 1 | NULL (4 rows) Time: 5.114 ms
D’après la doc, le lanvalidator doit pointer vers la fonction de validation du langage lanname. Dans le cas du ‘c’, ce devrait être fmgr_c_validator:
postgres=# select oid, proname from pg_proc where proname='fmgr_c_validator' ; oid | proname ------+------------------ 2247 | fmgr_c_validator (1 ligne)
Au final si on update la colonne dans pg_language, le CREATE EXTENSION va fonctionner de nouveau:
postgres=# update pg_language set lanvalidator=2247 where lanname='c' ; UPDATE 1 postgres=# create extension pg_stat_statements ; CREATE EXTENSION
Mais la question reste de savoir pourquoi la valeur se retrouve à 1 en premier lieu. On s’est également rendu compte que lanvalidator était aussi à 1 dans template1 et le problème se propage à chaque nouvelle création de base. Il n’y a qu’un CREATE DATABASE … TEMPLATE template0 qui ne posera pas le problème.
Est-ce un problème au moment de l’initdb qui modifie cette valeur ? Toujours est-il que le problème n’est pas nouveau, plusieurs threads sur le forum général le mentionnent, notamment ici : https://www.postgresql.org/message-id/b7082510-b2a1-acbe-dc79-d4492eccacc4%40gmail.com
Affaire à suivre, bonne journée à toutes / tous, à+
David.
Continuez votre lecture sur le blog :
- AWS RDS : les extensions PostgreSQL (Emmanuel RAMI) [AWSPostgreSQL]
- Nouveautés pg_stat_statements avec PostgreSQL 15 (David Baffaleuf) [PostgreSQL]
- Requêtes consommatrices sous PostgreSQL (épisode 1) (David Baffaleuf) [PostgreSQL]
- PostgreSQL : planifier une tâche avec pg_cron (Emmanuel RAMI) [Non classéPostgreSQL]
- PGDay Nantes 2021 session sur pg_stat_statements (David Baffaleuf) [PostgreSQL]