Temps d'execution d'un update très long - est-ce normal ?

Sylvain · 27/08/2018 11:30:12

Bonjour,

Je suis tout nouveau sur ce forum, et vous remercie à l'avance de l'éclairage que vous pourrez peut-être m'apporter. voici mon problème par rapport à un temps d'exécution que je trouve beaucoup trop long:

Sur une table qui compte environ 9 millions de lignes, et une dizaine de colonnes,
il a fallu 35 minutes pour exécuter : UPDATE wois_alarm SET engine_running = NULL;
et il a fallu 3 mn 30s pour effectuer : SELECT count(*) FROM wois_alarm;

Est-ce que ça vous parait normal ? Je n'ai pas de point de comparaison pour la durée d'exécution, étant donné que je n'avais jamais effectué un traitement massif sur cette table.

Merci d'avance !

ruizsebastien · 27/08/2018 11:44:35

Bonjour,

il nous faudrait le plan d'exécution de la requête d'update (quoique vu qu'il n'y a pas de where dans l'update, postgresql fait un table scan de toutes les lignes (lapsus))

Ensuite tout dépend de la vélocité de votre serveur.

Il faudrait voir du côté des paramètres mémoires dans le postgresql.conf (je pense à shared_buffer notamment) et voir combien vous avez de RAM et de CPU.

Autre piste : le paramètrage de l'autovacuum (voir dans les traces si il ne se déclenche pas trop souvent).

Cordialement,

dverite · 27/08/2018 12:54:01

Si le sous-système disque n'est pas un foudre de guerre, une trentaine de mn pour un UPDATE de 10M lignes n'est pas spécialement choquant.

Vous pouvez regarder un peu ce que fait le système pendant ce temps avec des outils de supervision système et Postgres, mais il faut bien voir que cet UPDATE massif va créer une copie de chaque ligne de la table, et pas forcément dans le même bloc s'il ne trouve pas de place, ça dépend des écritures précédentes dans la table et du fillfactor. Et s'il y a des index sur cette table, il va doubler aussi chaque entrée d'index. Là aussi le fillfactor entre en ligne de compte. Postgres va également écrire dans les fichiers journaux WAL en plus des fichiers de relation, soit deux fois plus d'écritures.

Au final un UPDATE global sur une table peut tout à fait engendrer l'écriture de N fois la taille initiale de la table.

Sylvain · 30/08/2018 15:47:08

Bonjour,
Merci beaucoup pour vos réponses !
J'ai surtout été surpris de la requête qui a pris 3 mn : SELECT count(*) FROM wois_alarm
on dirait qu'il faut plus de temps pour compter que pour trier !
Sébastien :
Voici à ma connaissance la configuration :
- shared_buffers = 128MB
- ressources de la machine virtuelle : 4GB, 2CPU
Daniel :
la table comporte plusieurs index en effet.
mais le champs qui a fait l'objet de l'update est un boolean, sans index
pour le facteur de remplissage, il n'y a rien de personnalisé. le réglage de l'auto vacuum est celui par défaut

gleu · 01/09/2018 16:09:08

Le plan d'exécution permettrait d'en savoir plus. Que vous donne un "EXPLAIN (ANALYZE,BUFFERS) UPDATE...". (à notez que cela génère aussi un paquet de journaux de transactions, les écritures sont faites en double)

Sylvain · 03/09/2018 10:04:40

Bonjour. Tout d'abords merci à tous pour le temps passé à me répondre et pour le partage de vos connaissance.
Voici le plan d'exécution de la requête dont le temps d'exécution me surprends le plus (un simple COUNT). Je posterai ensuite celui de la requête UPDATE dès que s'affichera le résultat.
--------------------------------------------------------------------------------
EXPLAIN (ANALYZE,BUFFERS) SELECT COUNT(*) FROM wois_alarm
--------------------------------------------------------------------------------
Aggregate (cost=388605.74..388605.75 rows=1 width=0) (actual time=248381.319..248381.320 rows=1 loops=1)
Buffers: shared hit=650 read=247866
-> Seq Scan on wois_alarm (cost=0.00..360587.79 rows=11207179 width=0) (actual time=116.003..240159.673 rows=9137124 loops=1)
Buffers: shared hit=650 read=247866
Planning time: 1.276 ms
Execution time: 248381.388 ms

Sylvain · 03/09/2018 10:49:37

Suite à mon précédent post, voici le plan d'exécution de la requête UPDATE. Merci d'avance si vous avez des idées pour l'optimisation de l'une ou l'autre de ces 2 requêtes.
----------------------------------------------------------------------
EXPLAIN (ANALYZE,BUFFERS) UPDATE wois_alarm SET engine_running = NULL
----------------------------------------------------------------------
Update on wois_alarm (cost=0.00..360587.79 rows=11207179 width=66) (actual time=2429124.370..2429124.370 rows=0 loops=1)
Buffers: shared hit=142222858 read=797052 dirtied=799067 written=70549
-> Seq Scan on wois_alarm (cost=0.00..360587.79 rows=11207179 width=66) (actual time=219.224..175874.781 rows=9137124 loops=1)
Buffers: shared hit=52 read=248464 written=70541
Planning time: 0.279 ms
Execution time: 2429134.392 ms

ruizsebastien · 03/09/2018 11:48:01

Bonjour,

vous avez un buffers shared hit très bas ce qui signifie que les blocs ne sont pas dans la RAM (normal lors d'une première exécution).
Si vous relancez le count(*) encore vous devriez voir le shared it monter.

gleu · 03/09/2018 13:31:41

J'ai un peu l'impression (étant donné le nombre de blocs lus par rapport au nombre de blocs écrits) que cette table est très fortement fragmentée. Il serait bon de le vérifier et de faire, le cas échéant, un "VACUUM FULL wois_alarm". Ensuite, pour éviter que cette fragmentation revienne rapidement, il serait préférable de modifier le UPDATE ainsi :

UPDATE wois_alarm SET engine_running = NULL WHERE engine_running IS NOT NULL;

Sylvain · 03/09/2018 13:45:27

ruizsebastien a écrit :

Bonjour,
vous avez un buffers shared hit très bas ce qui signifie que les blocs ne sont pas dans la RAM (normal lors d'une première exécution).
Si vous relancez le count(*) encore vous devriez voir le shared it monter.

---------------------------------------------------------------------------------------------------------------------------------
Merci.
J'ai relancé 3 fois la requête, et voici ci dessous le plan d'exécution :
Par contre, j'ai lancé 2 fois également la requête simple, sans ANALYSE. première fois : 2mn30, 2eme fois : 4mn30
---------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=382218.92..382218.94 rows=1 width=0) (actual time=252857.729..252857.730 rows=1 loops=1)
Buffers: shared hit=403 read=248113
-> Seq Scan on wois_alarm (cost=0.00..355478.34 rows=10696234 width=0) (actual time=0.045..244720.972 rows=9137124 loops=1)
Buffers: shared hit=403 read=248113
Planning time: 0.104 ms
Execution time: 252857.828 ms
---------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=382218.92..382218.94 rows=1 width=0) (actual time=230953.724..230953.725 rows=1 loops=1)
Buffers: shared hit=435 read=248081"
-> Seq Scan on wois_alarm (cost=0.00..355478.34 rows=10696234 width=0) (actual time=11.246..222865.570 rows=9137124 loops=1)
Buffers: shared hit=435 read=248081
Planning time: 0.204 ms
Execution time: 230953.779 ms
---------------------------------------------------------------------------------------------------------------------------------
Aggregate (cost=382218.92..382218.94 rows=1 width=0) (actual time=294853.451..294853.452 rows=1 loops=1)
Buffers: shared hit=467 read=248049
-> Seq Scan on wois_alarm (cost=0.00..355478.34 rows=10696234 width=0) (actual time=9.563..286475.286 rows=9137124 loops=1)
Buffers: shared hit=467 read=248049
Planning time: 0.095 ms
Execution time: 294853.512 ms

Dernière modification par Sylvain (03/09/2018 13:49:29)

Sylvain · 03/09/2018 13:47:57

gleu a écrit :

J'ai un peu l'impression (étant donné le nombre de blocs lus par rapport au nombre de blocs écrits) que cette table est très fortement fragmentée. Il serait bon de le vérifier et de faire, le cas échéant, un "VACUUM FULL wois_alarm". Ensuite, pour éviter que cette fragmentation revienne rapidement, il serait préférable de modifier le UPDATE ainsi :
UPDATE wois_alarm SET engine_running = NULL WHERE engine_running IS NOT NULL;

Merci.
J'ai un échec au bout de 30 s après avoir lancé VACUUM FULL wois_alarm :
********** Erreur **********
État SQL :53100

Je vais me rapprocher de l'administrateur réseau et voir avec lui si l'espace disque est suffisant ...
A suivre

Dernière modification par Sylvain (03/09/2018 13:48:48)

ruizsebastien · 03/09/2018 14:23:25

il faut voir aussi si en fonction de la taille de la RAM et de la taille de la table, tous les blocs peuvent-ils être présents en même temps en mémoire ?

gleu · 03/09/2018 17:14:02

53100 est un problème d'espace disque. Vous devez disposer d'environ le double de la taille de la table et de ses index pour être certain que l'opération ne générera pas plus de données (à condition que les journaux de transactions soient sur un autre disque... dans le cas contraire, comptez plutôt 3 fois).

Sylvain · 04/09/2018 16:38:27

Effectivement,
l'administrateur réseau vient de multiplier par 2 l'espace disque :
=> lancement de la requête SELECT COUNT(*) FROM wois_alarm : temps d'exécution = 2 mn 30
=> exécution de VACUUM FULL wois_alarm, puis à nouveau SELECT COUNT(*) : temps d'exécution = 1.5 s
quelle différence !!!
Par contre pour l'UPDATE global, on passe de 35mn à 23mn

Sylvain · 04/09/2018 16:54:09

Par contre, après voir lancé le dernier UPDATE wois_alarm SET engine_running = NULL (qui était déjà pourtant à NULL auparavant),
et bien le SELECT COUNT(*) à pris de nouveau plus de temps :
1ère fois : 1 mn 40
2ème fois : 22 s
3ème fois : 52 s
4ème fois : 1 mn 25
5ème fois : 2 mn 02
J'en découvre des choses, mais c'est à n'y rien comprendre !
J'essaierai à nouveau demain avec EXPLAIN (ANALYZE,BUFFERS)

rjuju · 04/09/2018 21:14:24

C'est normal, votre UPDATE (s'il n'avait bien pas de clause WHERE) a réécrit l'intégralité de la table, et a donc fortement augmenté la volumétrie. Un autovacuum a du se lancer depuis, mais l'espace ne sera pas récupéré mais réutilisé lors des prochaines opérations en écriture.

Le count(*) va donc devoir parcourir beaucoup plus de blocs, d'où un temps d'exécution plus élevé. Les fluctuations sur le temps d'exécution sont probablement dus à une utilisation concurrente de la base,et à une différence sur le nombre d'accès disque.

Concernant votre plan d'exécution précédent:

Aggregate (cost=382218.92..382218.94 rows=1 width=0) (actual time=294853.451..294853.452 rows=1 loops=1)
Buffers: shared hit=467 read=248049
-> Seq Scan on wois_alarm (cost=0.00..355478.34 rows=10696234 width=0) (actual time=9.563..286475.286 rows=9137124 loops=1)
Buffers: shared hit=467 read=248049
Planning time: 0.095 ms
Execution time: 294853.512 ms

Si mes calculs sont corrects, ça fait une moyenne de 6.7 Mo/s en lecture séquentielle, ce qui est très très peu.

gleu · 05/09/2018 08:40:24

D'où le fait qu'il est préférable d'exécuter ceci :

UPDATE wois_alarm SET engine_running = NULL WHERE engine_running IS NOT NULL:

ce qui vous avait été d'ailleurs déjà suggéré.

Sylvain · 05/09/2018 09:36:23

gleu a écrit :

D'où le fait qu'il est préférable d'exécuter ceci :
UPDATE wois_alarm SET engine_running = NULL WHERE engine_running IS NOT NULL:
ce qui vous avait été d'ailleurs déjà suggéré.

Oui tout à fait, mais j'avais voulu voir la différence de performance à requête égale avant et après VACUUM

Sylvain · 05/09/2018 09:38:24

rjuju a écrit :

Si mes calculs sont corrects, ça fait une moyenne de 6.7 Mo/s en lecture séquentielle, ce qui est très très peu.

Et du coup... (désolé pour ignorance) c'est bien / pas bien ? optimisable ?

rjuju · 05/09/2018 09:49:44

C'est très mauvais À titre de comparaison, sur le moins performant de mes vieux disques dur mécaniques 7200 RPM qui traînent, je dépasse les 75 Mo/s (d'autres montent à 175 Mo/s). Je ne sais pas quel est le système disque utilisé, mais il serait bon de vérifier les performances attendues et réelles.

