Forums PostgreSQL.fr

thomasp

Membre

Premier update très long, mais les suivants sont instantannés

Bonjour à tous,

Dans une procédure stockée, je fais un update très basique sur une table :

mytable (
   id_user UUID, 
   id_object UUID, 
   value FLOAT,
   CONSTRAINT pk_user_poi PRIMARY KEY (id_user, id_object))

-- requête :
update mytable set 
    value = [nouvelle valeur] 
where id_object =  [object à traiter]

Mon problème est que, pour un même id_object, le premier update est très long (varie entre 3 et 8 secondes!), alors que les suivants, sur le même id_object, ne prend que quelques millisecondes. Dès que je change d'id_object, le 1er prends toujours quelques secondes et pas les suivants.

- J'ai essayé de rajouter un index dédié à l'id_object (en plus de la clé primaire sur le couple user/object), mais ça n'a rien changé.
- Quand je reconstruis l'index, le 1er update est cette fois très rapide, mais la reconstruction d'index est trop longue pour que je l'utilise à chaque fois.

Savez-vous pourquoi il y a une telle différence entre le 1er update et les suivants pour un même id_object? Y a t'il une solution à ce problème de 1er update?

- mytable contient environ 7.000.000 de lignes
- le nombre d’occurrences d'id_object varie entre 1 et 5.000, pour environ 500.000 id_object différents

De plus, j'ai exactement le même système sur sql server 2008 (je suis entrain de migrer les données et procédures stockées de sql server vers postgres): sur sql server, tous les updates, premier ou non pour un même objet, sont tous de quelques millisecondes.

Merci et bonne journée, Thomas

Dernière modification par thomasp (02/05/2016 14:49:20)

ruizsebastien

Membre

Re : Premier update très long, mais les suivants sont instantannés

Bonjour,

C'est normal le premier coup les blocs ne sont pas dans le cache. Suite au where qui va rechercher le bon id_object, cet id_object est dans le cache. D'où la rapidité du deuxième update.
Si vous êtes en version 9.4 ou plus vous pouvez tenter d'utiliser pg_prewarm.
http://docs.postgresql.fr/9.4/pgprewarm.html

Cordialement.

---

Cordialement,

Sébastien.

rjuju

Administrateur

Re : Premier update très long, mais les suivants sont instantannés

Vous pouvez également vérifier si les accès se font ou non dans le cache :

EXPLAIN (ANALYZE, BUFFERS) update mytable set 
    value = [nouvelle valeur] 
where id_object =  [object à traiter]

(attention, cela va vraiment exécuter la requête).

shared read signifie un accès en dehors du cache de PostgreSQL, et shared hit signifie un accès dans ce cache.

Il faut peut être également revoir la configuration de postgres pour s'assurer que le cache est bien dimensionné par exemple.

---

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

thomasp

Membre

Re : Premier update très long, mais les suivants sont instantannés

Bonjour,

C'est normal le premier coup les blocs ne sont pas dans le cache. Suite au where qui va rechercher le bon id_object, cet id_object est dans le cache. D'où la rapidité du deuxième update.
Si vous êtes en version 9.4 ou plus vous pouvez tenter d'utiliser pg_prewarm.
http://docs.postgresql.fr/9.4/pgprewarm.html

Cordialement.

En effet j'ai déjà essayé le pg_prewarm, sur la table et sur l'index directement, mais ça n'a rien changé

thomasp

Membre

Re : Premier update très long, mais les suivants sont instantannés

Vous pouvez également vérifier si les accès se font ou non dans le cache

