Forums PostgreSQL.fr

mortimer.pw

Membre

Résultats après optimisation

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.

Dernière modification par mortimer.pw (25/10/2013 10:38:25)

rjuju

Administrateur

Re : Résultats après optimisation

Vous devriez faire un EXPLAIN (ANALYZE, BUFFERS) sur chacun des serveurs. Comme la version majeure est différente, cela suppose un dump/restore, le cache n'est sans doute pas aussi bien rempli. De plus, avez-vous fait un VACUUM ANALYZE ?

Vous parlez également de disques en miroir, quelle est la technologie employée ? Vous avez aussi spécifié 2 fois /dev/sdb pour les PGDATA et les WAL, s'agit-il du même disque ou d'une typo ?

---

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

mortimer.pw

Membre

Re : Résultats après optimisation

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.

mortimer.pw

Membre

Re : Résultats après optimisation

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

mortimer.pw

Membre

Re : Résultats après optimisation

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.

mortimer.pw

Membre

Re : Résultats après optimisation

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.

Ansari443

Membre

Re : Résultats après optimisation

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 ?

---

ali