Forums PostgreSQL.fr

mortimer.pw

Membre

PgBadger et fichiers temporaires

Bonjour,

Nous travaillons sur des bases 8.4.2 à 9.2.3 sous Cent-OS 5.4 à 5.9.

J'ai exécuté PgBadger à plusieurs reprises, en prenant chaque fois les logs d'une journée complète et j'obtiens les informations suivantes sur les fichiers temporaires.

Heure                         Count                        Av. size
08        7        275,749,741.71
09        5        380,197,273.60
11        4         13,682,688.00
12        4        471,740,416.00
13        6        464,093,184.00
16        5        380,692,070.40
17        4        472,182,784.00
20        4        472,354,816.00

Est-ce normal d'avoir des fichiers aussi volumineux ?
Comment identifier les requêtes qui générent ses fichiers ?

Marc Cousin

Membre

Re : PgBadger et fichiers temporaires

Non, ce n'est pas «normal», dans le sens «habituel». Ils sont tracés dans votre log, en même temps que les traces sur les fichiers temporaires. Cherchez «temporary file: path» dans la log, je pense que ça va vous y amener directement.

---

Marc.

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

Bonjour Marc,

Je viens d'installer la version 3.3 de PgBadger, relancer l'analyse des logs et j'ai davantage d'infos sur les fichiers temporaires.

La requête qui en génére le plus est :
UPDATE ONLY sas.I $ AB01IN_ptg_pers SET IND_UPDATE = 'U' FROM geo.ptg_pers AS T WHERE sas.I $ AB01IN_ptg_pers.id = T.id;

Je sais qui l'éxecute mais je ne la comprend pas. Je n'ai jamais vu cette syntaxe avec des $.

Savez-vous ce que cela veut dire ?

Marc Cousin

Membre

Re : PgBadger et fichiers temporaires

Moi non plus. C'est juste illisible.

Vous êtes allé regarder dans la log si vous la retrouvez ?

---

Marc.

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

J'ai trouvé la requête dans les logs :

1-17.log:2013-06-10 17:56:04 EAT [32121]: [464-1] user=postgres,db=geo 10.11.4.34 LOG:  duration: 0.705 ms  parse <unnamed>: UPDATE ONLY sas.I$AB01IN_ptg_pers SET IND_UPDATE = 'N' FROM geo.ptg_pers  AS  T WHERE sas.I$AB01IN_ptg_pers.id     = T.id and      ((sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg) or (sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL and T.id_type_trt_ptg IS NULL))
1-17.log:2013-06-10 17:56:04 EAT [32121]: [465-1] user=postgres,db=geo 10.11.4.34 LOG:  duration: 0.696 ms  bind <unnamed>: UPDATE ONLY sas.I$AB01IN_ptg_pers SET IND_UPDATE = 'N' FROM geo.ptg_pers  AS  T WHERE sas.I$AB01IN_ptg_pers.id      = T.id and      ((sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg) or (sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL and T.id_type_trt_ptg IS NULL))

Elle a peut être était mal interprété ? Les $ sont peut être mal acceptés ?
De plus il y a un ; après le = T.id alors que la requête n'est pas terminée.

Marc Cousin

Membre

Re : PgBadger et fichiers temporaires