En effet entre le 1er explain et les suivants, le share read passe de plusieurs milliers à quelques unités, tout le reste est identique. Merci, c'est donc bien le cache qui fait la différence. J'ai essayé le pg_prewarm pour mettre la table en mémoire (j'ai essayé aussi avec l'index sur l'id_object) mais ça n'a rien changé, savez-vous s'il y a une autre solution?

à noter que le planning time indique toujours quelques millisecondes, même pour les 1ères exécutions, il ne détecte pas que la 1ère requête va être très longue.

rjuju

Administrateur

Re : Premier update très long, mais les suivants sont instantannés

Le planning time correspond au temps pour calculer le plan d'exécution, il est normal que ce temps n'évolue pas.

Pouvez-vous nous donner le plan d'exécution de cette requête (cas lent et cas rapide) ?

---

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

thomasp

Membre

Re : Premier update très long, mais les suivants sont instantannés

oups, donc ok, le planning time n'a rien à voir...

Voici 2 explain faits d'affilée sur le même id_object:

-- PREMIER UPDATE LENT
explain (analyze,buffers) update mytable set value = value+1 where id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a';
                                                              QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------
 Update on mytable  (cost=5.38..487.08 rows=122 width=67) (actual time=2402.480..2402.480 rows=0 loops=1)
   Buffers: shared hit=24186 read=1395 dirtied=3267
   ->  Bitmap Heap Scan on mytable  (cost=5.38..487.08 rows=122 width=67) (actual time=1.009..81.692 rows=1215 loops=1)
         Recheck Cond: (id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a'::uuid)
         Heap Blocks: exact=1249
         Buffers: shared hit=1273 dirtied=1006
         ->  Bitmap Index Scan on ix_mytable_id_object  (cost=0.00..5.35 rows=122 width=0) (actual time=0.673..0.673 rows=4864 loops=1)
               Index Cond: (id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a'::uuid)
               Buffers: shared hit=24
 Planning time: 0.149 ms
 Execution time: 2402.540 ms
(11 rows)

Time: 2414,219 ms

-- DEUXIEME UPDATE RAPIDE
explain (analyze,buffers) update mytable set value = value-1 where id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a';
                                                              QUERY PLAN
--------------------------------------------------------------------------------------------------------------------------------------
 Update on mytable  (cost=5.38..487.08 rows=122 width=67) (actual time=42.607..42.607 rows=0 loops=1)
   Buffers: shared hit=22592 read=8 dirtied=11
   ->  Bitmap Heap Scan on mytable  (cost=5.38..487.08 rows=122 width=67) (actual time=1.253..6.887 rows=1215 loops=1)
         Recheck Cond: (id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a'::uuid)
         Heap Blocks: exact=1256
         Buffers: shared hit=1284
         ->  Bitmap Index Scan on ix_mytable_id_object  (cost=0.00..5.35 rows=122 width=0) (actual time=0.943..0.943 rows=6079 loops=1)
               Index Cond: (id_object = '8b41d75c-4371-4414-9c85-e84d43bb319a'::uuid)
               Buffers: shared hit=28
 Planning time: 0.172 ms
 Execution time: 42.663 ms
(11 rows)

Time: 44,534 ms

à noter que le "ix_mytable_id_object" n'est pas la clé primaire, c'est l'index dédié à l'id_object.
Merci pour votre aide!

Dernière modification par thomasp (02/05/2016 15:56:01)

rjuju

Administrateur

Re : Premier update très long, mais les suivants sont instantannés

Le premier plan montre que de nombreux blocs sont modifiés (dirtied=1006 et dirtied=3267, soit 33 Mo).

Est-ce que la table aurait été restaurée (ou chargée à l'aide de l'instruction COPY) plus ou moins récemment, ou s'agit-il d'un serveur de standby qui aurait été promu ? De quelle version de postgres s'agit-il, et est-ce que l'autovacuum est activé ?

Pouvez-vous essayer de faire un VACUUM ANALYZE sur la table, puis essayer de refaire des explain sur un nouveau id_object ?

---

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

thomasp

Membre

Re : Premier update très long, mais les suivants sont instantannés

Bonjour,
Tout à fait, c'est une table créée par un script puis remplie avec l'instruction COPY depuis des fichiers csv. C'est fait quotidiennement dans le cadre d'une migration de données depuis SQL Server vers Postgresql.
- La version du serveur DB est :  PostgreSQL 9.4.7 on x86_64-unknown-linux-gnu, compiled by gcc (Debian 4.9.2-10) 4.9.2, 64-bit
- L'autovaccum est activé, vous tourverez ci-dessous les différentes options,
- J'ai un fillfactor=70 indiqué pour la table mytable.
- J'ai fait le vacuum analyze sur mytable, les résultats des 2 explains sont en fin de message.

Merci encore pour votre aide !

-- VALEURS AUTOVACUUM :
-- select name, setting, context, vartype,source,min_val,max_val,enumvals,boot_val,reset_val
-- from pg_settings
-- where name like 'autovacuum%';

                name                 |  setting  |  context   | vartype | source  | min_val |  max_val   | enumvals | boot_val  | reset_val
-------------------------------------+-----------+------------+---------+---------+---------+------------+----------+-----------+-----------
 autovacuum                          | on        | sighup     | bool    | default | [null]  | [null]     | [null]   | on        | on
 autovacuum_analyze_scale_factor     | 0.1       | sighup     | real    | default | 0       | 100        | [null]   | 0.1       | 0.1
 autovacuum_analyze_threshold        | 50        | sighup     | integer | default | 0       | 2147483647 | [null]   | 50        | 50
 autovacuum_freeze_max_age           | 200000000 | postmaster | integer | default | 100000  | 2000000000 | [null]   | 200000000 | 200000000
 autovacuum_max_workers              | 3         | postmaster | integer | default | 1       | 8388607    | [null]   | 3         | 3
 autovacuum_multixact_freeze_max_age | 400000000 | postmaster | integer | default | 10000   | 2000000000 | [null]   | 400000000 | 400000000
 autovacuum_naptime                  | 60        | sighup     | integer | default | 1       | 2147483    | [null]   | 60        | 60
 autovacuum_vacuum_cost_delay        | 20        | sighup     | integer | default | -1      | 100        | [null]   | 20        | 20
 autovacuum_vacuum_cost_limit        | -1        | sighup     | integer | default | -1      | 10000      | [null]   | -1        | -1
 autovacuum_vacuum_scale_factor      | 0.2       | sighup     | real    | default | 0       | 100        | [null]   | 0.2       | 0.2
 autovacuum_vacuum_threshold         | 50        | sighup     | integer | default | 0       | 2147483647 | [null]   | 50        | 50
 autovacuum_work_mem                 | -1        | sighup     | integer | default | -1      | 2147483647 | [null]   | -1        | -1

-- PREMIER UPDATE
                                                                  QUERY PLAN
----------------------------------------------------------------------------------------------------------------------------------------------
 Update on mytable  (cost=5.54..501.43 rows=127 width=84) (actual time=197.794..197.794 rows=0 loops=1)
   Buffers: shared hit=10917 read=2238 dirtied=2627
   ->  Bitmap Heap Scan on mytable  (cost=5.54..501.43 rows=127 width=84) (actual time=1.062..26.874 rows=874 loops=1)
         Recheck Cond: (id_object = 'd9700727-bf42-4891-9541-2e3c8cb9dc8e'::uuid)
         Heap Blocks: exact=873
         Buffers: shared hit=821 read=62
         ->  Bitmap Index Scan on ix_mytable_id_object_id_user  (cost=0.00..5.51 rows=127 width=0) (actual time=0.701..0.701 rows=874 loops=1)
               Index Cond: (id_object = 'd9700727-bf42-4891-9541-2e3c8cb9dc8e'::uuid)
               Buffers: shared hit=1 read=9
 Planning time: 0.581 ms
 Execution time: 197.858 ms
(11 rows)

Time: 211,457 ms

-- DEUXIEME UPDATE
explain (analyze,buffers) update mytable set weight=weight+1 where id_object = 'd9700727-bf42-4891-9541-2e3c8cb9dc8e';
                                                                  QUERY PLAN
-----------------------------------------------------------------------------------------------------------------------------------------------
 Update on mytable  (cost=5.54..501.43 rows=127 width=84) (actual time=151.729..151.729 rows=0 loops=1)
   Buffers: shared hit=13145 read=6 dirtied=7
   ->  Bitmap Heap Scan on mytable  (cost=5.54..501.43 rows=127 width=84) (actual time=0.693..4.974 rows=874 loops=1)
         Recheck Cond: (id_object = 'd9700727-bf42-4891-9541-2e3c8cb9dc8e'::uuid)
         Heap Blocks: exact=873
         Buffers: shared hit=893 dirtied=1
         ->  Bitmap Index Scan on ix_mytable_id_object_id_user  (cost=0.00..5.51 rows=127 width=0) (actual time=0.427..0.427 rows=1748 loops=1)
               Index Cond: (id_object = 'd9700727-bf42-4891-9541-2e3c8cb9dc8e'::uuid)
               Buffers: shared hit=20
 Planning time: 0.154 ms
 Execution time: 151.824 ms
(11 rows)

Time: 157,755 ms

NB : ce n'est pas le même index que précédemment qui est utilisé, cette fois c'est  ix_mytable_id_object_id_user, qui est le même que la clé primaire (id_user, id_object) mais avec les colonnes inversées (on accède à cette table aussi bien par le user que par l'object, mais je ne sais pas si cet index est indispensable).

Dernière modification par thomasp (09/05/2016 11:49:05)