Forums PostgreSQL.fr

mortimer.pw

Membre

Requête mise en évidence par PgFouine

Bonjour à tous,

Je travaille sur des bases en 8.4 et 9.0 sous CentOs 5.4.
Les machines : DL360 - 64bits, 4Go RAM
Les paramètres Postgresql.conf
     Shared_buffers : 1024MB
     Work_mem : 10MB
     Maintenance_work_mem : 512MB
     Effective_cache_size : 2730MB

Je "parse" des fichiers de log avec PgFouine et une requête sort fréquemment.

     Queries that took up the most time
          Total duration : 49.8s
          Times executed : 112
          Query : select Igeo_pack.ActiviteCourante('')as id_activite;
     Slowest queries
          Duration : 0.98
          Query : select Igeo_pack.ActiviteCourante('I8246')as id_activite;
     Most frequent queries
          Times executed : 112
          Total duration : 49.8s
          Av duration : 0.44
          Query : select Igeo_pack.ActiviteCourante('')as id_activite;

Ci-dessous la description de la Fonction :
    CREATE OR REPLACE FUNCTION IGEO_PACK.ActiviteCourante(VARCHAR) RETURNS VARCHAR AS '
    DECLARE
        cActiviteCourante VARCHAR(10000);
        RPointage RECORD;
    BEGIN
        cActiviteCourante:=''NULL'';
        SELECT INTO RPointage P.*,A.*,OO.libelle
        FROM GEO.Pointage P
            LEFT OUTER JOIN GEO.O_f OO ON (P.of_sec=OO.of_sec)
            LEFT OUTER JOIN GEO.Vue_activite_geo A ON (P.id_ligne=A.id_ligne AND P.id_plan=A.id_plan AND P.id_fonction=A.id_fonction AND P.id_operation=A.id_operation)
        WHERE P.jour=CURRENT_DATE
        AND P.id_perso=$1
        ORDER BY P.heure DESC LIMIT 1;
        IF NOT FOUND THEN
            cActiviteCourante:=IGEO_PACK.DerniereActivite($1);
        ELSE
            cActiviteCourante:=RPointage.id_ligne||'';''||RPointage.lib_ligne||'';''||RPointage.id_plan||'';''||RPointage.lib_plan||'';''||
            RPointage.id_fonction||'';''||RPointage.lib_fonction||'';''||RPointage.id_operation||'';''||RPointage.lib_operation||'';'';
            IF RPointage.of_sec IS NOT NULL THEN
                IF RPointage.libelle IS NOT NULL THEN
                    cActiviteCourante:=cActiviteCourante||RPointage.of_sec||'';''||RPointage.libelle;
                ELSE
                    cActiviteCourante:=cActiviteCourante||'';'';
                END IF;
            ELSE
                cActiviteCourante:=cActiviteCourante||'';'';
            END IF;
            cActiviteCourante:=cActiviteCourante||'';''||RPointage.qte_igeo||'';''||TO_CHAR(RPointage.jour,''YYYYMMDD'')||'';''||
            RPointage.heure;
        END IF;
        RETURN cActiviteCourante;
    END;
    ' LANGUAGE 'plpgsql';
    ALTER FUNCTION IGEO_PACK.ActiviteCourante(VARCHAR) OWNER TO postgres;

