PostgreSQL La base de donnees la plus sophistiquee au monde.

Forums PostgreSQL.fr

Le forum officiel de la communauté francophone de PostgreSQL

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

#1 17/07/2019 17:01:40

coucou78187
Membre

perte de performances près modification de configuration

Bonjour à tous,

suite à une modification de la conf :


avant :

work_mem = '8MB'
maintenance_work_mem = '64MB'
min_wal_size = '80GB'
max_wal_size = '1GB'
checkpoint_timeout = '5min'
checkpoint_completion_target = '0.5'
effective_io_concurrency = '0'
wal_buffers = '16MB'
default_statistics_target = '100'
random_page_cost='1'


après :

work_mem = '16MB'
maintenance_work_mem = '128MB'
min_wal_size = '1GB'
max_wal_size = '2GB'
checkpoint_timeout = '10min'
checkpoint_completion_target = '0.9'
effective_io_concurrency = '20'
wal_buffers = '32MB'
default_statistics_target = '1000'
random_page_cost='1'

puis un arrêt relance de l'instance, il est à noter une baisse générale des performances...


contexte :

centOS7
PgSQL 10.9
ram 32go
ssd


les requêtes en générale sont plus longues (environ 20%)


à noter : l'extension pg_stat_statements a été ajoutée et donc après le redémarrage prise en compte 
cette extension a été installée sur toutes les BDD du cluster (environ une dizaine).
elle vient d'être retirée et laissée que sur la base postgres.


quelques exemples :

une requête exécutée environ 100 fois  avant et après changement (average selon pgbadger) :


avant : 16s
après : 21s



J'ai pensé au cache, mais cela fait un moment que les modifs ont eu lieu


les paramètres  positionnés ne me paraissaient pas incohérent et pouvant jouer sur les perfs de manière négative...


l'xtension pg_stat_statements peut elle être aussi impactante si installée sur nombre de bdd ?


sinon y aurait-il d'autres pistes ?


Merci

Hors ligne

#2 17/07/2019 21:41:41

rjuju
Administrateur

Re : perte de performances près modification de configuration

Bonjour,


Avec les éléments que vous fournissez, il est impossible de donner un quelconque avis pour la majorité des changements.  Le fait d'effectuer autant de changement portant sur tellement de choses différentes rend également impossible toute analyze.  La seule chose que je peux vous dire c'est que :

default_statistics_target = '1000'


me semble idéal pour ralentir les performances de manière globale.  Quel(s) problème(s) cherchiez-vous à corriger avec ce changement ?


Concernant pg_stat_statements (qui n'apparait pas sur la liste des changements soit dit en passant, si vous l'avez vraiment configurée), cela aura bien évidemment un impact sur les performances.  Au passage, l'extension n'est activée que globalement sur l'instance en la rajoutant dans shared_preload_libraries.  Le fait de créer l'extension sur une ou plusieurs base de données ne change absolument rien, ce ne sont que des fonctions permettant d'accéder aux compteurs (même si bien évidemment appeler ces compteurs à très haute fréquence posera des problèmes).

Hors ligne

#3 18/07/2019 09:38:33

coucou78187
Membre

Re : perte de performances près modification de configuration

Bonjour Julien,


merci pour le retour.


concernant les motivations :


augmentation work_mem car beaucoup de fichier temporaires sont utilisé lors d'opérations de tris (le paramétrer au niveau transactionnel est aussi en cours)
en effet environ 4Go de fichier temp sont générés chaque 2 heures par un job et de nuit on monte a 13Go pour un job en particulier. par ailleurs j'ai eu le cas où une requête de tri était plus rapide en faisant son tri sur disque qu'en mémoir ( je le relaterai dans un futur post  :-) )


augmentation maintenance_work_mem  car des opérations de create index assez longs (35 secondes à relativiser) lors de jobs sont réalisés et pour donner plus de mémoire aux opérations de vacuum sur des tables volumineuses avec plusieurs millions de llignes.


augmentations min_wal_size  et max_wal_size car des messages de checkpoints trop fréquents arrivaient des dizaines de fois de nuit lors d'un job depuis ça a grandement diminué.



augmentation checkpoint_timeout  et checkpoint_completion_target afin d'espacer les checkpoints et "lisser"  plus dans le temps les écritures sur disque.



augmentation effective_io_concurrency  car il s'agit de disques SSD (même si cela n'affecte que les bitmapscans à priori)


augmentation wal_buffers pour accorder plus de mémoire aux opérations non encore écrites dans les wal car il y a beaucoup d'écriture sur des tables  (relevé de température par timestamp donc beaucoup)



default_statistics_target à la base, justement pour affiner les stats collectées



peut etre que le paramètre wal_buffers peut avoir joué un tour aussi?


Merci

Hors ligne

#4 18/07/2019 09:49:12

rjuju
Administrateur

Re : perte de performances près modification de configuration

avant :

min_wal_size = '80GB'

après :

min_wal_size = '1GB'
[...]
augmentations min_wal_size  et max_wal_size car des messages de checkpoints trop fréquents arrivaient des dizaines de fois de nuit lors d'un job depuis ça a grandement diminué.

Je suis d'accord sur le principe, mais ça ne correspond pas à ce que vous annoncez.


