Forums PostgreSQL.fr

etpaf

Membre

Requète (très, très) lente...

Bonjour à tous,

J'ai une requête qui est franchement lente et je ne comprends pas le pourquoi...

Ma config : serveur dédié, postgresql 8.2.14 sous RHEL 4.4. (8giga ram, disque en raid 10)

La requète :

SELECT DISTINCT lm_action.entry_key , lm_action.pkey , lm_action.creation_ts , lm_action.origin , lm_action.polhid
FROM lm_action
INNER JOIN lm_status ON (lm_action.pkey=lm_status.action_key )
WHERE lm_action.inactif_uid is null AND lm_status.status IN (2 , 1 )
AND lm_status.inactif_uid is null
AND lm_action.entry_key in (3974400 , 3958028 , 3940355 , 3940309 , 3917969 , 3911509 , 3888821 , 3870523 , 3862873 , 3816029 , 3804693 , 3799560 , 3799546 , 3799542 , 3794777 , 3782636 , 3771277 , 3771233 , 3771222 , 3764226 , 3764147 , 3764136 , 3764130 , 3764125 , 3764121 , 3754407 , 3754396 , 3748869 , 3744775 , 3744774 , 3744772 , 3744771 , 3744764 , 3744758 , 3744742 )
ORDER BY origin;

Son temps d'exécution : 446723 ms pour rapporter 851 lignes.