Maintenant un plan d'exécution :
Limit  (cost=3365.54..3365.55 rows=1 width=684) (actual time=0.070..0.070 rows=0 loops=1)
   ->  Sort  (cost=3365.54..3365.55 rows=1 width=684) (actual time=0.066..0.066 rows=0 loops=1)
         Sort Key: p.heure
         Sort Method:  quicksort  Memory: 25kB
         ->  Nested Loop Left Join  (cost=24.62..3365.53 rows=1 width=684) (actual time=0.023..0.023 rows=0 loops=1)
               ->  Nested Loop Left Join  (cost=24.62..3361.25 rows=1 width=655) (actual time=0.023..0.023 rows=0 loops=1)
                     Join Filter: (((p.id_ligne)::text = (a.id_ligne)::text) AND ((p.id_plan)::text = (a.id_plan)::text) AND ((p.id_fonction)::text = (a.id
_fonction)::text) AND ((p.id_operation)::text = (a.id_operation)::text))
                     ->  Seq Scan on pointage p  (cost=0.00..1.50 rows=1 width=498) (actual time=0.022..0.022 rows=0 loops=1)
                           Filter: (((id_perso)::text = '80387'::text) AND (jour = ('now'::text)::date))
                     ->  Hash Join  (cost=24.62..3117.87 rows=12094 width=157) (never executed)
                           Hash Cond: ((a.id_operation)::text = (o.id_operation)::text)
                           ->  Hash Join  (cost=12.48..2939.44 rows=12094 width=139) (never executed)
                                 Hash Cond: ((a.id_plan)::text = (p.id_plan)::text)
                                 ->  Hash Join  (cost=4.50..2765.16 rows=12094 width=128) (never executed)
                                       Hash Cond: ((a.id_ligne)::text = (l.id_ligne)::text)
                                       ->  Hash Join  (cost=2.12..2596.50 rows=12094 width=103) (never executed)
                                             Hash Cond: ((a.id_fonction)::text = (f.id_fonction)::text)
                                             ->  Seq Scan on activite a  (cost=0.00..2428.08 rows=12094 width=83) (never executed)
                                                   Filter: (((id_type_ptg_sst)::text = 'G'::text) AND (valide = 1::numeric) AND (to_char((('now'::text)::da
te)::timestamp with time zone, 'YYYYMMDD'::text) <= to_char((((date_fin_valide)::text)::date)::timestamp with time zone, 'YYYYMMDD'::text)))
                                             ->  Hash  (cost=1.50..1.50 rows=50 width=24) (never executed)
                                                   ->  Seq Scan on fonction f  (cost=0.00..1.50 rows=50 width=24) (never executed)
                                       ->  Hash  (cost=1.61..1.61 rows=61 width=29) (never executed)
                                             ->  Seq Scan on ligne l  (cost=0.00..1.61 rows=61 width=29) (never executed)
                                 ->  Hash  (cost=4.66..4.66 rows=266 width=15) (never executed)
                                       ->  Seq Scan on plan p  (cost=0.00..4.66 rows=266 width=15) (never executed)
                           ->  Hash  (cost=7.06..7.06 rows=406 width=22) (never executed)
                                 ->  Seq Scan on operation o  (cost=0.00..7.06 rows=406 width=22) (never executed)
               ->  Index Scan using pk_of on o_f oo  (cost=0.00..4.27 rows=1 width=37) (never executed)
                     Index Cond: ((p.of_sec)::text = (oo.of_sec)::text)
Total runtime: 0.370 ms
(30 rows)

Cette Fonction est-elle mal écrite ? optimisable ? Les temps sont-ils acceptables ? Avez-vous besoin d'autres infos ?

Merci de me lire.

gleu

Administrateur

Re : Requête mise en évidence par PgFouine

Je suppose que le EXPLAIN vient de la requête SELECT avec les deux jointures LEFT OUTER JOIN. Difficile de dire quoi que ce soit sur ce plan d'exécution vu qu'il s'exécute en 0,07 ms, ce qui est excellent C'est d'ailleurs excellent parce que tout n'est pas exécuté, le parcours séquentiel sur la table pointage ne ramenant aucune ligne.

Concernant la fonction, elle a l'air très simple. Je ne vois que deux possibilités pour un problème de performances : la requête SELECT (mais avec des arguments qui demandent une exécution complète du plan), et la fonction IGEO_PACK.DerniereActivite.

Avez-vous activé track_functions pour connaître la durée d'exécution des fonctions ? Cet article (http://blog.guillaume.lelarge.info/inde … -functions) pourrait vous intéresser.

---

Guillaume.

mortimer.pw

Membre

Re : Requête mise en évidence par PgFouine

Bonjour Guillaume,

Désolé, oui le EXPLAIN vient bien de la requête SELECT avec les 2 jointures.