en effet environ 4Go de fichier temp sont générés chaque 2 heures par un job et de nuit on monte a 13Go pour un job en particulier.

La solution idéale serait plutôt d'avoir un utilisateur spécifique pour ces job, qui lui disposerait d'un work_mem (bien) plus important, voire d'une limite sur le nombre de connexion.  Je ne connais pas la totalité de votre paramétrage, mais il est possible que ce changement puisse engendrer des erreurs de type "out of memory" voire déclenchement d'un OOM killer si l'overcommit est activé sur votre serveur.


default_statistics_target à la base, justement pour affiner les stats collectées

Encore une fois, quel(s) problème(s) cherchiez vous à résoudre ?


peut etre que le paramètre wal_buffers peut avoir joué un tour aussi?

Non, cela ne consomme que 16 Mo supplémentaires, et l'effet sur les performances sera quelque part entre "aucun" et "légèrement améliorer des opérations de chargement en masse".

Hors ligne

#5 18/07/2019 10:06:48

coucou78187
Membre

Re : perte de performances près modification de configuration

Julien ,


Merci pour le retour rapide.


rjuju a écrit :

Je suis d'accord sur le principe, mais ça ne correspond pas à ce que vous annoncez.


désolé, il y a eu une coquille, il s'agit là bien des paramètres par défaut :


avant :
min_wal_size = '80MB'
après :
min_wal_size = '1GB'



rjuju a écrit :

Encore une fois, quel(s) problème(s) cherchiez vous à résoudre ?


je vais ici alors déposé un exemple de requête et ses explains avec et sans tri en mémoire quand j'aurai accès à celà


Merci

Hors ligne

#6 18/07/2019 11:08:36

coucou78187
Membre

Re : perte de performances près modification de configuration

Julien,



Voici la requête :


select count(distinct r.colonne1::date), r.colonne2 ,r.colonne3 ,r.colonne4,min(-(r.colonne1::date -  current_date))
from releve_temp r
where r.colonne1 between '2019-01-11 07:10:00.405934' and '2019-01-18 07:10:00.405934'
and r.colonne3 =  ANY ('{116565,6546561,875626,16546151,65461565,4654656,6465461,6546165,654165,1651635}'::integer[])
group by r. colonne2,r.colonne4,r.colonne3;


un index sur la clé de tri a été testé mais pas concluant.


ci-dessous les explains avec work_mem='8MB' et work_mem = '4GB' (pour "forcer" un tri en mémoire).


avec work_mem = '16mb' on est entre les deux (8240.719 ms) et un explain similaire à la config work_mem = '8mb'.


la table est partitionnée par date (mois) et un index btree composite sur (colonne1 desc, colonne3)


aussi, les stats me paraissent à peu près à jour (vacuum analyze manuel réalisé)


l'objectif est d'optimiser la requête.


j'ai remarqué une fragmentation des feuilles à 100% pour l'index index_releve_temp_colonne1_colonne3:



version | tree_level | index_size | root_block_no | internal_pages | leaf_pages | empty_pages | deleted_pages | avg_leaf_density | leaf_fragmentation
---------+------------+------------+---------------+----------------+------------+-------------+---------------+------------------+--------------------
       2 |          3 | 3093798912 |         45180 |           2453 |     375207 |           0 |             0 |            53.29 |                100



concernant la table :


table_len  | tuple_count | tuple_len  | tuple_percent | dead_tuple_count | dead_tuple_len | dead_tuple_percent | free_space | free_percent
------------+-------------+------------+---------------+------------------+----------------+--------------------+------------+--------------
9103474688 |    57784782 | 8556594164 |         93.99 |                0 |              0 |                  0 |   58484472 |         0.64





set work_mem = '8MB';

GroupAggregate  (cost=2023043.46..2063380.33 rows=407047 width=85) (actual time=6157.856..7899.641 rows=467497 loops=1)
   Group Key: r.colonne2, r.colonne4, r.colonne3
   Buffers: shared hit=574976, temp read=11850 written=11869
   ->  Sort  (cost=2023043.46..2026340.41 rows=1318778 width=81) (actual time=6157.823..7029.107 rows=988089 loops=1)
         Sort Key: r.colonne2, r.colonne4, r.colonne3
         Sort Method: external merge  Disk: 94800kB
         Buffers: shared hit=574976, temp read=11850 written=11869
         ->  Gather  (cost=361349.92..1852922.60 rows=1318778 width=81) (actual time=1596.185..3674.164 rows=988089 loops=1)
               Workers Planned: 2
               Workers Launched: 2
               Buffers: shared hit=574976
               ->  Result  (cost=360349.92..1725539.71 rows=549491 width=81) (actual time=1592.205..3868.810 rows=329363 loops=3)
                     Buffers: shared hit=574976
                     ->  Append  (cost=360349.92..1720044.80 rows=549491 width=81) (actual time=1592.204..3828.689 rows=329363 loops=3)
                           Buffers: shared hit=574976
                           ->  Parallel Bitmap Heap Scan on releve_temp r  (cost=360349.92..1720044.80 rows=549491 width=81) (actual time=1592.203..3801.775 rows=329363 loops=3)
                                 Recheck Cond: ((date >= '2019-01-11 07:10:00.405934'::timestamp without time zone) AND (date <= '2019-01-18 07:10:00.405934'::timestamp without time zone))
                                 Rows Removed by Index Recheck: 149
                                 Filter: colonne3( = ANY ('{116565,6546561,875626,16546151,65461565,4654656,6465461,6546165,654165,1651635}'::integer[]))
                                 Rows Removed by Filter: 7114210
                                 Heap Blocks: exact=24953 lossy=96668
                                 Buffers: shared hit=574976
                                 ->  Bitmap Index Scan on index_releve_temp_colonne1_colonne3 (cost=0.00..360020.23 rows=21772266 width=0) (actual time=1558.752..1558.752 rows=22330719 loops=1)
                                       Index Cond: ((date >= '2019-01-11 07:10:00.405934'::timestamp without time zone) AND (date <= '2019-01-18 07:10:00.405934'::timestamp without time zone))
                                       Buffers: shared hit=144999