Sylvain · 05/09/2018 12:29:04

rjuju a écrit :

Si mes calculs sont corrects, ça fait une moyenne de 6.7 Mo/s en lecture séquentielle, ce qui est très très peu.

Ci-dessous les tous nouveaux comptes rendu EXPLAIN pour vous demandez votre avis :
Et maintenant que la taille disque a été augmentée et VACUUM FULL exécuté, est-ce que les performances de la lecture séquentielle se sont améliorées ?
-----------------------------------------------
EXPLAIN (ANALYSE,BUFFERS) SELECT COUNT(*) FROM wois_alarm
-----------------------------------------------
Aggregate (cost=218661.05..218661.06 rows=1 width=0) (actual time=16977.133..16977.134 rows=1 loops=1)
Buffers: shared hit=15339 read=89108
-> Seq Scan on wois_alarm (cost=0.00..195818.24 rows=9137124 width=0) (actual time=0.039..8791.853 rows=9137124 loops=1)
Buffers: shared hit=15339 read=89108
Planning time: 0.093 ms
Execution time: 16977.185 ms

-----------------------------------------------
EXPLAIN (ANALYSE,BUFFERS) UPDATE wois_alarm SET engine_running = NULL
-----------------------------------------------
Update on wois_alarm (cost=0.00..195818.24 rows=9137124 width=66) (actual time=1521513.291..1521513.291 rows=0 loops=1)
Buffers: shared hit=139188764 read=601177 dirtied=751354 written=48382
-> Seq Scan on wois_alarm (cost=0.00..195818.24 rows=9137124 width=66) (actual time=0.009..37118.155 rows=9137124 loops=1)
Buffers: shared hit=546 read=103901 written=48382
Planning time: 0.182 ms
Execution time: 1521523.794 ms