J'ai lancé le EXPLAIN sur ma machine de test, encore désolé.
Voilà la même chose sur une machine de prod :
Limit  (cost=178.25..178.26 rows=1 width=371) (actual time=39.090..39.093 rows=1 loops=1)
   ->  Sort  (cost=178.25..178.26 rows=1 width=371) (actual time=39.087..39.087 rows=1 loops=1)
         Sort Key: p.heure
         Sort Method:  top-N heapsort  Memory: 25kB
         ->  Nested Loop Left Join  (cost=26.12..178.24 rows=1 width=371) (actual time=6.126..39.018 rows=3 loops=1)
               ->  Nested Loop Left Join  (cost=26.12..173.96 rows=1 width=341) (actual time=6.080..38.954 rows=3 loops=1)
                     Join Filter: (((p.id_ligne)::text = (a.id_ligne)::text) AND ((p.id_plan)::text = (a.id_plan)::text) AND ((p.id_fonction)::text = (a.i
d_fonction)::text) AND ((p.id_operation)::text = (a.id_operation)::text))
                     ->  Index Scan using pointage_chaine on pointage p  (cost=0.01..4.28 rows=1 width=185) (actual time=0.059..0.075 rows=3 loops=1)
                           Index Cond: ((jour = ('now'::text)::date) AND ((id_perso)::text = '80396'::text))
                     ->  Hash Join  (cost=26.11..162.12 rows=378 width=156) (actual time=0.271..12.536 rows=1133 loops=3)
                           Hash Cond: ((a.id_ligne)::text = (l.id_ligne)::text)
                           ->  Hash Join  (cost=23.74..154.55 rows=378 width=131) (actual time=0.239..11.567 rows=1133 loops=3)
                                 Hash Cond: ((a.id_plan)::text = (p.id_plan)::text)
                                 ->  Hash Join  (cost=15.57..141.19 rows=378 width=120) (actual time=0.160..10.626 rows=1133 loops=3)
                                       Hash Cond: ((a.id_operation)::text = (o.id_operation)::text)
                                       ->  Hash Join  (cost=2.17..122.59 rows=378 width=102) (actual time=0.045..9.653 rows=1133 loops=3)
                                             Hash Cond: ((a.id_fonction)::text = (f.id_fonction)::text)
                                             ->  Seq Scan on activite a  (cost=0.00..115.22 rows=378 width=83) (actual time=0.024..8.580 rows=1133 loops=3
)
                                                   Filter: (((id_type_ptg_sst)::text = 'G'::text) AND (valide = 1::numeric) AND (to_char((('now'::text)::d
ate)::timestamp with time zone, 'YYYYMMDD'::text) <= to_char((((date_fin_valide)::text)::date)::timestamp with time zone, 'YYYYMMDD'::text)))
                                             ->  Hash  (cost=1.52..1.52 rows=52 width=23) (actual time=0.047..0.047 rows=52 loops=1)
                                                   ->  Seq Scan on fonction f  (cost=0.00..1.52 rows=52 width=23) (actual time=0.009..0.021 rows=52 loops=
1)
                                       ->  Hash  (cost=8.18..8.18 rows=418 width=22) (actual time=0.330..0.330 rows=418 loops=1)
                                             ->  Seq Scan on operation o  (cost=0.00..8.18 rows=418 width=22) (actual time=0.012..0.143 rows=418 loops=1)
                                 ->  Hash  (cost=4.74..4.74 rows=274 width=15) (actual time=0.223..0.223 rows=274 loops=1)
                                       ->  Seq Scan on plan p  (cost=0.00..4.74 rows=274 width=15) (actual time=0.014..0.107 rows=274 loops=1)
                           ->  Hash  (cost=1.61..1.61 rows=61 width=29) (actual time=0.064..0.064 rows=61 loops=1)
                                 ->  Seq Scan on ligne l  (cost=0.00..1.61 rows=61 width=29) (actual time=0.016..0.031 rows=61 loops=1)
               ->  Index Scan using pk_of on o_f oo  (cost=0.00..4.27 rows=1 width=38) (actual time=0.017..0.018 rows=1 loops=3)
                     Index Cond: ((p.of_sec)::text = (oo.of_sec)::text)
Total runtime: 39.414 ms
(30 rows)

Oui, le track_functions est activé.

Je vais lire votre article de suite.

flo

Membre

Re : Requête mise en évidence par PgFouine

C'est normal toutes ces conversions en texte dans la requête?

Sinon, c'est bien cette requête-là?