C'est juste une erreur d'interprétation de pgbadger (les $ doivent le paniquer un peu, je viens de remonter le bug à l'auteur). Le $ est juste un bout du nom du champ, à priori, même si c'est un peu bizarre comme règle de nommage.

---

Marc.

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

Ok pour le problème du $.

Pour autant, je ne comprend pas la requête ? ni pourquoi elle génère des fichiers temporaires.

Marc Cousin

Membre

Re : PgBadger et fichiers temporaires

Elle met à jour ind_update sur la table sas, avec une jointure sur tpg_pers (colonnes id), et ne met à jour que ceux vérifiant : (sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg) or (sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL and T.id_type_trt_ptg IS NULL)

Bref, c'est un update avec jointure.

Après, pourquoi elle consomme autant d'espace temporaire, il faudrait en savoir davantage…

Vous pouvez poster le résultat de :

EXPLAIN ANALYZE SELECT I$AB01IN_ptg_pers.ind_update FROM sas.I$AB01IN_ptg_pers,  geo.ptg_pers
WHERE sas.I$AB01IN_ptg_pers.id     = T.id and      ((sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg) or (sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL and T.id_type_trt_ptg IS NULL))

(en espérant ne pas avoir fait d'erreur… le nom de table est vraiment bizarre)

Faites-le sur un environnement où ça pose problème.

---

Marc.

SQLpro

Membre

Re : PgBadger et fichiers temporaires

Cette requête :

UPDATE ONLY sas.I$AB01IN_ptg_pers 
SET    IND_UPDATE = 'N' 
FROM   geo.ptg_pers  AS  T 
WHERE  sas.I$AB01IN_ptg_pers.id     = T.id 
  and  (    (sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg) 
         or (sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL 
             and T.id_type_trt_ptg IS NULL));

             
Fait un OR dans la clause WHERE ce qui n'est pas seargable et oblige à lire toutes les données des tables et les remonte donc dans une table temporaire parce que sion en mémoire ce serait l'exlosion combinatoire.

Essayez de procéder en deux temps :             
             

UPDATE ONLY sas.I$AB01IN_ptg_pers 
SET    IND_UPDATE = 'N' 
FROM   geo.ptg_pers  AS  T 
WHERE  sas.I$AB01IN_ptg_pers.id     = T.id 
  and  sas.I$AB01IN_ptg_pers.id_type_trt_ptg = T.id_type_trt_ptg;

           
             

UPDATE ONLY sas.I$AB01IN_ptg_pers 
SET    IND_UPDATE = 'N' 
FROM   geo.ptg_pers  AS  T 
WHERE  sas.I$AB01IN_ptg_pers.id     = T.id 
  and  sas.I$AB01IN_ptg_pers.id_type_trt_ptg IS NULL and T.id_type_trt_ptg IS NULL;

A =

---

Frédéric Brouard, alias SQLpro,  ARCHITECTE DE DONNÉES,  Expert langage SQL
Le site sur les SGBD relationnel et langage SQL   : http://sqlpro.developpez.com/
Modélisation de données, conseil, expertise, audit, optimisation, tuning, formation
* * * * *  Enseignant CNAM PACA, ISEN Toulon,  CESI Aix en Provence  * * * * *

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

Bonjour Messieurs,
Désolé de revenir un peu tardivement sur ce post, et merci pour votre intérêt.
Pas évident de faire le explain analyze car :
     - Il s'agit d'une requête intermédiaire d'un traitement découpé en plusieurs étapes,
     - Cette requête est faite sur une table temporaire créée à la volée,
     - Sur un serveur en production et je ne dispose pas du traitement pour le rejouer sur une machine de test.
La vie est parfois compliquée.
Grossièrement, le traitement extrait de la table ptg_pers (15 millions d'enregistrements), les lignes qui sont dans un certains état (champ=valeur) et les insérent dans une table temporaire pour exploitation, et après traitement change l'état.
Ci-dessous le explain analyze de la première étape du traitement :

explain analyze SELECT PTG.id_perso AS C1_INT_VCRIT1,PTG.jour AS C2_INT_DCRIT2,PTG.id_ligne || PTG.id_plan || PTG.id_fonction || PTG.id_operation AS C3_INT_VCRIT3,PTG.id_type_trt_ptg AS C4_INT_ETAT,PTG.id AS C5_INT_VCRIT6,PTG.temps AS C6_TEMPS,ACT.code_compta AS C7_CODE_COMPTA
FROM geo.ptg_pers AS PTG,geo.operation AS OPE,geo.activite AS ACT
WHERE (1 = 1 )
AND (PTG.id_type_trt_ptg = 'EX' )
AND (OPE.id_type_alim = '2' )
AND (PTG.id_operation = OPE.id_operation )
AND ((((PTG.id_ligne = ACT.id_ligne ) AND PTG.id_plan = ACT.id_plan ) AND PTG.id_fonction = ACT.id_fonction ) AND PTG.id_operation = ACT.id_operation );

Nested Loop  (cost=7.08..23047.03 rows=5 width=51) (actual time=124144.580..124144.580 rows=0 loops=1)
   Join Filter: ((ope.id_operation)::text = (ptg.id_operation)::text)
   ->  Hash Join  (cost=7.08..1622.89 rows=2720 width=33) (actual time=0.241..134.029 rows=20252 loops=1)
         Hash Cond: ((act.id_operation)::text = (ope.id_operation)::text)
         ->  Seq Scan on activite act  (cost=0.00..1390.99 rows=52699 width=29) (actual time=0.026..52.498 rows=52700 loops=1)
         ->  Hash  (cost=6.88..6.88 rows=16 width=4) (actual time=0.169..0.169 rows=16 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 1kB
               ->  Seq Scan on operation ope  (cost=0.00..6.88 rows=16 width=4) (actual time=0.036..0.146 rows=16 loops=1)
                     Filter: ((id_type_alim)::text = '2'::text)
                     Rows Removed by Filter: 294
   ->  Index Scan using ptg_pers_idx on ptg_pers ptg  (cost=0.00..7.86 rows=1 width=38) (actual time=6.121..6.121 rows=0 loops=20252)
         Index Cond: (((id_ligne)::text = (act.id_ligne)::text) AND ((id_plan)::text = (act.id_plan)::text) AND ((id_fonction)::text = (act.id_fonction)::text) AND ((id_type_trt_p
tg)::text = 'EX'::text))
         Filter: ((act.id_operation)::text = (id_operation)::text)
Total runtime: 124144.747 ms

gleu

Administrateur

Re : PgBadger et fichiers temporaires

La requête passe son temps dans l'index :

Index Scan using ptg_pers_idx on ptg_pers ptg  (cost=0.00..7.86 rows=1 width=38) (actual time=6.121..6.121 rows=0 loops=20252)
         Index Cond: (((id_ligne)::text = (act.id_ligne)::text) AND ((id_plan)::text = (act.id_plan)::text) AND ((id_fonction)::text = (act.id_fonction)::text) AND ((id_type_trt_ptg)::text = 'EX'::text))
         Filter: ((act.id_operation)::text = (id_operation)::text)

Il y a déjà une erreur au niveau des statistiques. Il pense récupérer 2720 lignes au niveau du SeqScan sur activité et en récupère réellement 20252. Juste un facteur 10. Lire 2720 lignes dans un index, ce n'est pas du tout la même chose que lire 20252 lignes.

Un test intéressant à faire serait de désactiver les parcours d'index (SET enable_indexscan TO off;) peut être même les parcours de bitmap, et voir ce que donne le nouveau plan de requête et sa durée d'exécution.

Il serait aussi intéressant de voir les statistiques sur la table activite et savoir si elles représentent bien le contenu de la table.

---

Guillaume.

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

Bonjour Guillaume,

La définition de l'index ptg_pers_idx est la suivante :
          CREATE INDEX ptg_pers_idx ON ptg_pers USING btree (id_ligne, id_plan, id_fonction, id_document, id_job, id_type_trt_ptg, id_type_ptg_sst);

Désactiver les parcours d'index ne risque t'il pas de perturber la production ?

Les infos sur la table Activite :
          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_dead_tup | last_vacuum
|        last_autovacuum        |         last_analyze          |       last_autoanalyze        | vacuum_count | autovacuum_count | analyze_count | autoanalyze_count
-------+------------+----------+----------+--------------+-----------+---------------+-----------+-----------+-----------+---------------+------------+------------+-------------
+-------------------------------+-------------------------------+-------------------------------+--------------+------------------+---------------+-------------------
16574 | geo        | activite |   107051 |   5466223332 | 412122902 |    1237898752 |    109097 |     56139 |       258 |          3545 |      52700 |          2 |             
| 2013-05-06 12:55:51.223687+03 | 2013-06-23 03:27:49.735602+03 | 2013-05-06 12:55:53.862434+03 |            0 |                1 |            14 |                 2

select count(*) from activite;
count
-------
52700

la requête pour trouver les operation avec type_alim='2' :
select count(*) from activite a,operation o where a.id_operation=o.id_operation and o.id_type_alim='2';
count
-------
20252

Dernière modification par mortimer.pw (27/06/2013 07:47:50)

gleu

Administrateur

Re : PgBadger et fichiers temporaires

Désactiver les parcours d'index ne risque t'il pas de perturber la production ?

Il suffit de le faire juste au niveau de la session : SET enable_indexscan TO off; puis exécution de la requête.

Les infos sur la table Activite :

Je ne parlais pas de ces statistiques mais des statistiques du planificateur : SELECT * FROM pg_stats WHERE tablename='activite'; (faites un \x avant, sinon ça sera illisible).

---

Guillaume.

mortimer.pw

Membre

Re : PgBadger et fichiers temporaires

Bonjour Guillaume,

Ci-dessous le explain analyze avec SET enable_indexscan TO off;

Nested Loop  (cost=13.23..23926.96 rows=5 width=51) (actual time=128052.082..128052.082 rows=0 loops=1)
   Join Filter: ((ope.id_operation)::text = (ptg.id_operation)::text)
   ->  Hash Join  (cost=7.08..1624.76 rows=2723 width=33) (actual time=0.243..137.193 rows=20268 loops=1)
         Hash Cond: ((act.id_operation)::text = (ope.id_operation)::text)
         ->  Seq Scan on activite act  (cost=0.00..1392.60 rows=52760 width=29) (actual time=0.035..52.049 rows=52739 loops=1)
         ->  Hash  (cost=6.88..6.88 rows=16 width=4) (actual time=0.162..0.162 rows=16 loops=1)
               Buckets: 1024  Batches: 1  Memory Usage: 1kB
               ->  Seq Scan on operation ope  (cost=0.00..6.88 rows=16 width=4) (actual time=0.034..0.143 rows=16 loops=1)
                     Filter: ((id_type_alim)::text = '2'::text)
                     Rows Removed by Filter: 294
   ->  Bitmap Heap Scan on ptg_pers ptg  (cost=6.16..8.18 rows=1 width=38) (actual time=6.308..6.308 rows=0 loops=20268)
         Recheck Cond: (((id_ligne)::text = (act.id_ligne)::text) AND ((id_plan)::text = (act.id_plan)::text) AND ((id_fonction)::text = (act.id_fonction)::text) AND ((id_type_t
rt_ptg)::text = 'EX'::text))
         Filter: ((act.id_operation)::text = (id_operation)::text)
         ->  Bitmap Index Scan on ptg_pers_idx  (cost=0.00..6.16 rows=1 width=0) (actual time=6.305..6.305 rows=0 loops=20268)
               Index Cond: (((id_ligne)::text = (act.id_ligne)::text) AND ((id_plan)::text = (act.id_plan)::text) AND ((id_fonction)::text = (act.id_fonction)::text) AND ((id_ty
pe_trt_ptg)::text = 'EX'::text))
Total runtime: 128052.265 ms

Pour les infos de pg_stats, la requête me retourne 25 longues lignes d'informations (égal au nombre de champs de la table), du style :

geo=# SELECT * FROM pg_stats WHERE tablename='activite';
[ RECORD 1 ]
schemaname             | geo
tablename              | activite
attname                | id_ligne
inherited              | f
null_frac              | 0
avg_width              | 4
n_distinct             | 14
most_common_vals       | {010,030,070,020,050,060,025,040,080,090,095,089,295,289}
most_common_freqs      | {0.301133,0.209067,0.152067,0.120533,0.0855667,0.0811,0.0237,0.0107333,0.004,0.0037,0.00313333,0.0026,0.00183333,0.000833333}
histogram_bounds       |
correlation            | 0.153071
most_common_elems      |
most_common_elem_freqs |
elem_count_histogram   |
[ RECORD 2 ]
schemaname             | geo
tablename              | activite
attname                | id_plan
inherited              | f
null_frac              | 0
avg_width              | 4
n_distinct             | 427
most_common_vals       | {0350,0405,0305,0460,0964,0425,0655,0360,0199,0763,0270,0362,0190,0361,0364,0465,0135,0325,0974,0367,0260,0740,0540,0695,0090,0320,0368,0371,0340,0089,0
091,0315,0295,0385,0570,1032}
most_common_freqs      | {0.2314,0.0499667,0.0470333,0.0383667,0.0275667,0.0177333,0.0176333,0.0131333,0.0124333,0.0110333,0.0103667,0.0095,0.00916667,0.0079,0.00783333,0.0074,0
.0073,0.00693333,0.00666667,0.0063,0.00603333,0.00486667,0.00393333,0.00376667,0.0037,0.0037,0.00366667,0.00366667,0.0036,0.00343333,0.0032,0.0032,0.003,0.00296667,0.00296667,0.
00296667}
histogram_bounds       | {0073,0078,0082,0095,0101,0105,0108,0112,0115,0118,0124,0127,0129,0133,0136,0138,0141,0145,0148,0151,0156,0159,0161,0164,0167,0172,0177,0182,0189,0195,0
200,0210,0236,0245,0257,0280,0326,0349,0365,0375,0395,0407,0419,0435,0455,0483,0500,0535,0552,0555,0563,0595,0614,0620,0630,0650,0665,0675,0690,0715,0727,0733,0738,0743,0747,075
0,0769,0779,0787,0792,0799,0806,0813,0818,0839,0843,0852,0857,0865,0875,0886,0895,0906,0910,0916,0922,0968,0976,0981,1002,1008,1024,1037,1065,1252,1264,1270,1278,295,360,928}
correlation            | 0.0612787
most_common_elems      |
most_common_elem_freqs |
elem_count_histogram   |

Quelles informations sont intéressantes ?