Vous n'êtes pas identifié(e).
Bonjour tout le monde,
Je travaille sous CenOS 5.4 avec un moteur PostgreSQL 9.3.2.
La charge machine (nombre de process, utilisation CPU, RAM, I/O) est sous surveillance Centreon.
J'essaye de mettre en place un monitoring de la base.
Je surveille la taille de la base
SELECT PG_DATABASE_SIZE;
Je surveille le Ratio Cache Hit/miss
SELECT ROUND((blks_hit::FLOAT/(blks_read+blks_hit+1)*100)::NUMERIC,2) FROM pg_stat_database WHERE datname='MA_BASE'
Je surveille le nombre d'enregistrements, la taille, le Ratio Cache Hit/miss par Table.
Je surveille la taille, le Ratio Cache Hit/miss par Indexe.
Je surveille les appels aux Fonctions
SELECT funcname,calls,total_time,self_time FROM pg_stat_user_functions;
Je surveille l'activité par Utilisateur avec PgBadger :
Le nombre des connexions
Le volume des requêtes Select/Insert/Update/Delete/Others
Les verrous
Les requêtes les plus lentes
Les requêtes les plus exécutées
Je surveille également les transactions validées et annulées, le nombre global de lignes renvoyées, récupérées, insérées, mise à jour et supprimées
SELECT xact_commit,xact_rollback,tup_returned,tup_fetched,tup_inserted,tup_updated,tup_deleted FROM pg_stat_database WHERE datname='MA_BASE'
Quelle est la différence entre TUP_RETURNED et TUP_FETCHED ? Est-ce les requêtes simples et par exemples les curseurs ?
Ces compteurs ne font qu'augmenter. Peut-on faire un PG_STAT_RESET(), par exemple chaque dimanche, pour avoir une vue à la semaine ?
Le PG_STAT_RESET() peut-il avoir des effets négatifs sur l'optimiseur de requêtes ou autre ?
Quels Ratios peut-on mettre en place pour les Lectures/Ecritures ?
Y-a t'il d'autres points importants à surveiller ?
D'avance merci pour vos réponses.
Ok, merci Guillaume.
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 ?
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.
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é.
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.
Bonjour Guillaume,
Ok, je vais regarder l'auto_explain.
Merci.
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.
Bonjour tout le monde,
J'ajoute un petit up pour essayer d'obtenir des infos.
J'ai également lu le post "[v9.2] Performances en lecture faible sur 25M de lignes, étrange ?"
Serions-nous également aux limites ? mais alors pourquoi plus rapide en 9.2.4 ?
D'avance merci pour les réponses.
Bonjour à tous,
Je résume un peu nos différents tests :
Test 1 :
12Go RAM
1 disque 10000 tours en EXT3 (OS+DATA+XLOG+STATS+TRACES)
Moteur 9.2.4
Shared_buffers=3072MB, Maintenance_work_mem=1536MB, Checkpoint_segments=96, Checkpoint_timeout=15min, Checkpoint_completion_target=0.9, Random_page_cost=2.4, Effective_cache_size=8192MB
Temps de réponse globaux acceptable (mais à améliorer), 6000 INSERT par seconde, plus d'écriture de fichiers temporaires sur disque, toutes les requêtes sont acquittées.
Test 2 :
32Go RAM
1 disque 10000 tours en EXT4 (OS+TRACES)
1 disque 15000 tours en EXT4 (DATA)
1 disque 15000 tours en EXT4 (XLOG)
1 "RAM disque" (stats_temp_directory = '/ramcache')
Moteur 9.3.0
Shared_buffers=8192MB, Maintenance_work_mem=4096MB, Checkpoint_segments=64, Checkpoint_timeout=10min, Effective_cache_size=21840MB
Checkpoint_completion_target et Random_page_cost laissé par défaut.
Globalement, meilleurs, 10000 INSERT par seconde, mais temps de réponse sur les gros SELECT en chute de 25%.
Test 3 :
Matériel idem TEST 2
Moteur 9.3.1
Paramètres idem TEST 2
Résultat idem TEST 2
Test N :
Matériel idem TEST 2
Déplacement DATA et XLOG entre les disques.
Augmentation et diminution des paramètres liés à la mémoire et aux Checkpoints
Résultats idem TEST 2
Avant dernier test :
Matériel idem TEST 2
Moteur 9.2.4
Paramètres idem TEST 1
AMELIORATION GENERALE
Dernier test :
Matériel idem TEST 2
Moteur 9.3.1
Paramètres idem TEST 1
Dégradation des temps de réponse, de nouveaux des fichiers temporaires sur disque, des requêtes non acquittées (trop longues).
Peut-il y avoir une dégradation entre les versions 9.2.4 et 9.3.0 voir 9.3.1 ?
Shared_buffers à 1/4 de RAM, Maintenance_work_mem à 1/8 de RAM, Effective_cache_size à 2/3 de RAM sont-ils toujours de bonnes bases ?
Checkpoint_completion_target et Random_page_cost ont-ils une influence ?
Plus généralement, certains paramètres ont-ils "évolué" ? ou le fait de les laisser à des valeurs par défaut peut-il avoir une incidence ?
Pouvez-vous orienter nos recherches ?
D'avance merci pour les réponses.
Bonjour à tous,
J'ajoute ci-dessous les traces des checkpoints :
2013-10-25 11:35:33 CEST [32375]: [27-1] user=,db= LOG: checkpoint starting: time
2013-10-25 11:40:08 CEST [32375]: [28-1] user=,db= LOG: checkpoint complete: wrote 2752 buffers (0.3%); 0 transaction log file(s) added, 0 removed, 0 recycled; write=275.412 s, sync=0.015 s, total=275.429 s; sync files=48, longest=0.002 s, average=0.000 s
2013-10-25 11:45:33 CEST [32375]: [29-1] user=,db= LOG: checkpoint starting: time
2013-10-25 11:50:33 CEST [32375]: [30-1] user=,db= LOG: checkpoint complete: wrote 23702 buffers (2.3%); 0 transaction log file(s) added, 0 removed, 2 recycled; write=299.263 s, sync=0.020 s, total=299.287 s; sync files=53, longest=0.002 s, average=0.000 s
2013-10-25 11:55:33 CEST [32375]: [31-1] user=,db= LOG: checkpoint starting: time
[postgres@geo-jouve-ce pg_log]$ grep checkpoint 5-12.log
2013-10-25 12:00:33 CEST [32375]: [32-1] user=,db= LOG: checkpoint complete: wrote 31090 buffers (3.0%); 0 transaction log file(s) added, 0 removed, 18 recycled; write=299.915 s, sync=0.030 s, total=299.949 s; sync files=40, longest=0.004 s, average=0.000 s
2013-10-25 12:05:33 CEST [32375]: [33-1] user=,db= LOG: checkpoint starting: time
2013-10-25 12:10:33 CEST [32375]: [34-1] user=,db= LOG: checkpoint complete: wrote 30919 buffers (2.9%); 0 transaction log file(s) added, 0 removed, 21 recycled; write=299.787 s, sync=0.025 s, total=299.816 s; sync files=47, longest=0.004 s, average=0.000 s
J'ajoute également les snapshots de Pg_database :
to_char;sum_read;sum_hit
11:36:01;4558;500031
11:38:01;213219;17744339
11:40:01;232485;23885985
11:42:02;277468;40755820
11:44:01;307388;118257390
11:46:01;315632;119598947
11:48:01;317265;193124626
11:50:01;319015;194256264
11:52:01;328456;202149667
11:54:01;336597;292555394
11:56:01;339588;361303798
11:58:01;341211;441672148
12:00:01;342722;456526614
12:02:01;345178;460772733
12:04:01;352200;611444058
12:06:01;352677;689441976
12:08:01;352681;689442662
12:10:01;352681;759558216
Ainsi que les snapshots de Pg_bgwriter :
to_char;buffers_checkpoint;buffers_clean;buffers_backend
11:36:01;107182;0;1145946
11:38:01;108381;0;1148873
11:40:01;109579;0;1151036
11:42:02;109647;0;1151995
11:44:01;109647;0;1151995
11:46:01;111867;0;1161241
11:48:01;121356;0;1162532
11:50:01;130837;0;1164149
11:52:01;133349;0;1164339
11:54:01;133349;0;1164339
11:56:01;136329;0;1176265
11:58:01;148767;0;1177794
12:00:01;161205;0;1179243
12:02:01;164439;0;1180273
12:04:01;164439;0;1180273
12:06:01;167357;0;1189070
12:08:01;179734;0;1189074
12:10:01;192103;0;1189074
Bonjour Julien,
Merci pour votre réponse.
Il va être compliqué de faire le explain sur "l'ancienne version", suite à l'ajout de RAM, des disques, des changements de système de fichiers.
Voici le résultat du explain (analyse,buffers) sur la nouvelle configuration :
Nested Loop (cost=499394.97..527258.36 rows=1 width=238) (actual time=8182.900..741677.534 rows=1234501 loops=1)
Join Filter: ((pe.id_groupe)::text = (g.id_groupe)::text)
Rows Removed by Join Filter: 49380040
Buffers: shared hit=76634330
-> Nested Loop (cost=499393.05..527165.11 rows=1 width=213) (actual time=8182.664..68591.230 rows=1234501 loops=1)
Buffers: shared hit=26019788
-> Nested Loop (cost=499392.91..527164.95 rows=1 width=209) (actual time=8182.658..64825.431 rows=1234501 loops=1)
Buffers: shared hit=23550786
-> Nested Loop (cost=499392.77..527164.78 rows=1 width=200) (actual time=8182.651..61559.353 rows=1234501 loops=1)
Buffers: shared hit=21081784
-> Nested Loop (cost=499392.50..527164.47 rows=1 width=188) (actual time=8182.640..56537.030 rows=1234501 loops=1)
Buffers: shared hit=17376725
-> Nested Loop (cost=499392.23..527164.17 rows=1 width=180) (actual time=8182.630..51494.816 rows=1234501 loops=1)
Buffers: shared hit=13673222
-> Nested Loop (cost=499392.10..527164.01 rows=1 width=165) (actual time=8182.623..48442.985 rows=1234501 loops=1)
Buffers: shared hit=11204220
-> Nested Loop (cost=499391.82..527163.70 rows=1 width=118) (actual time=8182.611..42051.029 rows=1234594 loops=1)
Buffers: shared hit=7494687
-> Merge Join (cost=499391.67..527162.81 rows=5 width=107) (actual time=8182.597..37233.338 rows=1234594 loops=1)
Merge Cond: (((li.id_ligne)::text = (ptg.id_ligne)::text) AND ((ac.id_plan)::text = (ptg.id_plan)::text) AND ((ac.id_fonction)::
text = (ptg.id_fonction)::text) AND ((ac.id_operation)::text = (ptg.id_operation)::text))
Join Filter: (ac.date_fin_valide = (SubPlan 1))
Buffers: shared hit=5025499
-> Merge Join (cost=11.13..6431.03 rows=52777 width=69) (actual time=0.034..103.287 rows=52759 loops=1)
Merge Cond: ((ac.id_ligne)::text = (li.id_ligne)::text)
Buffers: shared hit=51819
-> Index Scan using activite_lpfo on activite ac (cost=0.41..5536.99 rows=52777 width=47) (actual time=0.019..52.968 row
s=52759 loops=1)
Filter: (((id_site)::text = 'TANA'::text) OR ((id_site)::text = '*'::text))
Buffers: shared hit=51817
-> Materialize (cost=0.14..12.86 rows=41 width=22) (actual time=0.006..4.696 rows=52774 loops=1)
Buffers: shared hit=2
-> Index Scan using pk_ligne on ligne li (cost=0.14..12.76 rows=41 width=22) (actual time=0.004..0.020 rows=30 loo
ps=1)
Buffers: shared hit=2
-> Sort (cost=498946.25..502071.88 rows=1250252 width=50) (actual time=8182.485..8534.322 rows=1234594 loops=1)
Sort Key: ptg.id_ligne, ptg.id_plan, ptg.id_fonction, ptg.id_operation
Sort Method: quicksort Memory: 179302kB
Buffers: shared hit=28858
-> Bitmap Heap Scan on ptg_pers ptg (cost=26531.52..372334.56 rows=1250252 width=50) (actual time=108.432..472.300 rows=
1234594 loops=1)
Recheck Cond: ((jour >= to_date('20130401 '::text, 'YYYYMMDD'::text)) AND (jour <= to_date('20130430'::text, 'YYYYMM
DD'::text)))
Buffers: shared hit=28858
-> Bitmap Index Scan on ptg_pers_jour_type_ptg_sst (cost=0.00..26218.96 rows=1250252 width=0) (actual time=103.773
..103.773 rows=1234594 loops=1)
Index Cond: ((jour >= to_date('20130401 '::text, 'YYYYMMDD'::text)) AND (jour <= to_date('20130430'::text, 'YY
YYMMDD'::text)))
Buffers: shared hit=3376
SubPlan 1
-> Aggregate (cost=8.44..8.45 rows=1 width=4) (actual time=0.019..0.019 rows=1 loops=1234594)
Buffers: shared hit=4944822
-> Index Scan using activite_lpfo on activite ac2 (cost=0.41..8.44 rows=1 width=4) (actual time=0.017..0.017 rows=1 lo
ops=1234594)
Index Cond: (((id_ligne)::text = (ptg.id_ligne)::text) AND ((id_plan)::text = (ptg.id_plan)::text) AND ((id_foncti
on)::text = (ptg.id_fonction)::text) AND ((id_operation)::text = (ptg.id_operation)::text))
Filter: (date_fin_valide >= ptg.jour)
Buffers: shared hit=4944822
-> Index Scan using pk_operation on operation op (cost=0.15..0.17 rows=1 width=19) (actual time=0.003..0.003 rows=1 loops=1234594)
Index Cond: ((id_operation)::text = (ptg.id_operation)::text)
Buffers: shared hit=2469188
-> Index Scan using pk_personnel on personnel pe (cost=0.28..0.31 rows=1 width=52) (actual time=0.004..0.004 rows=1 loops=1234594)
Index Cond: ((id_perso)::text = (ptg.id_perso)::text)
Filter: (((id_type_oper)::text = '0'::text) OR ((id_type_oper)::text = 'I'::text))
Buffers: shared hit=3709533
-> Index Scan using pk_salaire on salaire sa (cost=0.12..0.15 rows=1 width=19) (actual time=0.001..0.002 rows=1 loops=1234501)
Index Cond: ((id_salaire)::text = (pe.id_salaire)::text)
Buffers: shared hit=2469002
-> Index Scan using pk_plan on plan pl (cost=0.27..0.29 rows=1 width=16) (actual time=0.003..0.003 rows=1 loops=1234501)
Index Cond: ((id_plan)::text = (ptg.id_plan)::text)
Buffers: shared hit=3703503
-> Index Scan using pk_fonction on fonction fo (cost=0.28..0.30 rows=1 width=20) (actual time=0.003..0.003 rows=1 loops=1234501)
Index Cond: ((id_fonction)::text = (ptg.id_fonction)::text)
Buffers: shared hit=3705059
-> Index Scan using pk_type_qte_act on type_qte_act tq (cost=0.14..0.16 rows=1 width=13) (actual time=0.001..0.002 rows=1 loops=1234501)
Index Cond: (id_type_qte_act = ac.id_type_qte_act)
Buffers: shared hit=2469002
-> Index Scan using pk_type_act on type_act ta (cost=0.14..0.16 rows=1 width=7) (actual time=0.002..0.002 rows=1 loops=1234501)
Index Cond: ((id_type_act)::text = (ac.id_type_act)::text)
Buffers: shared hit=2469002
-> Hash Join (cost=1.92..92.72 rows=41 width=37) (actual time=0.007..0.533 rows=41 loops=1234501)
Hash Cond: ((p.id_perso)::text = (g.id_perso)::text)
Buffers: shared hit=50614542
-> Seq Scan on personnel p (cost=0.00..67.34 rows=2634 width=31) (actual time=0.001..0.220 rows=2634 loops=1234501)
Buffers: shared hit=50614541
-> Hash (cost=1.41..1.41 rows=41 width=12) (actual time=0.017..0.017 rows=41 loops=1)
Buckets: 1024 Batches: 1 Memory Usage: 2kB
Buffers: shared hit=1
-> Seq Scan on groupe g (cost=0.00..1.41 rows=41 width=12) (actual time=0.003..0.008 rows=41 loops=1)
Buffers: shared hit=1
Total runtime: 741865.273 ms
Nos tests sont basés, sur une période de 30 minutes, pendant lesquelles :
- un outil fait de l'insert "en masse",
- un autre outil, lancé depuis plusieurs serveurs, exécute différentes requêtes (SELECT et UPDATE), sur différentes tables, avec différents paramètres, à intervalle réguliers.
Entre les changements, nous avons bien fait des vacuum full analyze et reindex.
Effectivement, il y a bien un troisième disque (sdc). Je viens de corriger.
Bonjour à tous,
Suite aux différents posts précédents, je résume notre situation.
Nous avions :
- Cent-OS 5.9, PostgreSQL 9.2.4, 12Go de RAM,
- 1 disque (sda) 300Go, 10000 tours, FS ext3, en mirroir, supportant OS + Moteur Pg + DATA + XLOG + TRACES.
Nous avons maintenant :
- Cent-OS 6.4, PostreSQL 9.3.1, 32Go de RAM,
- disque (sda), 300Go, 10000 tours, FS ext4, en mirroir, supportant OS + Moteur + TRACES,
- disque (sdb), 150Go, 15000 tours, FS ext4, en mirroir, supportant les DATA,
- disque (sdc), 150Go, 15000 tours, FS ext4, en mirroir, supportant les XLOG.
Postgresql.conf avant :
max_connections = 100,
shared_buffers = 3072MB, work_mem = 10MB, maintenance_work_mem = 1536MB
checkpoint_segments = 64, checkpoint_timeout = 10min
effective_cache_size = 8192MB
Postgresql.conf maintenant :
max_connections = 100
shared_buffers = 8192MB, work_mem = 10MB, maintenance_work_mem = 4096MB
checkpoint_segments = 64, checkpoint_timeout = 10min
effective_cache_size = 21840MB
Les statistiques sont maintenant envoyé vers le FS RAM (stats_temp_directory = '/ramcache').
Les traces sont activées de la façon suivante pour pouvoir ensuite faire de l'analyse avec BgBadger :
logging_collector = on
log_directory = '/home/postgres/pg_log', log_filename = '%u-%H.log'
log_truncate_on_rotation = on, log_rotation_age = 1h, log_rotation_size = 0MB
log_min_duration_statement = 0
log_checkpoints = on, log_connections = on, log_disconnections = on
log_line_prefix = '%t [%p]: [%l-1] user=%u,db=%d %h '
log_statement = 'none'
log_lock_waits = on, log_temp_files = 0
track_functions = pl
La base de données fait 11Go.
Globalement, l'ensemble des préconisations mises en place s'avérent bénéfiques :
- Nous faisons davantage d'INSERT (nous sommes passés de 6000 à 10000 inserts par seconde),
- Nous n'écrivons plus de fichiers temporaires sur disque,
- Les temps de réponse sur les requêtes, retournés par PgBadger, sont en amélioration.
Seul point noir, les temps de réponses sur des "gros" SELECT.
Exemple :
SELECT PTG.id_perso, PE.id_perso_cgu, PTG.id_ligne, PTG.id_plan, PTG.id_fonction, PTG.id_operation, PTG.OFP_CPT, PTG.OFS_CPT, to_char(PTG.jour,'dd/mm/yyyy'), PTG.temps, PTG.quantite, PE.nom, PE.prenom, PE.ligne_defaut, PE.id_Salaire, PE.id_type_oper, SA.Variable, SA.Sal_Mini, SA.Sal_Base, SA.Salaire, SA.Sal_Max, LI.libelle, PL.libelle,FO.Libelle,OP.Libelle,TA.id_type_alim_cgu, AC.id_type_ptg, AC.id_type_act, AC.tps_gam, AC.tps_gam_test, AC.taux_h, AC.id_type_coq, AC.id_type_qte_act,AC.envoi_com, TQ.Libelle,FO.taux_h,AC.ID_SITE, G.responsable
FROM geo.Ptg_pers PTG,geo.Personnel PE, geo.Salaire SA, geo.Ligne LI, geo.Plan PL, geo.Fonction FO, geo.Operation OP, geo.Activite AC, geo.Type_Qte_Act TQ, geo.Type_Act TA,(select G.id_groupe,(P.id_perso||' : '||P.nom||' '||P.prenom) as responsable from geo.personnel P, geo.groupe G where P.id_perso=G.id_perso) G
WHERE (PTG.JOUR Between TO_DATE('20130401 ','YYYYMMDD') AND TO_DATE('20130430','YYYYMMDD'))
AND PE.id_perso = PTG.id_perso
AND ((PE.id_type_Oper = '0') OR (PE.id_type_Oper = 'I'))
AND SA.id_salaire = PE.id_Salaire
AND G.id_groupe = PE.id_groupe
AND LI.id_ligne = PTG.id_ligne AND PL.id_plan = PTG.id_plan AND FO.id_fonction = PTG.id_fonction AND OP.id_operation = PTG.id_operation
AND TA.id_type_Act=AC.id_type_act
AND AC.id_ligne = PTG.id_ligne AND AC.id_plan = PTG.id_plan AND AC.id_fonction = PTG.id_fonction AND AC.id_operation = PTG.id_operation
AND (AC.ID_SITE='TANA' OR AC.ID_SITE='*')
AND AC.DATE_FIN_VALIDE=(SELECT min(AC2.DATE_FIN_VALIDE) from geo.ACTIVITE AC2 WHERE AC2.id_ligne = PTG.id_ligne AND AC2.id_plan = PTG.id_plan AND AC2.id_fonction = PTG.id_fonction AND AC2.id_operation = PTG.id_operation AND AC2.DATE_FIN_VALIDE>=PTG.JOUR)
AND TQ.id_type_qte_act = AC.id_type_qte_act;
1.2 million de lignes retournées sur un peu plus de 15 millions dans PTG_PERS.
Avant modification nous avions le retour en 6 minutes, à présent cela prend un peu plus de 8 minutes.
De ce fait, nous avons refait les tests, en remettant tout sur le disque sda.
Le volume d'INSERT reste identique (10000/s), les temps de réponse des gros SELECT aussi, ce qui laisse à penser que le gain viendrait de la RAM.
Vers quelles pistes pouvons nous orienter nos recherches ?
D'avance merci pour vos réponses.
Bonjour,
Une de nos applications, installée sur un site distant du site ou se trouve notre base de données, fait des requêtes qui retournent un gros volume de données.
Existe t'il une méthode qui permettrait de compresser les données avant envoi ?
Quelles techniques existent ?
D'avance merci.
Guillaume,
Oui, l'option -z du vacuumdb, donc les tables sont analysées, le 29/09, entre 1h45 et 3h26.
Pour les indexes, y a t'il les mêmes informations que le n_dead_tup pour les tables ? voir l'évolution de la fragmentation.
Pour la formation, j'en avais fait une il y a quelques années (8.0 ou 8.1), plutôt une introduction à l'administration. Je ne sais pas quelle formation pourrait combler mes lacunes ? plutôt sur le "fonctionnement interne", l'analyse de cas pratiques.
Bon week-end et merci encore.
Bonjour,
Merci messieurs pour les réponses.
L'analyze lui s'exécute bien chaque semaine et sur toutes les tables, alors que certaines ne subissent aucune modification, pour quelle raison ?
Faut-il diminuer le scale_factor du vacuum à 0.1 ? ou faut-il gérer plus finement au niveau des tables ?
Si les compteurs last_vacuum et vacuum_count ne sont pas incrémentés, y-a-t'il un autre endroit où trouver l'information que le vacuum full s'est exécuté en dehors des logs ?
Comment mesurer ces 20% par semaine ? en surveillant, entre 2 dimanches, les compteurs n_tup_upd, n_tup_del et n_tup_hot_upd ? ou n_live_tup et n_dead_tup ?
Si moins de 20% de la table change chaque semaine, un vacuum est-il nécessaire ? ou est-ce que au fil des semaines la table (et ses index) se "dégrade" ?
Je crois que je vais devoir passer DBA à plein temps, lol.
Bonjour,
J'ai un serveur de prod en 9.2.3 sous CentOS 5.4.
Tout les dimanche est programmé un "vacuumdb -a -f -z", suivi d'un "reindexdb -a" puis d'un "reindexdb -s".
En regardant les logs, je vois ces traces :
2013-09-29 01:45:02 EAT [14674]: [1-1] user=[unknown],db=[unknown] LOG: connection received: host=[local]
2013-09-29 01:45:02 EAT [14674]: [2-1] user=postgres,db=geo [local] LOG: connection authorized: user=postgres database=geo
2013-09-29 02:17:54 EAT [14674]: [3-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.0", size 1073741824
2013-09-29 02:17:54 EAT [14674]: [4-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 02:17:54 EAT [14674]: [5-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.1", size 217432064
2013-09-29 02:17:54 EAT [14674]: [6-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 02:46:00 EAT [14674]: [7-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.2", size 1073741824
2013-09-29 02:46:00 EAT [14674]: [8-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 02:46:00 EAT [14674]: [9-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.3", size 505937920
2013-09-29 02:46:00 EAT [14674]: [10-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 03:03:44 EAT [14674]: [11-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.4", size 1073741824
2013-09-29 03:03:44 EAT [14674]: [12-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 03:03:45 EAT [14674]: [13-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.5", size 167059456
2013-09-29 03:03:45 EAT [14674]: [14-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 03:20:14 EAT [14674]: [15-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.6", size 583753728
2013-09-29 03:20:14 EAT [14674]: [16-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 03:26:11 EAT [14674]: [17-1] user=postgres,db=geo [local] LOG: temporary file: path "base/pgsql_tmp/pgsql_tmp14674.7", size 441016320
2013-09-29 03:26:11 EAT [14674]: [18-1] user=postgres,db=geo [local] STATEMENT: VACUUM (FULL, ANALYZE);
2013-09-29 03:26:24 EAT [14674]: [19-1] user=postgres,db=geo [local] LOG: duration: 6081940.220 ms statement: VACUUM (FULL, ANALYZE);
2013-09-29 03:26:24 EAT [14674]: [20-1] user=postgres,db=geo [local] LOG: disconnection: session time: 1:41:21.943 user=postgres database=geo host=[local]
Lorsque je fais la requête suivante (sur la plus grosse de mes tables) :
select * from pg_stat_user_tables where relname='ptg_pers';
J'obtiens en réponse :
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
-------+------------+----------+----------+--------------+-----------+---------------+-----------+-----------+-----------+---------------+------------+------------+-------------+-
----------------+-------------------------------+-------------------------------+--------------+------------------+---------------+-------------------
16800 | geo | ptg_pers | 82518 | 212479893776 | 275806381 | 19986180460 | 22160277 | 37318526 | 6406037 | 55565 | 15752700 | 1258080 | |
| 2013-09-29 03:26:23.178792+03 | 2013-09-27 13:41:29.194096+03 | 0 | 0 | 27 | 23
Pas d' autovacuum, juste un autoanalyze.
Les paramètres de mon postgresql.conf sont :
#vacuum_cost_delay = 0ms
#vacuum_cost_page_hit = 1
#vacuum_cost_page_miss = 10
#vacuum_cost_page_dirty = 20
#vacuum_cost_limit = 200
#track_counts = on
#autovacuum = on
log_autovacuum_min_duration = 300
#autovacuum_max_workers = 3
#autovacuum_naptime = 1min
#autovacuum_vacuum_threshold = 50
#autovacuum_analyze_threshold = 50
#autovacuum_vacuum_scale_factor = 0.2
#autovacuum_analyze_scale_factor = 0.1
#autovacuum_freeze_max_age = 200000000
#autovacuum_vacuum_cost_delay = 20ms
#autovacuum_vacuum_cost_limit = -1
N'y aurait-il jamais d' autovacuum ?
Merci pour vos réponses.
Bonjour Pitpoule,
Merci pour votre réponse.
Avez-vous une réponse pour ma deuxième question ?
Bonjour Guillaume,
Effectivement, je n'avais pas compris.
Pouvez-vous me dire pourquoi "3*" ?
Sur ma base de 40Go, si je fais un vacuum full puis un reindex, est-il possible de prévoir le volume d'occupation disque que cela va engendrer dans pg_xlog ? et dans le répertoire des logs archivés ?
J'espère ne pas trop monopoliser de votre temps et encore merci pour votre aide.
Bonjour Guillaume,
Je reviens sur ce sujet.
Il s'agit bien de 3 systèmes disques en RAID.
Nous allons activer l'archivage des logs, sur quel disque préconisez-vous de mettre les logs archivés ?
Bonjour,
Nous travaillons à la migration d'une base de données de 40 Go, d'un moteur 8.2.4 à 9.2.4 sous CentOS 5.9.
Dans le fichier postgresql.conf, nous avons défini le checkpoint_segments à 32. Toutefois dans le répertoire pg_xlog, je vois 66 fichiers.
Est-ce que la valeur du paramètre n'est pas assez haute ?
Est-ce que PostgreSQL utilise "un peu" plus de fichiers au besoin ?
Nous allons activer l'archivage des fichiers wal, et le week-end, nous allons faire tourner un script de maitenance qui effectue :
- vacuumdb -a -f -z
- reindexdb -a
Cela va t'il généré davantage de fichiers dans pg_xlog ? ou est-ce uniquement le répertoire des logs archivés qui va grossir ?
Notre script de maintenance est-il toujours d'actualité en 9.2, à savoir faut-il toujours faire un vacuum full ? et un reindex de toutes les bases ?
D'avance merci pour les réponses.
Bonjour Guillaume,
Pour le "Quid", je voulais dire de façon générale quelles sont les bonnes pratiques ?
Bonjour Guillaume,
Dans le cadre de l'amélioration des performances suite aux premiers tests de charge, nous allons :
- passer la RAM à 32Go.
- réinstaller le serveur en CentOS 6 pour avoir un système de fichiers EXT4 sur le disque pour les data et le disque pour les xlog, ainsi qu'un système de fichiers en RAM pour les stats.
- Installer la version 9.3.
Nous ferons ensuite de nouveaux tests de charge.
Merci encore pour les infos et toute l'aide que vous nous apportez.
Bonjour Guillaume,
Ok merci pour la réponse. Encore du boulot 
.
Bonjour,
Nous travaillons sur la migration d'une base 8.2.4 vers 9.2.4 sous CentOS 5.9.
Nous avons des problèmes de casts sur certaines requêtes :
ERROR: operator does not exist: numeric <= text
LINE 6: and A.debut_periode<=to_char(P.jour,'yyyymmdd')
^
HINT: No operator matches the given name and argument type(s). You might need to add explicit type casts.
Y-a-t'il un moyen de contournement ? peut être avec un paramètre dans le postgresql.conf ?
D'avance merci pour les réponses.