Planning time: 0.719 ms
Execution time: 7920.274 ms






set work_mem = '4GB';

GroupAggregate  (cost=1987074.38..2027412.90 rows=407047 width=85) (actual time=8889.551..10203.305 rows=467497 loops=1)
   Group Key: r.colonne2, r.colonne4, r.colonne3
   Buffers: shared hit=574976
   ->  Sort  (cost=1987074.38..1990371.48 rows=1318838 width=81) (actual time=8889.511..9224.192 rows=988089 loops=1)
         Sort Key: r.colonne2, r.colonne4, r.colonne3
         Sort Method: quicksort  Memory: 163527kB
         Buffers: shared hit=574976
         ->  Gather  (cost=361365.89..1853008.99 rows=1318838 width=81) (actual time=1758.646..4342.514 rows=988089 loops=1)
               Workers Planned: 2
               Workers Launched: 2
               Buffers: shared hit=574976
               ->  Result  (cost=360365.89..1725620.35 rows=549516 width=81) (actual time=1756.352..4298.310 rows=329363 loops=3)
                     Buffers: shared hit=574976
                     ->  Append  (cost=360365.89..1720125.19 rows=549516 width=81) (actual time=1756.350..4251.963 rows=329363 loops=3)
                           Buffers: shared hit=574976
                           ->  Parallel Bitmap Heap Scan on on releve_temp r  (cost=360365.89..1720125.19 rows=549516 width=81) (actual time=1756.350..4220.543 rows=329363 loops=3)
                                 Recheck Cond: ((date >= '2019-07-11 07:10:00.405934'::timestamp without time zone) AND (date <= '2019-07-18 07:10:00.405934'::timestamp without time zone))
                                 Filter: colonne3( = ANY ('{116565,6546561,875626,16546151,65461565,4654656,6465461,6546165,654165,1651635}'::integer[]))
                                 Rows Removed by Filter: 7114210
                                 Heap Blocks: exact=135246
                                 Buffers: shared hit=574976
                                 ->  Bitmap Index Scan on index_releve_temp_colonne1_colonne3  (cost=0.00..360036.18 rows=21773262 width=0) (actual time=1579.312..1579.312 rows=22330719 loops=1)
                                       Index Cond: ((date >= '2019-01-11 07:10:00.405934'::timestamp without time zone) AND (date <= '2019-01-18 07:10:00.405934'::timestamp without time zone))
                                       Buffers: shared hit=144999
Planning time: 0.460 ms
Execution time: 10248.814 ms




Merci.

Hors ligne

#7 18/07/2019 11:16:09

coucou78187
Membre

Re : perte de performances près modification de configuration

rjuju a écrit :

Encore une fois, quel(s) problème(s) cherchiez vous à résoudre ?


il existait une différence significative entre les rows retournés estimés et rééls (surestimation, il estimait environ 1200000 lignes hors il en retourne environ 470000)


après un vacuum analyze, c'est mieux:


(cost=1987074.38..2027412.90 rows=407047 width=85) (actual time=8889.551..10203.305 rows=467497 loops=1)


Merci

Hors ligne

#8 18/07/2019 11:36:08

rjuju
Administrateur

Re : perte de performances près modification de configuration

Et un vacuum analyze sur la ou les tables impactées sans changer le default_statistic_target ne corrigeait pas l'estimation ?  Ce problème d'estimation entrainait-il un changement de plan ?  Pourquoi ne pas changer la valeur pour la ou les tables impactées uniquement ?

Hors ligne

#9 18/07/2019 11:46:06

coucou78187
Membre

Re : perte de performances près modification de configuration

Julien,


Pour info, le paramètre avait été configuré à la base uniquement sur les colonne1 et colonne3, puis élargi à l'ensemble un cours laps de temps

Non cela n'entrainait pas de changement de plan mais avec un échantillonage plus élevé j'espérais plus de précision.


le paramètre a été replacé par défaut (100)


Merci,

Hors ligne

#10 18/07/2019 14:20:55

coucou78187
Membre

Re : perte de performances près modification de configuration

Julien,


le phénomène que je n'arrive pas a expliquer par ailleurs est le fait qu'un "external merge  Disk" soit plus rapide qu'un "quicksort  Memory" car c'est sur ce noeud que ce joue une partie de la différence...


bien que la quantité de données traitée soit différente (94800kB Vs 163527kB).


Aussi j'imagine que l'utilisation d'un HashAggregate à la place du GroupAggregate n'est pas possible ici et utiliserais trop de mémoire...


