Vous n'êtes pas identifié(e).
Pages : 1
Bonjour tout le monde,
Nous travaillons sous CenOS 5.4 avec un moteur PostgreSQL 9.3.2.
J'analyse les temps des requêtes sur notre serveur avec PgBadger 5.0.
J'ai la procédure stockée suivante qui répond en 9547ms.
CREATE FUNCTION histogroupe2(character varying, character varying, character varying, character varying, character, character, character) RETURNS refcursor
LANGUAGE plpgsql
AS $_$
DECLARE
RHisto REFCURSOR;
cJDeb CHAR(8);
cJFin CHAR(8);
cHFin CHAR(6);
BEGIN
OPEN RHisto FOR
SELECT FOO.CJour,geo.Centi2Heure(SUM(FOO.CTemps)) AS CTemps,FOO.CIdLig,FOO.CLibLig,FOO.CIdPlan,FOO.CLibPlan,FOO.CIdFonc,FOO.CLibFonc,FOO.CIdOpe,FOO.CLibOpe,FOO.COfSec,FOO.CLibOf
FROM (
SELECT PTG.jour AS CJour,
PTG.heure_deb AS CHeureDeb,
PTG.heure_fin AS CHeureFin,
PTG.Temps AS CTemps,
A.id_ligne AS CIdLig,
A.lib_ligne AS CLibLig,
A.id_plan AS CIdPlan,
A.lib_plan AS CLibPlan,
A.id_fonction AS CIdFonc,
A.lib_fonction AS CLibFonc,
A.id_operation AS CIdOpe,
A.lib_operation AS CLibOpe,
PTG.ofs_cpt AS COfSec,
OO.libelle AS CLibOf
FROM GEO.Ptg_pers PTG
LEFT OUTER JOIN GEO.O_f OO ON (OO.id_cgu='TOTO' AND PTG.ofs_cpt=OO.of_sec)
LEFT OUTER JOIN GEO.Vue_activite_geo A ON (A.id_cgu='TOTO' AND (A.id_site='TITI' OR A.id_site='*') AND PTG.id_ligne=A.id_ligne AND PTG.id_plan=A.id_plan AND PTG.id_fonction=A.id_fonction AND PTG.id_operation=A.id_operation)
WHERE PTG.jour>=TO_DATE('20140303','YYYYMMDD') AND PTG.jour<=TO_DATE('20140303','YYYYMMDD')
AND PTG.id_cgu='TOTO' AND PTG.id_site_pointage='TITI' AND PTG.id_perso='00135'
) AS FOO
WHERE FOO.CIdOpe != '0000'
GROUP BY FOO.CJour,FOO.CIdLig,FOO.CLibLig,FOO.CIdPlan,FOO.CLibPlan,FOO.CIdFonc,FOO.CLibFonc,FOO.CIdOpe,FOO.CLibOpe,FOO.COfSec,FOO.CLibOf
ORDER BY FOO.CJour DESC;
RETURN RHisto;
END;
$_$;
ALTER FUNCTION igeo_pack.histogroupe2(character varying, character varying, character varying, character varying, character, character, character) OWNER TO postgres;
Lorsque j'exécute la requête contenue dans la procédure stockée (de SELECT FOO à CJour DESC;), la réponse est retournée en 112ms.
Pour exécuter la procédure stockées, je fais :
begin;
select igeo_pack.histogroupe2('TOTO', 'TITI', 'FRTI', '00135','20140303','20140303','0000');
fetch all in "<unnamed portal 1>";
end;
Est-il possible de faire un EXPLAIN ANALYZE sur une procédure stockée ?
D'où peut venir cette différence de temps ?
Merci pour vos réponses.
Hors ligne
Est-il possible de faire un EXPLAIN ANALYZE sur une procédure stockée ?
Non, sauf en utilisant le module auto_explain.
D'où peut venir cette différence de temps ?
Vous ne comparez pas la même chose : exécution d'une requête via un curseur et sans curseur. Essayez de comparer la fonction avec une transaction qui ouvre un curseur (DECLARE curseur CURSOR FOR requete;).
Guillaume.
Hors ligne
Bonjour Guillaume,
Ok, je vais regarder l'auto_explain.
Merci.
Hors ligne
Bonjour Guillaume,
J'ai ajouté les 2 lignes suivantes dans mon postgresql.conf :
shared_preload_libraries = 'auto_explain' # (change requires restart)
auto_explain.log_min_duration = '0s'
J'ai redémarré mon serveur.
J'exécute ma procédure stockée :
begin;
select igeo_pack.histogroupe2('TOTO', 'TITI', 'FRTI', '00135','20140303','20140303','0000');
fetch all in "<unnamed portal 1>";
end;
Je ne vois pas d'infos supplémentaires sur la durée "anormale" du fetch dans mes logs :
2014-03-27 11:02:19 CET [22142]: [3-1] user=postgres [local] 2014-03-27 11:02:16 CET LOG: duration: 0.135 ms statement: begin;
2014-03-27 11:02:24 CET [22142]: [4-1] user=postgres [local] 2014-03-27 11:02:16 CET LOG: duration: 44.820 ms plan:
Query Text: select igeo_pack.histogroupe2('TOTO', 'TITI', 'FRTI', '00135','20140303','20140303','0000');
Result (cost=0.00..0.26 rows=1 width=0)
2014-03-27 11:02:24 CET [22142]: [5-1] user=postgres [local] 2014-03-27 11:02:16 CET LOG: duration: 45.585 ms statement: select igeo_pack.histogroupe2
'TOTO', 'TITI', 'FRTI', '00135','20140303','20140303','0000');
2014-03-27 11:02:38 CET [22142]: [6-1] user=postgres [local] 2014-03-27 11:02:16 CET LOG: duration: 9683.488 ms statement: fetch all from "<unnamed portal 1>";
2014-03-27 11:02:40 CET [22142]: [7-1] user=postgres [local] 2014-03-27 11:02:16 CET LOG: duration: 0.289 ms statement: end;
Pour l'autre solution (comparer la fonction avec une transaction....). J'ai fait cela :
begin;
declare RHisto CURSOR FOR SELECT .......... ;
fetch all from RHisto;
end;
Et j'obtiens dans les logs :
2014-03-27 12:23:58 CET [410]: [16-1] user=postgres [local] 2014-03-27 12:20:12 CET LOG: duration: 1129.922 ms statement: fetch all from RHisto;
2014-03-27 12:24:02 CET [410]: [17-1] user=postgres [local] 2014-03-27 12:20:12 CET LOG: duration: 1129.787 ms plan:
Query Text: declare RHisto CURSOR FOR SELECT ....
GroupAggregate (cost=26.57..26.86 rows=1 width=113)
-> Sort (cost=26.57..26.57 rows=1 width=113)
Sort Key: "*SELECT* 2".cjour, "*SELECT* 2".cidlig, "*SELECT* 2".cliblig, "*SELECT* 2".cidplan, "*SELECT* 2".clibplan, "*SELECT* 2".cidfonc, "*SELECT* 2".clibfonc, "*SELECT* 2".cidope, "*SELECT* 2".clibope, "*SELECT* 2".cofsec, "*SELECT* 2".clibof
-> Append (cost=2.25..26.56 rows=1 width=113)
-> Subquery Scan on "*SELECT* 2" (cost=2.25..26.56 rows=1 width=113)
-> Nested Loop (cost=2.25..26.55 rows=1 width=127)
-> Nested Loop (cost=1.98..26.23 rows=1 width=120)
-> Nested Loop (cost=1.70..25.91 rows=1 width=112)
-> Nested Loop (cost=1.43..25.59 rows=1 width=107)
-> Nested Loop (cost=1.28..25.40 rows=1 width=94)
-> Nested Loop Left Join (cost=0.86..16.92 rows=1 width=70)
-> Index Scan using ptg_pers_jour_typetrtptg on ptg_pers ptg (cost=0.44..8.47 rows=1 width=49)
Index Cond: ((jour >= to_date('20140303'::text, 'YYYYMMDD'::text)) AND (jour <= to_date('20140303'::text, 'YYYYMMDD'::text)))
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((id_site_pointage)::text = 'TITI'::text) AND ((id_perso)::text = '00135'::text))
-> Index Scan using pk_of on o_f oo (cost=0.42..8.45 rows=1 width=29)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((ptg.ofs_cpt)::text = (of_sec)::text))
-> Index Scan using activite_lpfo on activite a (cost=0.42..8.47 rows=1 width=24)
Index Cond: (((id_ligne)::text = (ptg.id_ligne)::text) AND ((id_plan)::text = (ptg.id_plan)::text) AND ((id_fonction)::text = (ptg.id_fonction)::text) AND ((id_operation)::text = (ptg.id_operation)::text))
Filter: (((id_operation)::text <> '0000'::text) AND ((id_cgu)::text = 'TOTO'::text) AND (((id_site)::text = 'TITI'::text) OR ((id_site)::text = '*'::text)) AND (('now'::cstring)::date <= date_fin))
-> Index Scan using pk_ligne on ligne l (cost=0.14..0.18 rows=1 width=27)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((id_ligne)::text = (a.id_ligne)::text))
Filter: ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp))
-> Index Scan using pk_plan on plan p (cost=0.28..0.31 rows=1 width=21)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((id_plan)::text = (a.id_plan)::text))
Filter: ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp))
-> Index Scan using pk_fonction on fonction f (cost=0.28..0.31 rows=1 width=24)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((id_fonction)::text = (a.id_fonction)::text))
Filter: ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp))
-> Index Scan using pk_operation on operation o (cost=0.28..0.31 rows=1 width=27)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((id_operation)::text = (a.id_operation)::text))
Filter: ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp))
La duration passe de 9600ms à 1100ms.
Comment cela s'explique t'il ?
Merci.
Dernière modification par mortimer.pw (27/03/2014 14:28:37)
Hors ligne
Guillaume,
En cherchant sur le net, j'ai trouvé le paramètre qui va bien pour me retourner le détail de la fonction : auto_explain.log_nested_statements=true
Et maintenant, j'ai bien le détail dans les logs :
2014-03-27 14:22:17 CET [17228]: [5-1] user=postgres [local] 2014-03-27 14:22:06 CET LOG: duration: 61.094 ms statement: select igeo_pack.histogroupe2('TOTO', 'TITI', 'FRTI', '00135','20140303','20140303','0000');
2014-03-27 14:22:37 CET [17228]: [6-1] user=postgres [local] 2014-03-27 14:22:06 CET LOG: duration: 9527.346 ms statement: fetch all from "<unnamed portal 1>";
2014-03-27 14:22:40 CET [17228]: [7-1] user=postgres [local] 2014-03-27 14:22:06 CET LOG: duration: 9527.192 ms plan:
Query Text: SELECT .....
GroupAggregate (cost=561445.13..561445.43 rows=1 width=113)
-> Sort (cost=561445.13..561445.14 rows=1 width=113)
Sort Key: ptg.jour, a.id_ligne, l.libelle, a.id_plan, p.libelle, a.id_fonction, f.libelle, a.id_operation, o.libelle, ptg.ofs_cpt, oo.libelle
-> Nested Loop (cost=0.84..561445.12 rows=1 width=113)
Join Filter: ((a.id_operation)::text = (o.id_operation)::text)
-> Nested Loop (cost=0.84..561400.38 rows=1 width=106)
Join Filter: ((a.id_fonction)::text = (f.id_fonction)::text)
-> Nested Loop (cost=0.84..561371.89 rows=1 width=98)
Join Filter: ((a.id_plan)::text = (p.id_plan)::text)
-> Nested Loop Left Join (cost=0.84..561348.62 rows=1 width=93)
-> Nested Loop (cost=0.42..561340.96 rows=1 width=72)
Join Filter: ((l.id_ligne)::text = (a.id_ligne)::text)
-> Nested Loop (cost=0.00..558225.30 rows=645 width=62)
Join Filter: ((ptg.id_ligne)::text = (l.id_ligne)::text)
-> Seq Scan on ptg_pers ptg (cost=0.00..556923.11 rows=1138 width=35)
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((id_site_pointage)::text = 'TITI'::text) AND ((id_perso)::text = '00135'::text) AND (to_char((jour)::timestamp with time zone, 'YYYYMMDD'::text) >= '20140303'::text) AND (to_char((jour)::timestamp with time zone, 'YYYYMMDD'::text) <= '20140303'::text))
-> Materialize (cost=0.00..5.06 rows=76 width=27)
-> Seq Scan on ligne l (cost=0.00..4.68 rows=76 width=27)
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp)))
-> Index Scan using activite_lpfo on activite a (cost=0.42..4.82 rows=1 width=24)
Index Cond: (((id_ligne)::text = (ptg.id_ligne)::text) AND ((id_plan)::text = (ptg.id_plan)::text) AND ((id_fonction)::text = (ptg.id_fonction)::text) AND ((id_operation)::text = (ptg.id_operation)::text))
Filter: (((id_operation)::bpchar <> '0000'::bpchar) AND ((id_cgu)::text = 'TOTO'::text) AND (((id_site)::text = 'TITI'::text) OR ((id_site)::text = '*'::text)) AND (('now'::cstring)::date <= date_fin))
-> Index Scan using pk_of on o_f oo (cost=0.42..7.65 rows=1 width=29)
Index Cond: (((id_cgu)::text = 'TOTO'::text) AND ((ptg.ofs_cpt)::text = (of_sec)::text))
-> Seq Scan on plan p (cost=0.00..15.86 rows=593 width=21)
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp)))
-> Seq Scan on fonction f (cost=0.00..19.84 rows=692 width=24)
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp)))
-> Seq Scan on operation o (cost=0.00..31.04 rows=1096 width=27)
Filter: (((id_cgu)::text = 'TOTO'::text) AND ((date_susp IS NULL) OR (('now'::cstring)::date <= date_susp)))
Visiblement l'index sur ptg_pers n'est pas utilisé.
Alors que dans l'autre test (comparer la fonction avec une transaction....), l'index est utilisé.
Dernière modification par mortimer.pw (27/03/2014 16:06:51)
Hors ligne
Une procédure stockée voit ses différents plans d'exécution conservés en mémoire pour être réutilisés lors des prochaines exécutions. Dans le cas de requêtes dynamiques, cela pose soucis car PostgreSQL doit faire le choix de la sécurité et non des performances. Ce qui m'étonne ici, c'est que la requête du curseur est statique. Donc on ne devrait pas avoir cet effet de bord. Sauf si le code de la procédure stockée a été édité pour une raison ou une autre.
Guillaume.
Hors ligne
Bonjour Guillaume,
Effectivement le code de la procédure a changé entre temps.
Nous avons corrigé :
WHERE TO_CHAR(PTG.jour,'YYYYMMDD')>='20140303'
Par :
WHERE PTG.jour>=TO_DATE('20140303','YYYYMMDD')
Ce qui je pense, explique l'utilisation de l'index.
Pour autant, nous avons utilisé CREATE OR REPLACE FUNCTION.
Cela n'aurait-il pas d'infuence sur le plan d'exécution sauvegardé ?
Et dans ce cas comment le "réinitialiser" ?
Merci.
Hors ligne
Si, le remplacement du code invalide le cache.
Guillaume.
Hors ligne
Bonjour Guillaume,
L'index a été créé après la mise en place de la procédure stockée.
Il faut donc recréer la procédure stockée, c'est bien ça ?
Hors ligne
Si la procédure a été exécutée avant la création de l'index, oui.
Guillaume.
Hors ligne
Ok, merci Guillaume.
Hors ligne
Pages : 1