SELECT INTO RPointage P.*,A.*,OO.libelle
        FROM GEO.Pointage P
            LEFT OUTER JOIN GEO.O_f OO ON (P.of_sec=OO.of_sec)
            LEFT OUTER JOIN GEO.Vue_activite_geo A ON (P.id_ligne=A.id_ligne AND P.id_plan=A.id_plan AND P.id_fonction=A.id_fonction AND P.id_operation=A.id_operation)
        WHERE P.jour=CURRENT_DATE
        AND P.id_perso=$1
        ORDER BY P.heure DESC LIMIT 1;

Parce que je ne comprends pas pourquoi, dans le plan d'exécution fourni, il y a la table ligne, la table fonction...
cela non plus :

Filter: (((id_type_ptg_sst)::text = 'G'::text) AND (valide = 1::numeric) AND (to_char((('now'::text)::d
ate)::timestamp with time zone, 'YYYYMMDD'::text) <= to_char((((date_fin_valide)::text)::date)::timestamp with time zone, 'YYYYMMDD'::text)))

?

mortimer.pw

Membre

Re : Requête mise en évidence par PgFouine

Bonjour Flo,

La requête utililse une Vue (GEO.Vue_activite_geo) décrite ci-dessous :

CREATE OR REPLACE VIEW geo.vue_activite_geo AS
    SELECT a.id_ligne,l.libelle AS lib_ligne,a.id_plan,p.libelle AS lib_plan,a.id_fonction,f.libelle AS lib_fonction,a.id_operation,
    o.libelle AS lib_operation,a.id_type_ptg,a.id_type_act,a.tps_gam,a.tps_gam_test,a.id_type_coq,a.id_type_qte_act,a.qte_igeo,a.id_type_cum_doc,
    a.dbl_ptg,a.code_compta,a.date_fin_valide,a.id_site
    FROM geo.activite a,geo.ligne l,geo.plan p,geo.fonction f,geo.operation o
    WHERE a.id_type_ptg_sst='G'
    AND a.valide=1
    AND to_char('now'::text::date::timestamp with time zone,'YYYYMMDD'::text)<=to_char(a.date_fin_valide::text::date,'YYYYMMDD'::text)
    AND a.id_ligne=l.id_ligne
    AND a.id_plan=p.id_plan
    AND a.id_fonction=f.id_fonction
    AND a.id_operation=o.id_operation;
ALTER TABLE geo.vue_activite_geo OWNER TO postgres;

Les conversions en texte ne sont pas nécessaires ?

Merci pour votre participation.

rjuju

Administrateur

Re : Requête mise en évidence par PgFouine

La conversion n'est pas nécessaire, mais en plus empêche l'utilisation d'un index sur la colonne s'il est présent, et prend aussi du temps cpu supplémentaire.

Comme le montrait flo, cela résulte à un seqscan sur la table activite (cela dépend aussi si vous avez des index sur les colonnes id_type_ptg_ss, valide et selon le nombre de lignes correspondant à ces critères).

>  Seq Scan on activite a  (cost=0.00..115.22 rows=378 width=83) (actual time=0.024..8.580 rows=1133 loops=3
)
                                                   Filter: (((id_type_ptg_sst)::text = 'G'::text) AND (valide = 1::numeric) AND (to_char((('now'::text)::d
ate)::timestamp with time zone, 'YYYYMMDD'::text) <= to_char((((date_fin_valide)::text)::date)::timestamp with time zone, 'YYYYMMDD'::text)))

Vous pouvez également essayer un analyze sur la table activite, les statistiques ayant l'air erronées.

Dernière modification par rjuju (05/06/2012 10:58:01)

---

Julien.
https://rjuju.github.io/

gleu

Administrateur

Re : Requête mise en évidence par PgFouine

Comme l'ont indiqué Florence et Julien, le gros problème vient du parcours séquentiel sur la table activite. C'est très flagrant sur http://explain.depesz.com/s/clE. Trois parcours séquentiels à 9ms chacune, donne 24 ms, soit un peu plus que la moitié de la requête. Commencez par regarder la table activite pour vérifier si des index sont présents sur les colonnes filtrées. Et ne pas faire de conversion de texte, une comparaison de date est beaucoup plus simple et peut utiliser les index.

---

Guillaume.

gleu

Administrateur

Re : Requête mise en évidence par PgFouine

Cela étant dit, on est loin des secondes dont parle pgfouine...

---

Guillaume.

mortimer.pw

Membre

Re : Requête mise en évidence par PgFouine

Bonjour Rjuju,