le count(distinct ) ne facilite pas...


Merci

Hors ligne

#11 19/07/2019 13:13:43

dverite
Membre

Re : perte de performances près modification de configuration

le phénomène que je n'arrive pas a expliquer par ailleurs est le fait qu'un "external merge  Disk" soit plus rapide qu'un "quicksort  Memory" car c'est sur ce noeud que ce joue une partie de la différence...

La machine a seulement 32GB, donc ces allocations de 4GB posent peut-être des difficultés à l'OS qui l'obligent à écrire des buffers disque en urgence pour libérer de la mémoire ou à swapper. Surtout si les 4GB se trouvent multipliés puisque comme dit la doc:

De plus, de nombreuses sessions peuvent exécuter de telles opérations simultanément. La mémoire totale utilisée peut, de ce fait, atteindre plusieurs fois la valeur de work_mem ; il est nécessaire de garder cela à l'esprit lors du choix de cette valeur.

Là vous faites peut-être des tests sur un serveur isolé, mais dans une utilisation normale, mettre 1/8 de la RAM dans le postgresql.conf pour work_mem est une mauvaise idée. Si une requête a besoin d'un work_mem particulier, on peut faire un SET work_mem TO valeur dans la session pour limiter le champ d'application à cette session.


Par ailleurs la partie écrite sur disque dans le cas du "external merge Disk" n'est pas énorme, moins de 100MB apparemment, un SSD peut faire ça en une fraction de seconde, et est-ce que ces données temporaires qui ne sont utilisées que quelques secondes atterrissent physiquement sur le disque d'ailleurs? Si ça se trouve, tout se passe en cache disque.


Si le quick sort s'avère consommer 167 MB pourquoi ne pas réessayer avec un work_mem beaucoup plus proche de cette valeur plutôt que 4GB ?

Hors ligne

#12 19/07/2019 13:51:54

coucou78187
Membre

Re : perte de performances près modification de configuration

Bonjour Daniel,


merci pour le retour  smile


La machine a seulement 32GB, donc ces allocations de 4GB posent peut-être des difficultés à l'OS qui l'obligent à écrire des buffers disque en urgence pour libérer de la mémoire ou à swapper. Surtout si les 4GB se trouvent multipliés puisque comme dit la doc:


Le paramètre a bien été testé uniquement pour la session. Il n'y a pas eu de swap sur la machine.
Pour certaines requêtes ce paramètre a même été positionné au niveau transaction (set local work_mem). le 4GB était vraiment pour le test empirique.



Par ailleurs la partie écrite sur disque dans le cas du "external merge Disk" n'est pas énorme, moins de 100MB apparemment, un SSD peut faire ça en une fraction de seconde, et est-ce que ces données temporaires qui ne sont utilisées que quelques secondes atterrissent physiquement sur le disque d'ailleurs? Si ça se trouve, tout se passe en cache disque.  Si le quick sort s'avère consommer 167 MB pourquoi ne pas réessayer avec un work_mem beaucoup plus proche de cette valeur plutôt que 4GB ?


Avec work_mem= 200MB pour la session on fait bien un quicksort et la requête est toujours moins rapide qu'avec work_mem=16MB (environ 2sec d'écart 8s/10s - exécution 3x chacun).
je trace aussi les fichiers temp dans les logs, à priori ca arrive bien dans les logs :

LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp16217.8", size 97097841



je n'arrive pas à l'expliquer...


Merci

Hors ligne

#13 19/07/2019 13:56:57

coucou78187
Membre

Re : perte de performances près modification de configuration

Aussi,  Pour info


j'ai remarqué un comportement très différent sur les checkpoints depuis la modification de configuration (Normal)


je me demande si celà peut jouer sur les perfs


rappel,


avant :


min_wal_size = '80MB'
max_wal_size = '1GB'
checkpoint_timeout = '5min'
checkpoint_completion_target = '0.5'




après :


min_wal_size = '1GB'
max_wal_size = '2GB'
checkpoint_timeout = '10min'
checkpoint_completion_target = '0.9'




je vais essayé de mettre les métriques sachant que j'ai des graphs plus parlant mais mettre des pièces jointes est compliqué sur le forum



Merci

Hors ligne

#14 19/07/2019 14:28:09

dverite
Membre

Re : perte de performances près modification de configuration

Si on regarde exactement le noeud de tri dans les 2 cas, via le explain analyze:
Cas 1:

work_mem = '8MB';


GroupAggregate  (cost=2023043.46..2063380.33 rows=407047 width=85) (actual time=6157.856..7899.641 rows=467497 loops=1)
   Group Key: r.colonne2, r.colonne4, r.colonne3
   Buffers: shared hit=574976, temp read=11850 written=11869
   ->  Sort  (cost=2023043.46..2026340.41 rows=1318778 width=81) (actual time=6157.823..7029.107 rows=988089 loops=1)
         Sort Key: r.colonne2, r.colonne4, r.colonne3
         Sort Method: external merge  Disk: 94800kB


7029 - 6157 = 870 ms pour faire le tri


Cas 2:

  set work_mem = '4GB';