dverite · 05/09/2018 14:35:24

Que les temps d'exécution soient très variables peut aussi venir du fait que le sous-système disque serait virtualisé.

C'est facile à gérer pour les admins (peut-être que le doublage de taille de la partition a juste consisté à bouger une réglette dans une interface?) mais les performances sont imprévisibles puisque les disques physiques sont partagés par plusieurs machines virtuelles.

Même sur un système disque dédié, les temps sont variables, pour bien faire il faut enchaîner entre 5 et 10 exécutions du test et considérer le temps médian comme résultat.

#1 27/08/2018 11:30:12

Temps d'execution d'un update très long - est-ce normal ?

#2 27/08/2018 11:44:35

Re : Temps d'execution d'un update très long - est-ce normal ?

#3 27/08/2018 12:54:01

Re : Temps d'execution d'un update très long - est-ce normal ?

#4 30/08/2018 15:47:08

Re : Temps d'execution d'un update très long - est-ce normal ?

#5 01/09/2018 16:09:08

Re : Temps d'execution d'un update très long - est-ce normal ?

#6 03/09/2018 10:04:40

Re : Temps d'execution d'un update très long - est-ce normal ?

#7 03/09/2018 10:49:37

Re : Temps d'execution d'un update très long - est-ce normal ?

#8 03/09/2018 11:48:01