J'ai remplacé :
     to_char('now'::text::date::timestamp with time zone,'YYYYMMDD'::text)<=to_char(a.date_fin_valide::text::date,'YYYYMMDD'::text)
Par :
     now()<=a.date_fin_valide
Dans la Vue, le temps d'exécution ne semble pas bouger.

Il n'y a pas d'index sur les colonnes date_fin_valide, id_type_ptg_sst et valide.

La table activite contient 1864 lignes, la vue retourne 1133 lignes.

Les statistiques de la table :

geo=# select * from pg_stat_user_tables where relname='activite';
relid | schemaname | relname  | seq_scan | seq_tup_read | idx_scan | idx_tup_fetch | n_tup_ins | n_tup_upd | n_tup_del | n_tup_hot_upd | n_live_tup | n_dea
d_tup |          last_vacuum          |       last_autovacuum        |         last_analyze          |       last_autoanalyze
-------+------------+----------+----------+--------------+----------+---------------+-----------+-----------+-----------+---------------+------------+------
------+-------------------------------+------------------------------+-------------------------------+------------------------------
16484 | geo        | activite |  1314165 |   1967106299 |  9028205 |     105013628 |      2380 |       356 |       120 |            19 |       1864 |
    0 | 2012-06-03 08:01:10.716333+02 | 2012-05-29 14:21:05.13258+02 | 2012-06-03 08:01:10.819685+02 | 2012-05-29 14:21:05.13258+02

Comment voit-on que les stats sont erronées ?

rjuju

Administrateur

Re : Requête mise en évidence par PgFouine

Sur le explain analyze, l'analyseur s'attend à trouver 378 ligne et en trouve au final 1133

Seq Scan on activite a  (cost=0.00..115.22 rows=378 width=83) (actual time=0.024..8.580 rows=1133 loops=3

edit: pgFouine pointe cette requête comme prenant 49.8 secondes sur 112 exécutions, soit un temps moyen de 444 ms., avec un pic à 980 ms. Votre explain durant 39ms, le problème vient peut-être d'accès concurrent dans la journée, d'un cache pas assez grand ou de temps différent selon le paramètre en entrée.

Dernière modification par rjuju (05/06/2012 11:24:03)

---

Julien.
https://rjuju.github.io/

mortimer.pw

Membre

Re : Requête mise en évidence par PgFouine

Je ne comprend pas pourquoi l'analyseur s'attend à trouver 378 lignes ?

Un vacuum full analyze (vacuumdb -a -f -z) est fait le dimanche et il n'y a pas eu de changement dans la table depuis.

rjuju

Administrateur

Re : Requête mise en évidence par PgFouine

Il faudrait regarder sur chacune des colonnes le n_distinct (pg_stats) et comparer à ce que vous avez réellement. S'il y a une grosse différence vous pouvez augmenter le nombre de lignes utilisées pour les statistiques (ALTER TABLE <table> ALTER COLUMN <column> SET STATISTICS <number>; et relancer un analyze.

Dans tous les cas, la table étant parcourue par un scan séquentiel, il serait intéressant d'ajouter un index sur une ou plusieurs des colonnes utilisées.

Dernière modification par rjuju (05/06/2012 11:40:18)

---

Julien.
https://rjuju.github.io/

mortimer.pw

Membre

Re : Requête mise en évidence par PgFouine

Rjuju,

La colonne id_type_ptg_sst ne comporte actuellement qu'une seule valeur et à terme peut être 4 ou 5.
La colonne valide vaut 1 ou 0
La colonne date_fin_valide vaut par défaut 01/01/3000 et change de date lorsque l'activité n'est plus valide.

Est-il intéressant de créer un index ? sera t'il utilisé vu le faible nombre de lignes dans la tables et le faible nombre de valeurs différentes ?

rjuju

Administrateur

Re : Requête mise en évidence par PgFouine

Votre vue récupère 1133 lignes sur les 1864, ce qui fait 60% de la table, ça peut valoir le coup d'essayer.
Votre colonne valide ne fait-elle pas double emploi avec la colonne date_fin_valide ? Surtout si vous interrogez la base à une autre date que la date du jour.

Vous devriez essayer de mettre un index sur la date et voir si le plan d'exécution change pour gagner un peu en IO.

---

Julien.
https://rjuju.github.io/