GroupAggregate  (cost=1987074.38..2027412.90 rows=407047 width=85) (actual time=8889.551..10203.305 rows=467497 loops=1)
   Group Key: r.colonne2, r.colonne4, r.colonne3
   Buffers: shared hit=574976
   ->  Sort  (cost=1987074.38..1990371.48 rows=1318838 width=81) (actual time=8889.511..9224.192 rows=988089 loops=1)
         Sort Key: r.colonne2, r.colonne4, r.colonne3
         Sort Method: quicksort  Memory: 163527kB
         Buffers: shared hit=574976


9224 - 8889 = 335 ms pour faire le tri


Le tri lui-même est plus rapide en mémoire que sur disque, conformément à ce qu'on peut attendre.

Au moment de commençer le tri, la requête avec le work_mem à 4GB semble déjà bien en retard par rapport à l'autre configuration, et c'est ce retard là qui semble jouer dans la différence totale entre les deux requêtes, plus que l'étape de tri.

Mais il y a une chose qui n'est pas claire pour moi, c'est si vous comparez uniquement des work_mem différents ou si vous comparez toujours deux configurations différentes sur de multiples paramètres comme au début du post.

Hors ligne

#15 19/07/2019 15:15:31

coucou78187
Membre

Re : perte de performances près modification de configuration

Daniel,


J'ai comparé les requêtes uniquement sur le paramètre work_mem sans changer d'autre conf.

La question des checkpoints, elle, est relative au ralentissement générale subi après un A/R et des changement d'autre paramètres de conf précédemment.



Concernant le temps d'execution des tris je me suis basé sur les stats données par depesz (exclusive) :



work_mem= 8MB :


node type                                    count       sum of times         % of query
Append                                        1                26.914 ms         0.3 %
Bitmap Index Scan                        1             1,558.752 ms        19.7 %
Gather                                        1           0.000 ms              0.0 %
GroupAggregate                             1           870.534 ms            11.0 %
Parallel Bitmap Heap Scan                 1             2,243.023 ms            28.4 %
Result                                         1                40.121 ms                0.5 %
Sort                                                 1               3,354.943 ms             42.5 %



work_mem= 4GB :


node type                                                                    count       sum of times         % of query
Append                                                                       1                31.420 ms              0.3 %
Bitmap Index Scan                                                       1              1,579.312 ms              15.5 %
Gather                                                                       1               44.204 ms               0.4 %
GroupAggregate                                                               1                979.113 ms               9.6 %
Parallel Bitmap Heap Scan on on releve_temp r               1                2,641.231 ms       25.9 %
Result                                                                       1                   46.347 ms                0.5 %
Sort                                                                               1                  4,881.678 ms       47.8 %



C'est curieux...

Hors ligne

#16 19/07/2019 15:40:59

coucou78187
Membre

Re : perte de performances près modification de configuration

Concernant le sujet des checkpoints,


pour rappel :



avant :


min_wal_size = '80MB'
max_wal_size = '1GB'
checkpoint_timeout = '5min'
checkpoint_completion_target = '0.5'




après :


min_wal_size = '1GB'
max_wal_size = '2GB'
checkpoint_timeout = '10min'
checkpoint_completion_target = '0.9'


Dans les 2 posts suivants je vais vous faire parvenir les stats AVANT/APRES à ce niveau Checkpoint buffers, checkpoint files et checkpoint distance

Hors ligne

#17 19/07/2019 15:44:42

coucou78187
Membre

Re : perte de performances près modification de configuration

AVANT


checkpoint Buffers (Avant)


Hour             Writtenbuff            Write time                 Sync time              total time
00                  76,944                1,798.573s                 0.324s                 1,799.007s
01                 39,530                 1,798.737s                 0.293s                 1,799.135s                 
02                 718,466                 1,871.054s                 3.284s                 1,876.312s                 
03                 18,302                 1,699.691s                 0.226s                 1,700.043s                 
04                 19,647                 1,789.159s                 0.282s                 1,789.548s                 
05                 33,108                 1,798.794s                 0.272s                 1,799.198s                 
06                 50,323                 1,049.209s                 0.259s                 1,049.563s                 
07                 354,060                 1,592.803s                 1.499s                 1,595.214s                 
08                 147,032                 1,798.437s                 0.544s                 1,799.16s                 
09                 367,928                 1,799.438s                 1.82s                 1,802.035s                 
10                 136,695                 1,648.45s                 0.661s                 1,649.252s                 
11                 396,898                 1,779.29s                 2.407s                 1,782.55s                 
12                 145,238                 1,648.39s                 0.511s                 1,649.049s                 
13                 402,781                 1,589.767s                 4.784s                 1,597.161s                 
14                 149,037                 1,537.378s                 0.488s                 1,538.025s                 
15                 377,475                 1,702.605s                 1.752s                 1,705.394s                 
16                 136,494                 1,648.52s                 0.446s                 1,649.112s                 
17                 386,866                 1,727.155s                 1.92s                 1,730.011s                 
18                 148,072                 1,798.109s                 0.584s                 1,798.885s                 
19                 410,002                 1,791.737s                 1.654s                 1,794.337s                 
20                 136,358                 1,648.363s                 0.458s                 1,648.982s                 
21                 364,881                 1,689.253s                 1.587s                 1,691.557s                 
22                 130,534                 1,648.495s                 0.462s                 1,649.086s                 
23                 323,463                 1,661.115s                 1.456s                 1,663.406s




checkpoint Files (Avant)


