perte de performances près modification de configuration

coucou78187 · 17/07/2019 17:01:40

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

rjuju · 17/07/2019 21:41:41

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).

coucou78187 · 18/07/2019 09:38:33

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

rjuju · 18/07/2019 09:49:12

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".

coucou78187 · 18/07/2019 10:06:48

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

coucou78187 · 18/07/2019 11:08:36

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.

coucou78187 · 18/07/2019 11:16:09

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

rjuju · 18/07/2019 11:36:08

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 ?

coucou78187 · 18/07/2019 11:46:06

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,

coucou78187 · 18/07/2019 14:20:55

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

dverite · 19/07/2019 13:13:43

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 ?

coucou78187 · 19/07/2019 13:51:54

Bonjour Daniel,

merci pour le retour

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

coucou78187 · 19/07/2019 13:56:57

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

dverite · 19/07/2019 14:28:09

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.

coucou78187 · 19/07/2019 15:15:31

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...

coucou78187 · 19/07/2019 15:40:59

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

coucou78187 · 19/07/2019 15:44:42

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

coucou78187 · 19/07/2019 15:48:21

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

rjuju · 19/07/2019 15:52:57

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.

coucou78187 · 19/07/2019 16:24:38

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.

dverite · 19/07/2019 16:25:04

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à.

coucou78187 · 19/07/2019 16:46:01

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

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

désolé

coucou78187 · 19/07/2019 16:48:06

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

dverite · 19/07/2019 17:51:42

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.

coucou78187 · 19/07/2019 18:02:53

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

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

perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

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

Re : perte de performances près modification de configuration

Pied de page des forums

À propos

Nous contacter

Groupes Locaux

Réseaux Sociaux