Re : Temps d'execution d'un update très long - est-ce normal ?

#9 03/09/2018 13:31:41

Re : Temps d'execution d'un update très long - est-ce normal ?

#10 03/09/2018 13:45:27

Re : Temps d'execution d'un update très long - est-ce normal ?

#11 03/09/2018 13:47:57

Re : Temps d'execution d'un update très long - est-ce normal ?

#12 03/09/2018 14:23:25

Re : Temps d'execution d'un update très long - est-ce normal ?

#13 03/09/2018 17:14:02

Re : Temps d'execution d'un update très long - est-ce normal ?

#14 04/09/2018 16:38:27

Re : Temps d'execution d'un update très long - est-ce normal ?

#15 04/09/2018 16:54:09

Re : Temps d'execution d'un update très long - est-ce normal ?

#16 04/09/2018 21:14:24

Re : Temps d'execution d'un update très long - est-ce normal ?

#17 05/09/2018 08:40:24

Re : Temps d'execution d'un update très long - est-ce normal ?

#18 05/09/2018 09:36:23

Re : Temps d'execution d'un update très long - est-ce normal ?

#19 05/09/2018 09:38:24

Re : Temps d'execution d'un update très long - est-ce normal ?

#20 05/09/2018 09:49:44

Re : Temps d'execution d'un update très long - est-ce normal ?

#21 05/09/2018 12:29:04

Re : Temps d'execution d'un update très long - est-ce normal ?

#22 05/09/2018 14:35:24

Re : Temps d'execution d'un update très long - est-ce normal ?

Pied de page des forums

À propos

Nous contacter

Groupes Locaux

Réseaux Sociaux