Hour            Added           Removed                         Recycled       Synced files       Longest sync           Average sync
00                 0                 2                                          1                3,694                0.002s                0s               
01                0                2                                            0                3,494                0.005s                0s               
02                0                27                                        329                5,255                0.345s                0.011s               
03                0                1                                            0                3,244                0.001s                0s               
04                0                2                                            0                3,291                0.011s                0s               
05                0                2                                            0                3,467                0.002s                0s               
06                0                2                                            0                2,124                0.012s                0s               
07                0                24                                        112                6,029                0.307s                0.002s               
08                0                13                                          3                   4,185                0.013s                0s               
09                0                18                                        123                5,489                0.340s                0.002s               
10                0                11                                          3                3,907                0.142s                0s               
11                0                28                                        121                5,321                0.303s                0.005s               
12                0                11                                         2                3,897                0.007s                0s               
13                0                57                                        284                5,835                0.338s                0.023s               
14                0                11                                         3                4,162                0.005s                0s               
15                1                18                                         131                5,289                0.339s                0.002s               
16                0                12                                         3                3,865                0.004s                0s               
17                1                18                                       136                5,329                0.364s                0.003s               
18                0                14                                        4                4,228                0.005s                0s               
19                0                18                                      135                5,285                0.351s                0.001s               
20                0                12                                        3                3,812                0.020s                0s               
21                0                16                                      129                4,857                0.338s                0.003s               
22                0                11                                        3                3,757                0.005s                0s               
23                0                20                                      123                4,673                0.343s                0.003s





Checkpoint distance (Avant)


Hour             Mean distance              Mean estimate
00                4,033.42 kB                108,453.75 kB
01               3,061.17kB               32,970.17kB               
02               242,456.58kB               336,763.71kB               
03               2,398.25kB               98,734.67kB               
04               2,088.92kB               29,334.50kB               
05               2,658.42kB               10,019.00kB               
06               4,753.43kB               5,205.29kB               
07               148,187.27kB               274,071.27kB               
08               20,668.58kB               118,129.83kB               
09               144,975.44kB               275,189.75kB               
10               20,425.36kB               110,141.64kB               
11               152,172.00kB               283,053.12kB               
12               19,264.09kB               112,095.00kB               
13               254,369.09kB               350,192.45kB               
14               18,184.83kB               85,746.92kB               
15               152,992.31kB               273,168.19kB               
16               21,704.18kB               112,962.55kB               
17               157,885.50kB               283,809.44kB               
18               23,407.75kB               119,352.75kB               
19               157,613.25kB               284,452.19kB               
20               21,806.00kB               115,358.09kB               
21               148,911.75kB               281,283.19kB               
22               19,415.36kB               109,655.55kB               
23               147,320.44kB               279,706.44kB

Hors ligne

#18 19/07/2019 15:48:21

coucou78187
Membre

Re : perte de performances près modification de configuration

APRES




checkpoint Buffers (Après)


Hour             Writtenbuff            Write time              Sync time              total time
00               26,090               2,629.624s               0.074s               2,629.776s               
01               10,112               1,015.087s               0.054s               1,015.194s               
02               509,723               1,707.737s               3.514s               1,713.973s               
03               8,176               820.223s               0.063s               820.348s               
04               9,590               962.338s               0.059s               962.467s               
05               12,205               1,237.05s               0.056s               1,237.174s               
06               18,731               1,870.826s               0.083s               1,870.978s               
07               193,220               3,192.259s               0.739s               3,193.688s               
08               65,681               3,239.389s               1.42s               3,240.953s               
09               209,692               3,295.966s               0.416s               3,296.78s               
10               48,928               3,239.478s               0.176s               3,239.766s               
11               198,633               3,205.858s               0.302s               3,206.714s               
12               49,349               2,699.409s               0.208s               2,699.714s               
13               191,865               3,343.705s               0.377s               3,344.59s               
14               53,720               3,239.282s               0.178s               3,239.582s               
15               354,375               2,764.578s               21.612s               2,789.415s               
16               43,360               3,239.447s               0.136s               3,239.699s               
17               197,167               3,206.193s               0.45s               3,207.402s               
18               53,132               3,239.213s               0.164s               3,239.522s               
19               208,049               3,331.313s               0.779s               3,332.996s               
20               56,148               3,239.465s               0.129s               3,239.696s               
21               208,698               3,280.648s               0.375s               3,281.531s               
22               54,738               3,239.615s               0.128s               3,239.837s               
23               192,719               3,202.159s               0.218s               3,203.031s               



checkpoint Files (Après)


Hour            Added  Removed       Recycled       Synced files       Longest sync           Average sync
00               0               0               9               725                            0.004s               0s               
01               0               0               4               478                           0.002s               0s               
02               0               45            312               1,332                     0.617s               0.031s               
03               0               0               3               573                          0.003s               0s               
04               0               0               3               583                           0.001s               0s               
05               0               0               4               521                            0.002s               0s               
06               0               0               8               451                           0.010s               0s               
07               0               27            117               1,044                      0.459s               0.002s               
08               0               1               59               1,127                       1.179s               0.003s               
09               0               1             156               1,262                         0.114s               0s               
10               0               0               35               911                            0.004s               0s               
11               0               27            119               1,088                         0.030s               0s               
12               0               0               25               798                            0.004s               0s               
13               0               22            124               1,068                          0.101s               0s               
14               0               0               33               951                            0.004s               0s               
15               0               80            1,079               3,293                      0.923s               0.215s               
16               0               0               39               625                             0.005s               0s               
17               0               28            129               767                            0.212s               0.002s               
18               0               0               43               545                            0.005s               0s               
19               0               34            119               689                            0.223s               0.005s               
20               0               0               33               581                             0.004s               0s               
21               0               24            120               614                            0.226s               0.002s               
22               0               0               26               576                             0.004s               0s               
23               0               23            107               594                            0.096s               0.001s




