Vous n'êtes pas identifié(e).

#1 11/03/2014 11:45:47

mortimer.pw
Membre

Requête plus rapide que procédure stockée

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

#2 12/03/2014 23:44:11

gleu
Administrateur

Re : Requête plus rapide que procédure stockée

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

#3 26/03/2014 15:52:07

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

Bonjour Guillaume,

Ok, je vais regarder l'auto_explain.

Merci.

Hors ligne

#4 27/03/2014 12:16:05

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

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

#5 27/03/2014 16:05:00

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

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

#6 30/03/2014 17:44:18

gleu
Administrateur

Re : Requête plus rapide que procédure stockée

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

#7 31/03/2014 11:05:54

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

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

#8 31/03/2014 22:32:01

gleu
Administrateur

Re : Requête plus rapide que procédure stockée

Si, le remplacement du code invalide le cache.


Guillaume.

Hors ligne

#9 01/04/2014 08:42:33

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

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

#10 01/04/2014 22:47:55

gleu
Administrateur

Re : Requête plus rapide que procédure stockée

Si la procédure a été exécutée avant la création de l'index, oui.


Guillaume.

Hors ligne

#11 02/04/2014 13:15:05

mortimer.pw
Membre

Re : Requête plus rapide que procédure stockée

Ok, merci Guillaume.

Hors ligne

Pied de page des forums