Les tables :
CREATE TABLE lm_action
(
  pkey bigserial NOT NULL,
  entry_key bigint,
  regrouping_key bigint,
  creation_ts timestamp without time zone,
  origin timestamp without time zone,
  polhid integer,
  inactif_uid bigint,
  CONSTRAINT lm_action_pkey PRIMARY KEY (pkey),
  CONSTRAINT lm_action_fk FOREIGN KEY (entry_key)
      REFERENCES lm_entry (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT lm_action_fk1 FOREIGN KEY (regrouping_key)
      REFERENCES lm_entry_regrouping (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION
)
WITH (
  OIDS=TRUE
);
ALTER TABLE lm_action OWNER TO arthur;

CREATE INDEX idx_lm_action_entry_key
  ON lm_action
  USING btree
  (entry_key);

CREATE TABLE lm_status
(
  pkey bigserial NOT NULL,
  entry_key bigint,
  action_key bigint,
  regrouping_key bigint,
  status smallint,
  creation_ts timestamp(0) without time zone NOT NULL,
  polhid integer NOT NULL,
  inactif_uid bigint,
  origin timestamp without time zone,
  CONSTRAINT lm_status_pkey PRIMARY KEY (pkey),
  CONSTRAINT lm_status_fk FOREIGN KEY (entry_key)
      REFERENCES lm_entry (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT lm_status_fk1 FOREIGN KEY (regrouping_key)
      REFERENCES lm_entry_regrouping (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT lm_status_fk2 FOREIGN KEY (action_key)
      REFERENCES lm_action (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION,
  CONSTRAINT lm_status_fk3 FOREIGN KEY (inactif_uid)
      REFERENCES lm_delete_data (pkey) MATCH SIMPLE
      ON UPDATE NO ACTION ON DELETE NO ACTION
)
WITH (
  OIDS=TRUE
);
ALTER TABLE lm_status OWNER TO arthur;

CREATE INDEX idx_lm_status_action_key
  ON lm_status
  USING btree
  (action_key);

CREATE INDEX idx_lm_status_entry_key
  ON lm_status
  USING btree
  (entry_key);

CREATE INDEX idx_lm_status_origin
  ON lm_status
  USING btree
  (origin);

CREATE INDEX idx_lm_status_status
  ON lm_status
  USING btree
  (status);

CREATE INDEX lm_status_idx2
  ON lm_status
  USING btree
  (regrouping_key);

Le plan d'exécution :

Je suis assez perplexe car je ne dépasse pas les 2 secondes pour les autres requêtes sur ma DB.
Pour configurer postgresql.conf, j'ai utilisé pg_tune (légèrement adapté).

Est-ce que l'un d'entre vous voit la cause de ces lenteurs?
D'avance merci pour votre aide.

Dernière modification par etpaf (17/02/2010 15:05:10)

gleu

Administrateur

Re : Requète (très, très) lente...

C'est bien d'avoir pensé au plan d'exécution. Par contre, le plan de pgAdmin apporte assez peu d'informations. Indiquez plutôt le résultat texte du EXPLAIN ANALYZE.

---

Guillaume.

etpaf

Membre

Re : Requète (très, très) lente...

Bonjour,

Merci pour l'intérêt porté à ma question.

L'explain analyse donne ceci :

Unique  (cost=1900115.33..1919800.62 rows=1312353 width=36) (actual time=327436.701..327446.455 rows=855 loops=1)
  ->  Sort  (cost=1900115.33..1903396.21 rows=1312353 width=36) (actual time=327436.691..327439.849 rows=864 loops=1)
        Sort Key: lm_action.origin, lm_action.entry_key, lm_action.pkey, lm_action.creation_ts, lm_action.polhid
        ->  Hash Join  (cost=886494.66..1735996.83 rows=1312353 width=36) (actual time=310684.445..327431.949 rows=864 loops=1)
              Hash Cond: (lm_status.action_key = lm_action.pkey)
              ->  Bitmap Heap Scan on lm_status  (cost=176955.22..794709.68 rows=11597756 width=8) (actual time=100966.826..279975.553 rows=10740857 loops=1)
                    Recheck Cond: (status = ANY ('{2,1}'::integer[]))
                    Filter: (inactif_uid IS NULL)
                    ->  Bitmap Index Scan on idx_lm_status_status  (cost=0.00..174055.78 rows=11656037 width=0) (actual time=100895.813..100895.813 rows=10854635 loops=1)
                          Index Cond: (status = ANY ('{2,1}'::integer[]))
              ->  Hash  (cost=632301.26..632301.26 rows=3802495 width=36) (actual time=73.277..73.277 rows=897 loops=1)
                    ->  Bitmap Heap Scan on lm_action  (cost=89929.49..632301.26 rows=3802495 width=36) (actual time=0.909..58.674 rows=897 loops=1)
                          Recheck Cond: (entry_key = ANY ('{3974400,3958028,3940355,3940309,3917969,3911509,3888821,3870523,3862873,3816029,3804693,3799560,3799546,3799542,3794777,3782636,3771277,3771233,3771222,3764226,3764147,3764136,3764130,3764125,3764121,3754407,3754396,3748869,3744775,3744774,3744772,3744771,3744764,3744758,3744742}'::bigint[]))
                          Filter: (inactif_uid IS NULL)
                          ->  Bitmap Index Scan on idx_lm_action_entry_key  (cost=0.00..88978.86 rows=4917019 width=0) (actual time=0.853..0.853 rows=1215 loops=1)
                                Index Cond: (entry_key = ANY ('{3974400,3958028,3940355,3940309,3917969,3911509,3888821,3870523,3862873,3816029,3804693,3799560,3799546,3799542,3794777,3782636,3771277,3771233,3771222,3764226,3764147,3764136,3764130,3764125,3764121,3754407,3754396,3748869,3744775,3744774,3744772,3744771,3744764,3744758,3744742}'::bigint[]))

J'ai aussi vérifié les vacuum et le dernier date de moins de 12h.

Existe-t-il un petit programme qui permette d'interpréter les valeurs retournées par l'explain analyse facilement?

Dernière modification par etpaf (18/02/2010 10:25:47)

gleu

Administrateur

Re : Requète (très, très) lente...

Existe-t-il un petit programme qui permette d'interpréter ce genre de renseignements facilement?

Non, c'est surtout une question d'expérience

Néanmoins, copiez le explain analyze sur le site http://explain.depesz.com/ et vous obtenez ceci : http://explain.depesz.com/s/Gk

Donc, on s'aperçoit que les statistiques sont clairement à l'ouest. Si je prends la première opération (dernière ligne, Bitmap Index Scan), le planificateur suppose qu'il va récupérer pratiquement 5 millions de lignes (4917019 lignes exactement) alors qu'à l'exécution, il n'en récupère que 1215. Je pense qu'il serait intéressant de mettre à jour les statistiques sur les données. Un ANALYZE sur la base suffit pour cela.

Par contre, je ne suis pas sûr que ça suffira à améliorer les perfs. La requête demande quand même la lecture de 11 millions de lignes dans lm_status.

---

Guillaume.

etpaf

Membre

Re : Requète (très, très) lente...

Je viens de lancer un analyse depuis pg_admin sur les 2 tables et je passe maintenant à 137000ms, il y a effectivement un mieux.

Je croyais que Postgres gérais les analyses et vacuum sur base du fichier postgresql.conf, le mien serait-il mal configuré?

J'utilise ceci :

autovacuum  = on
autovacuum_naptime  = 60
autovacuum_vacuum_threshold  = 250 
autovacuum_analyze_threshold  = 125
autovacuum_vacuum_scale_factor  = 0.4
autovacuum_analyze_scale_factor  = 0.2

vacuum_cost_delay  = 0
vacuum_cost_page_hit  = 1
vacuum_cost_page_miss  = 10
vacuum_cost_page_dirty  = 20
vacuum_cost_limit  = 200

Manque-t-il des paramètres?

Dernière modification par etpaf (18/02/2010 12:55:23)

gleu

Administrateur

Re : Requète (très, très) lente...

Ce que le fichier indique, c'est que l'autovacuum va lancer un ANALYZE sur les tables dont le nombre d'insert, update, delete a dépassé 125 lignes + 20% de la taille de la table en nombre de lignes. C'est à dire certainement beaucoup pour votre table qui doit faire plus de 12 millions de lignes. Une configuration particulière pour cette table serait certainement utile. Descendre les valeurs par défaut peut aussi être un plus.

---

Guillaume.

etpaf

Membre

Re : Requète (très, très) lente...

Merci pour ces renseignements...
Je vais encore abuser mais comment fait-on une configuration particulière pour une table?

gleu

Administrateur

Re : Requète (très, très) lente...

Sur une 8.2, il faut insérer une ligne dans pg_autovacuum. Voir http://docs.postgresql.fr/8.2/catalog-p … acuum.html pour les détails.

---

Guillaume.

etpaf

Membre

Re : Requète (très, très) lente...

Merci encore...

Chose étrange, après avoir lancé 1 analyse, ça s'accélère mais...

Unique  (cost=1940027.55..1963256.44 rows=1548593 width=36) (actual time=188216.157..188225.939 rows=858 loops=1)
  ->  Sort  (cost=1940027.55..1943899.03 rows=1548593 width=36) (actual time=188216.148..188219.323 rows=867 loops=1)
        Sort Key: lm_action.origin, lm_action.entry_key, lm_action.pkey, lm_action.creation_ts, lm_action.polhid
        ->  Hash Join  (cost=896687.13..1744515.62 rows=1548593 width=36) (actual time=171962.153..188211.231 rows=867 loops=1)
              Hash Cond: (lm_status.action_key = lm_action.pkey)
              ->  Bitmap Heap Scan on lm_status  (cost=163653.01..769996.01 rows=10693207 width=8) (actual time=28388.613..133203.947 rows=10744023 loops=1)
                    Recheck Cond: (status = ANY ('{2,1}'::integer[]))
                    Filter: (inactif_uid IS NULL)
                    ->  Bitmap Index Scan on idx_lm_status_status  (cost=0.00..160979.71 rows=10732560 width=0) (actual time=28314.001..28314.001 rows=10857831 loops=1)
                          Index Cond: (status = ANY ('{2,1}'::integer[]))
              ->  Hash  (cost=633064.22..633064.22 rows=4921592 width=36) (actual time=16.765..16.765 rows=1215 loops=1)
                    ->  Bitmap Heap Scan on lm_action  (cost=90336.65..633064.22 rows=4921592 width=36) (actual time=1.112..8.834 rows=1215 loops=1)
                          Recheck Cond: (entry_key = ANY ('{3974400,3958028,3940355,3940309,3917969,3911509,3888821,3870523,3862873,3816029,3804693,3799560,3799546,3799542,3794777,3782636,3771277,3771233,3771222,3764226,3764147,3764136,3764130,3764125,3764121,3754407,3754396,3748869,3744775,3744774,3744772,3744771,3744764,3744758,3744742}'::bigint[]))
                          ->  Bitmap Index Scan on idx_lm_action_entry_key  (cost=0.00..89106.25 rows=4921592 width=0) (actual time=1.058..1.058 rows=1215 loops=1)
                                Index Cond: (entry_key = ANY ('{3974400,3958028,3940355,3940309,3917969,3911509,3888821,3870523,3862873,3816029,3804693,3799560,3799546,3799542,3794777,3782636,3771277,3771233,3771222,3764226,3764147,3764136,3764130,3764125,3764121,3754407,3754396,3748869,3744775,3744774,3744772,3744771,3744764,3744758,3744742}'::bigint[]))
Total runtime: 137230.291 ms

Le nombre de ligne rapportées ne change pas, les données sont pourtant récupérées plus rapidement (mise en cache?).

gleu

Administrateur

Re : Requète (très, très) lente...

La mise en cache doit jouer. Si un ANALYZE récent n'améliore pas les statistiques, c'est que l'échantillon statistique n'est pas assez important. Il pourrait être intéressant de tester avec un default_statistics_target plus important ou en configurant spécifiquement cette table

---

Guillaume.

etpaf

Membre

Re : Requète (très, très) lente...

Bonjour,

La différence est énorme, avec un SET STATISTICS à 500 sur mon index, l'analyse est 2 fois plus lent mais la requête ne prend plus que 469ms.
Un tout grand merci pour le coup de main.

Une dernière question, concernant l'analyse, puis-je mettre autovacuum_analyze_scale_factor à 0?

SAS

Membre

Re : Requète (très, très) lente...

Bonjour,

Comment sont répartis les status dans la table lm_status ?

---

Stéphane Schildknecht
Conseil, formations et support PostgreSQL
http://www.loxodata.com

etpaf

Membre

Re : Requète (très, très) lente...

Je ne sais pas trop, je n'ai pas développé l'application...
Ca a une importance?

gleu

Administrateur

Re : Requète (très, très) lente...

Si vous mettez un scale_factor, il y a de fortes chances que vous ayez un ANALYZE toutes les autovacuum_naptime (soit, il me semble, toutes les minutes). Ça n'est pas une bonne idée à mon avis.

---

Guillaume.

SAS

Membre

Re : Requète (très, très) lente...

Je m'interrogeais sur les valeurs de lm_status, parce que si vous n'avez que quelques valeurs distinctes pour lm_status, et que votre requête porte sur 2 valeurs qui offrent peu de discriminance, il y a de fortes chances que l'index ne soit pas utilisé.

Mais entre temps, vous avez observé une très nette amélioration lorsque les statistiques étaient calculées sur plus de valeur (set statistics à 500).

Avec un scale_factor à 0, je dirai que cela dépend de la fréquence des mises à jour. L'analyze se déclenchera dès que vous avez 125 lignes modifiées.

---

Stéphane Schildknecht
Conseil, formations et support PostgreSQL
http://www.loxodata.com

etpaf

Membre

Re : Requète (très, très) lente...

Merci pour votre aide.
Je vais donc laisser autovacuum_analyze_scale_factor  = 0.2 dans mon fichier de propriété.
Je ferai aussi une ligne dans pg_autovacuum pour chacune des grosses tables manipulées par l'application avec scale_factor à 0 et fréquence d'analyse et vacuum respectivement à 5000 et 10.000 lignes modifiées.
J'ai par contre abaissé à 100 le set statistics car j'ai constaté une grosse montée de l'utilisation de mon file system avec le set statistics à 500 (nettement moindre mais tout aussi performant à 100).