Checkpoint distance (Après)


Hour             Mean distance              Mean estimate
00               23,871.86kB               392,501.00kB               
01               12,313.80kB               213,910.80kB               
02               450,065.77kB               613,053.46kB               
03               8,064.33kB               380,585.17kB               
04               8,092.00kB               196,842.00kB               
05               11,238.80kB               108,033.20kB               
06               28,279.75kB               67,693.75kB               
07               327,846.14kB               499,900.71kB               
08               110,796.33kB               446,377.33kB               
09               413,389.57kB               617,772.43kB               
10               95,371.67kB               448,853.17kB               
11               343,002.71kB               578,550.57kB               
12               83,067.60kB               431,125.00kB               
13               338,891.29kB               567,086.57kB               
14               91,190.83kB               441,394.83kB               
15               655,227.24kB               701,119.41kB               
16               101,639.67kB               450,092.50kB               
17               367,085.43kB               580,830.43kB               
18               118,485.00kB               457,990.00kB               
19               360,727.57kB               602,285.43kB               
20               90,360.33kB               465,769.50kB               
21               340,111.29kB               578,125.43kB               
22               71,693.33kB               434,594.00kB               
23               308,283.86kB               568,864.57kB

Hors ligne

#19 19/07/2019 15:52:57

rjuju
Administrateur

Re : perte de performances près modification de configuration

Concernant le sort, je confirme que vos résultats indique que le tri est plus rapide avec un external sort.  Pour analyser la sortie d'explain:

   ->  Sort  (cost=2023043.46..2026340.41 rows=1318778 width=81) (actual time=6157.823..7029.107 rows=988089 loops=1)
         Sort Key: r.colonne2, r.colonne4, r.colonne3
         Sort Method: external merge  Disk: 94800kB
         Buffers: shared hit=574976, temp read=11850 written=11869
         ->  Gather  (cost=361349.92..1852922.60 rows=1318778 width=81) (actual time=1596.185..3674.164 rows=988089 loops=1)

les différents temps d'exécution sont:

- récupération de l'intégralité des lignes + temps pour trier les lignes : temps total du noeud sous jacent - temps initial du noeud sort, soit ici 6157.823 - 3674.164
- temps pour renvoyer toutes les lignes au noeud parent : temps total du noeud sort - temps initial du noeud sort, soit ici 7029.107 - 6157.823


Le tri est donc bien plus rapide, mais l'envoi des lignes un peu plus lent.  Je suppose que la différence pour le tri s'explique par des finesses dans l'algorithme de tape sort + la distribution des données en entrée peut être, et pour le renvoi des lignes par le fait que l'envoi des lignes depuis le fichier externe est un peu plus lent.



Pour le reste je suis totalement perdu, ce thread partant dans tous les sens.  Si vous voulez de l'aide, il serait sans doute préférable de créer un thread à la fois pour chaque problème, sans changer des paramètres dans tous les sens et en coupant la discussions avec des sujets annexes.

Hors ligne

#20 19/07/2019 16:24:38

coucou78187
Membre

Re : perte de performances près modification de configuration

Ce que je remarque ce sont des :



checkpoint Buffers:

Write time ==> beaucoup plus élevés APRES (x2)
Total time ==> beaucoup plus élevé APRES (x2)



checkpoint Files

Synced files ==> beaucoup MOINS nombreux APRES



Checkpoint distance

Mean distance ==> Des valeurs beaucoup PLUS élevés APRES (idem pour le mean estimate).


Je comprends que le temps d'écriture des buffers par heure est beaucoup plus long APRES.


iostat :



avg-cpu:  %user   %nice %system %iowait  %steal   %idle
           3,99    0,00    2,70    2,15    0,01   91,15

Device:         rrqm/s   wrqm/s     r/s       w/s      rkB/s         wkB/s    avgrq-sz     avgqu-sz   await      r_await    w_await     svctm      %util
sdb               0,00     0,00          0,01    4,17     0,37        1774,12    850,12        0,30         66,76        0,89       66,87     3,95        1,65
sda               0,00     0,02          0,52    0,32    16,75        5,01         51,94          0,28          1,52         0,54        3,13      327,67      27,46
sdd               0,00     0,29      882,75   50,79  13733,84   2040,19    33,79         0,06          0,07         0,48        2,80     0,32         30,08
sdc               0,00     0,01          0,00  110,49     0,13     1402,73    25,39         0,25          2,11         0,23        2,11     0,77          8,46



Je précises que les graphes APRES (checkpoint distance et checkpoint write buffers par exemple) présentent beaucoup plus de "dentitions" entre les pics qu'auparavant qui était plus lisse entre les pics mais avec des MAX différents (j'essaie de m'exprimer correctement


