Vous n'êtes pas identifié(e).
Bonjour,
Pour faire un retour c'est bien possible. Il faut juste spécifier le format "nagios" dans la configuration telegraf.
Le plus dur ensuite est l'ajustement des seuils (Warning, Critical) en fonction des métriques suivies et intervalle de collecte.
Merci,
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
Julien ,
Merci j'imagine que le Checkpoint distance se retrouve par le même calcul augmenté (espacement des checkpoints) donc ce qui est normal...
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.
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
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
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 = '100'
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...
devant de nombreux message de type "checkpoint occurs too frequently", les paramètres suivant ont été modifié et depuis beaucoup moins de ces messages remontent.
Cependant en comparant les stats de checkpoint AVANT/APRES on remarque une grande différence
je mets ci dessous ces éléments.
je me demandais si la cause pouvais provenir de là ?
sinon y aurait-il d'autres pistes ?
Merci
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
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é
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.
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
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
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
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...
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
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
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
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,
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
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.
Julien ,
Merci pour le retour rapide.
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'
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
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
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
Bonjour Julien,
Merci pour l'info, je vais essayer d'intégrer quelques sondes et tester.
Je tâcherai de faire un retour dessus.
Bonjour tout le monde,
check_pgactivity est un outil que j'ai déjà implémenté/utilisé en entreprise utilisant Nagios et qui correspondait très bien.
Les sondes sont exhaustives et permettent un suivi précis.
Actuellement, l'environnement dans lequel j'évolue a changé pour un ensemble telegraf/influxdb/grafana.
Etant donné que je fus très satisfait de check_pgactivity j'aimerai continuer avec de plus que le projet est bien suivi.
Pour cela, je voulais vous demander si il était possible d'implémenter ce plug-in avec cette configuration et de quelle manière car à la base ce plug-in est créé pour être une sonde Nagios...
Merci pour votre aide.
