optimisation :explain et fuite temporelle

[Lady]

Ok j'ai ce que j’appellerais "une fuite temporelle".

Je viens de découvrir "EXPLAIN" et je l'applique donc sur un requête qui me prend bien 5 secondes sauf que le EXPLAIN me donne un coût final de 362 ce qui sur mes autres requêtes vaut à peine 100 ms en général.

Je fais donc un EXPLAIN ANALYZE et là :

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
 
"Hash Semi Join  (cost=360.62..362.76 rows=1 width=18) (actual time=12117.600..12117.673 rows=11 loops=1)"
"  Hash Cond: (publication_validation.pubval_pub_id = test.pub_id)"
"  ->  Seq Scan on publication_validation  (cost=0.00..1.90 rows=90 width=18) (actual time=0.015..0.070 rows=25 loops=1)"
"  ->  Hash  (cost=360.60..360.60 rows=1 width=4) (actual time=12117.503..12117.503 rows=11 loops=1)"
"        ->  HashAggregate  (cost=360.58..360.59 rows=1 width=4) (actual time=12117.453..12117.474 rows=11 loops=1)"
"              ->  Nested Loop  (cost=12.08..360.58 rows=1 width=4) (actual time=10477.601..12117.351 rows=12 loops=1)"
"                    Join Filter: ((author_publication_personne.publication_pub_id = test.pub_id) AND (pmid_requete.pmid_valeur = test.pub_pmid))"
"                    ->  Nested Loop  (cost=12.08..349.33 rows=1 width=8) (actual time=0.593..700.076 rows=113758 loops=1)"
"                          ->  Nested Loop  (cost=12.08..341.80 rows=1 width=8) (actual time=0.545..56.977 rows=687 loops=1)"
"                                ->  Nested Loop  (cost=12.08..338.36 rows=1 width=8) (actual time=0.512..39.788 rows=619 loops=1)"
"                                      ->  Nested Loop  (cost=12.08..337.49 rows=1 width=8) (actual time=0.473..27.738 rows=42 loops=1)"
"                                            Join Filter: ((personne.per_normedprenom)::text = (author.aut_normedforename)::text)"
"                                            ->  Hash Join  (cost=12.08..83.71 rows=48 width=20) (actual time=0.362..17.912 rows=48 loops=1)"
"                                                  Hash Cond: (personne.per_id = profilproj.personne_per_id)"
"                                                  ->  Seq Scan on personne  (cost=0.00..64.02 rows=1902 width=20) (actual time=0.030..13.820 rows=1902 loops=1)"
"                                                  ->  Hash  (cost=11.48..11.48 rows=48 width=8) (actual time=0.292..0.292 rows=48 loops=1)"
"                                                        ->  Seq Scan on profilproj  (cost=0.00..11.48 rows=48 width=8) (actual time=0.017..0.196 rows=48 loops=1)"
"                                            ->  Index Scan using aut_normedlname on author  (cost=0.00..5.23 rows=4 width=17) (actual time=0.042..0.167 rows=12 loops=48)"
"                                                  Index Cond: ((author.aut_normedlastname)::text = (personne.per_normednom)::text)"
"                                      ->  Index Scan using author_has_publication_fkindex1 on author_publication_personne  (cost=0.00..0.70 rows=13 width=8) (actual time=0.034..0.220 rows=15 loops=42)"
"                                            Index Cond: (author_publication_personne.author_aut_id = author.aut_id)"
"                                ->  Index Scan using req_profilproj_pro_id_idx on requetepubmed  (cost=0.00..3.43 rows=1 width=8) (actual time=0.011..0.014 rows=1 loops=619)"
"                                      Index Cond: (requetepubmed.profilproj_pro_id = profilproj.pro_id)"
"                          ->  Index Scan using pmid_req_req_id_idx on pmid_requete  (cost=0.00..7.52 rows=1 width=8) (actual time=0.008..0.351 rows=166 loops=687)"
"                                Index Cond: (pmid_requete.requete_req_id = requetepubmed.req_id)"
"                    ->  Seq Scan on test  (cost=0.00..10.50 rows=50 width=8) (actual time=0.002..0.047 rows=25 loops=113758)"
"Total runtime: 12120.127 ms"

Alors soit j'ai la berlue soit J'ai un trou entre 700 ms (ligne 9) et 10477(ligne 7).

Comme je dit je débute avec le Explain (et son interprétation) quelqu'un aurait il une explication?


Ah et la requête en question :

Code :

1
2
3
4
UPDATE import_brut_pubmed.publication_validation SET pubval_regle4 = 1 WHERE pubval_pub_id IN ( SELECT DISTINCT pub_id 
FROM annuaire.personne,  mod_proj.profilproj,  mod_proj.requetepubmed, import_brut_pubmed.pmid_requete,  test, import_brut_pubmed.author_publication_personne, import_brut_pubmed.author 
WHERE  personne.per_id = profilproj.personne_per_id AND requetepubmed.profilproj_pro_id=profilproj.pro_id AND requetepubmed.req_id = pmid_requete.requete_req_id AND pmid_requete.pmid_valeur = test.pub_pmid AND test.pub_id = author_publication_personne.publication_pub_id AND author_publication_personne.author_aut_id = author.aut_id 
AND  personne.per_normednom=author.aut_normedlastname AND    personne.per_normedprenom=author.aut_normedforename );

Désolée pour ceux à qui ça à fait saigner les yeux ....

ps: j'ai testé en remplaçant le From tab1,tab2... where .... par des INNER JOIN mais j'ai la même trace. (C'est pas moi qui ai écrit la requête au départ...)

[estofilo]

Il est possible d'avoir une représentation visuelle un peu plus sympa en copiant le plan ici:
http://explain.depesz.com

Ce qui est bizarre surtout à la ligne 9:

Nested Loop  (cost=12.08..349.33 rows=1 width=8) (actual time=0.593..700.076 rows=113758 loops=1)"

C'est que l'estimation est d'1 ligne alors que la réalité est de 113758 lignes.
Souvent ça veut dire que les statistiques ne sont pas à jour (faire ANALYZE sur les tables concernées pour être sûr) ou bien que certaines colonnes ont un échantillon statistique trop faible, ce dernier paramètre étant réglable par colonne avec ALTER TABLE.. ALTER COLUMN...SET STATISTICS

Apparemment la table test est parcourue 113758 fois (voir dernière ligne de l'explain) ce qui explique probablement la lenteur globale, même si la table a peu de lignes.

[Lady]

Envoyé par estofilo

Il est possible d'avoir une représentation visuelle un peu plus sympa en copiant le plan ici:
http://explain.depesz.com

Ce qui est bizarre surtout à la ligne 9:

Nested Loop  (cost=12.08..349.33 rows=1 width=8) (actual time=0.593..700.076 rows=113758 loops=1)"

C'est que l'estimation est d'1 ligne alors que la réalité est de 113758 lignes.
Souvent ça veut dire que les statistiques ne sont pas à jour (faire ANALYZE sur les tables concernées pour être sûr) ou bien que certaines colonnes ont un échantillon statistique trop faible, ce dernier paramètre étant réglable par colonne avec ALTER TABLE.. ALTER COLUMN...SET STATISTICS

Apparemment la table test est parcourue 113758 fois (voir dernière ligne de l'explain) ce qui explique probablement la lenteur globale, même si la table a peu de lignes.

Ok merci pour le lien déjà

La table Test est une table temporaire faite à partir du filtrage d'une autre table (je passe d'une table de 52000 lignes à une de 25) du coup y a pas de statistiques dessus je pense.
Je me penche là dessus.

Merci !