Que pourrais-je tirer d'autres comme conclusion à partir de ces éléments?


Merci beaucoup.

Hors ligne

#21 19/07/2019 16:25:04

dverite
Membre

Re : perte de performances près modification de configuration

rjuju a écrit :

Concernant le sort, je confirme que vos résultats indique que le tri est plus rapide avec un external sort.  Pour analyser la sortie d'explain:

les différents temps d'exécution sont:

- récupération de l'intégralité des lignes + temps pour trier les lignes : temps total du noeud sous jacent - temps initial du noeud sort, soit ici 6157.823 - 3674.164
- temps pour renvoyer toutes les lignes au noeud parent : temps total du noeud sort - temps initial du noeud sort, soit ici 7029.107 - 6157.823

Oui je me suis trompé dans mon message précédent en confondant le temps mesuré à partir de la 1ere ligne sortie avec le temps total du tri. Autant pour moi. Concernant la lenteur du quicksort, cet algorithme a des cas dégénérés où il est peu performant en O(n²), peut-être effectivement que le profil des données en entrée fait qu'il se retrouve dans ce cas là.

Hors ligne

#22 19/07/2019 16:46:01

coucou78187
Membre

Re : perte de performances près modification de configuration

Julien,



Pour le reste je suis totalement perdu, ce thread partant dans tous les sens.  Si vous voulez de l'aide, il serait sans doute préférable de créer un thread à la fois pour chaque problème, sans changer des paramètres dans tous les sens et en coupant la discussions avec des sujets annexes.



Oui j'ai voulu traiter ces sujets en parallèle car la source était une perte de perf généralisée.



Je vais créer un autre post pour l'autre sujet  pour ne pas nous emmêler  smile


Restons ici,  si vous le voulez, sur le sujet des tris en mémoire/disque qui est intéressant


désolé

Hors ligne

#23 19/07/2019 16:48:06

coucou78187
Membre

Re : perte de performances près modification de configuration

Concernant les paramètres ils sont les suivants :


work_mem = '16MB'
maintenance_work_mem = '128MB'
min_wal_size = '1GB'
max_wal_size = '2GB'
checkpoint_timeout = '10min'
checkpoint_completion_target = '0.9'
effective_io_concurrency = '20'
wal_buffers = '32MB'
default_statistics_target = '100'
random_page_cost='1'


Merci

Hors ligne

#24 19/07/2019 17:51:42

dverite
Membre

Re : perte de performances près modification de configuration

coucou78187 a écrit :

je trace aussi les fichiers temp dans les logs, à priori ca arrive bien dans les logs :

LOG:  temporary file: path "base/pgsql_tmp/pgsql_tmp16217.8", size 97097841

Ca je n'en doutais pas mais ce n'est pas ce que je voulais dire en disant que le contenu temporaire à durée de quelques secondes ne va pas forcément physiquement sur les disques.

Prenons un exemple sous Linux avec 32Go de RAM, et un FS ext4 basique.

Je créé un fichier random de 100Mo:
$ dd if=/dev/urandom of=file bs=1024 count=$((100*1024))

Mettons maintenant que je le copie en regardant à côté avec vmstat les accès sur l'interface disque.

$ vmstat -n 1
procs -----------memory---------- ---swap-- -----io---- -system-- ------cpu-----
r  b   swpd   free   buff  cache   si   so    bi    bo   in   cs us sy id wa st
0  0   8256 382924 1133884 30858356    0    0     0     0   68   85  0  0 100  0  0
0  0   8256 382924 1133884 30858356    0    0     0     0   46   56  0  0 100  0  0
... pas mal de secondes plus tard...
0  0   8256 382180 1133884 30858356    0    0     0 102555  310  219  0  0 99  1  0
0  0   8256 382180 1133884 30858360    0    0     0     6  238   93  0  0 100  0  0
1  0   8256 382180 1133884 30858360    0    0     0     0   66   69  0  0 100  0  0
0  0   8256 382312 1133884 30858360    0    0     0    19   98  138  0  0 100  0  0

Au bout d'un moment on voit passer les 100Mo en colonne "bo" qui correspond à l'écriture physique, c'est le 102555 en l'occurrence.

Mais qu'est-ce qui se passe si on fait "cp file file2 ; sleep 3; rm file2" c.a.d que le fichier est détruit au bout de quelques secondes?
Et bien typiquement cette ligne dans vmstat n'apparait jamais, car les données ont été abandonnées avant que le cache soit vidé sur disque. En vrai tout s'est passé en mémoire.


Dans le cas d'un petit fichier de 100Mo écrits dans base/pgsql_tmp, vu que postgres n'a pas de raison de demander un "fsync" sur ce fichier qui n'a pas à survivre à la transaction, je ne vois pas pourquoi l'OS se précipiterait pour l'écrire physiquement sur disque.

Hors ligne

#25 19/07/2019 18:02:53

coucou78187
Membre

Re : perte de performances près modification de configuration

Daniel,


C'est très intéressant et donc pour vérifier ce point la seule solution est de monitorer les I/O finement lors des executions


et si l'on constate que cette quatité de données (fichier temp dans les logs)  n'est pas tracée on peut éventuellement  conclure qu'elle a seulement transitée par le cache.


Merci

Hors ligne

Pied de page des forums