Vous n'êtes pas identifié(e).
Pages : 1
Bonjour,
Un batch lancé depuis un serveur applicatif sur la base de données mettait moins de 5mn à s'exécuter.
Depuis un upgrade PostgreSQL 9.4 –> 9.6 + changement de plateforme + mise en réplication, il met près de 50mn.
En activant les traces je peux voir que l'attente se situe au niveau d'une requête de select qui mets 2868220.280 ms soit 47mn.
Si pendant ces 47mn, j'exécute la même requête avec le même compte directement sur la base, elle mets 716ms, excluant il me semble, les problèmes de locks ou de contention.
J’ai du mal à croire que c’est lié au changement de version car ma commande directe passe très bien.
Pour moi le problème vient du traitement du résultat du SELECT qui est fait au niveau du serveur applicatif (scripts en java), voire éventuellement du réseau.
Que pensez-vous de ma conclusion ?
L'équipe applicative ne sait pas pour l'instant tracer ce qui se passe sur le serveur applicatif, c'est à dire tracer ce qui est fait du résultat du SELECT.
Puis-je vérifier autre chose depuis le serveur de base de données ?
Merci.
Henri Couroussé
Voici le détail des traces et de l'explain analyze
Session vue du serveur de base de données PostgreSQL
2018-06-20 10:16:03 CEST;4066;[unknown];[unknown];LOG: connection received: host=10.198.136.216 port=56610
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: connection authorized: user=ps3a01owner database=ps3a01
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.069 ms parse S_1: BEGIN
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.010 ms bind S_1: BEGIN
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: execute S_1: BEGIN
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.029 ms
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 2.412 ms parse <unnamed>: SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 2.474 ms bind <unnamed>: SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation
2018-06-20 10:16:03 CEST;4066;ps3a01owner;ps3a01;LOG: execute <unnamed>: SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation
2018-06-20 11:03:51 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 2868220.280 ms
2018-06-20 11:03:53 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.037 ms parse S_2: COMMIT
2018-06-20 11:03:53 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.625 ms bind S_2: COMMIT
2018-06-20 11:03:53 CEST;4066;ps3a01owner;ps3a01;LOG: execute S_2: COMMIT
2018-06-20 11:03:53 CEST;4066;ps3a01owner;ps3a01;LOG: duration: 0.044 ms
2018-06-20 11:03:53 CEST;4066;ps3a01owner;ps3a01;LOG: disconnection: session time: 0:47:50.518 user=ps3a01owner database=ps3a01 host=10.198.136.216 port=56610
Explain Analyze sur le serveur de base de données PostgreSQL
ps3a01=> explain analyze SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation;
QUERY PLAN
------------------------------------------------------------------------------------------------------------------------------------------------------------
-----------
Hash Join (cost=99075.03..104536.53 rows=1 width=109) (actual time=640.067..714.015 rows=20276 loops=1)
Hash Cond: ((w_dm.num_dm)::text = "substring"((commande.reference_commande_ihm)::text, 5, (char_length((commande.reference_commande)::text) - 4)))
-> Seq Scan on w_dm (cost=0.00..4774.35 rows=91618 width=88) (actual time=0.014..29.885 rows=91540 loops=1)
Filter: ((reference_commande IS NULL) OR ((reference_commande)::text = ''::text))
Rows Removed by Filter: 24408
-> Hash (cost=99075.02..99075.02 rows=1 width=39) (actual time=635.345..635.345 rows=38873 loops=1)
Buckets: 65536 (originally 1024) Batches: 1 (originally 1) Memory Usage: 2893kB
-> Hash Join (cost=95250.21..99075.02 rows=1 width=39) (actual time=559.275..609.277 rows=38873 loops=1)
Hash Cond: (((c.reference_commande_ihm)::text = (commande.reference_commande_ihm)::text) AND ((max(c.date_creation_sam)) = commande.date_crea
tion_sam))
-> HashAggregate (cost=47425.04..47807.52 rows=38248 width=26) (actual time=274.330..297.304 rows=38873 loops=1)
Group Key: c.reference_commande_ihm
-> Seq Scan on commande c (cost=0.00..47224.97 rows=40013 width=26) (actual time=0.037..193.109 rows=39281 loops=1)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
Rows Removed by Filter: 265529
-> Hash (cost=47224.97..47224.97 rows=40013 width=47) (actual time=284.611..284.611 rows=39281 loops=1)
Buckets: 65536 Batches: 1 Memory Usage: 3297kB
-> Seq Scan on commande (cost=0.00..47224.97 rows=40013 width=47) (actual time=0.067..261.897 rows=39281 loops=1)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
Rows Removed by Filter: 265529
Planning time: 1.160 ms
Execution time: 716.049 ms
(21 rows)
Hors ligne
Si la requête s'effectue dans une transaction, exécuter la même requête de manière concurrente ne traitera pas les même données. À mon avis, le seul moyen d'avoir une idée claire de pourquoi cette requête met autant de temps à s'exécuter est d'activer le module auto_explain, et le configurer pour afficher le plan des requêtes de plus d'une demi-heure par exemple. Idéalement, il faudrait également activer les options :
- log_analyze
- log_buffers
- log_timing
- log_triggers
puis de nous fournir le plan d'exécution ainsi obtenu. Attention toutefois, l'activation de ce module (dans session_preload_librairies pour éviter un redémarrage) pourrait avoir un impact important sur les performances générales.
Julien.
https://rjuju.github.io/
Hors ligne
Merci Julien.
J'ai la chance de pouvoir reproduire le phénomène sur un serveur de qualif.
Je vais donc mettre en oeuvre ces outils pour fournir le plan d'exécution obtenu.
Henri
Hors ligne
Bonjour,
Voici déjà le résultat de l'explain sans activation de :
- log_analyze
- log_buffers
- log_timing
- log_triggers
Je relance un traitement avec ces paramètres activés
2018-06-22 16:15:51 CEST;20426;ps3a01owner;ps3a01;LOG: duration: 2776251.011 ms plan:
Query Text: SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation
Nested Loop (cost=94943.18..102185.48 rows=1 width=647)
Join Filter: ("substring"((commande.reference_commande_ihm)::text, 5, (char_length((commande.reference_commande)::text) - 4)) = (w_dm.num_dm)::text)
-> Hash Join (cost=94943.18..98733.79 rows=1 width=39)
Hash Cond: (((c.reference_commande_ihm)::text = (commande.reference_commande_ihm)::text) AND ((max(c.date_creation_sam)) = commande.date_creation_sam))
-> HashAggregate (cost=47272.16..47651.22 rows=37906 width=26)
Group Key: c.reference_commande_ihm
-> Seq Scan on commande c (cost=0.00..47072.74 rows=39885 width=26)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
-> Hash (cost=47072.74..47072.74 rows=39885 width=47)
Buckets: 65536 Batches: 1 Memory Usage: 3286kB
-> Seq Scan on commande (cost=0.00..47072.74 rows=39885 width=47)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
-> Seq Scan on w_dm (cost=0.00..3449.69 rows=100 width=626)
Filter: ((reference_commande IS NULL) OR ((reference_commande)::text = ''::text))
Hors ligne
Voici la structure de la table commande
=> \d commande
Table "xxx.commande"
Column | Type | Modifiers
----------------------------------+-----------------------------+-----------------------
reference_commande | character varying(30) | not null
version | integer | not null
ado | character varying(3) | not null
ado_code_groupe_responsable | character varying(12) |
ado_fax_rai | character varying(30) |
ado_groupe_responsable | character varying(80) |
ado_mail_rai | character varying(240) |
ado_nom_rai | character varying(40) |
ado_prenom_rai | character varying(40) |
ado_tel_rai | character varying(30) |
affaire_externe | character varying(20) |
cerac | boolean |
chef_projet | character varying(40) |
cle_echange_feuillet | character varying(32) |
cle_echange_opus | character varying(32) |
cle_echange_su | character varying(32) |
old_code_dernier_modificateur | character varying(12) |
code_insee | character varying(40) |
code_postal | character varying(40) |
code_production | character varying(50) |
code_responsable_extrem | character varying(12) |
code_responsable_global | character varying(12) |
commande_commerciale | character varying(30) |
commentaire_adv | text |
old_commentaire_coa | character varying(500) |
commentaire_complementaire | character varying(1000) |
old_commentaire_rai | character varying(500) |
commune | character varying(40) |
cpl_adresse | character varying(50) |
date_contractuelle | timestamp without time zone |
date_creation | timestamp without time zone |
old_date_derniere_modif | timestamp without time zone |
date_signature | timestamp without time zone |
date_souhaitee | timestamp without time zone |
devis_cablage | character varying(60) |
devis_materiel | character varying(20) |
entite_demandeur | character varying(30) |
fax_contact | character varying(30) |
financement | boolean |
heures_vendues | numeric(13,4) |
ident_etablissement | character varying(10) |
install_routeur | character varying(100) |
lib_voie | character varying(80) |
mail_contact | character varying(255) |
mail_demandeur | character varying(255) |
mob_contact | character varying(15) |
mode_regroupement | character varying(11) |
nom_client | character varying(100) |
nom_contact | character varying(100) |
nom_demandeur | character varying(40) |
old_nom_dernier_modificateur | character varying(40) |
nom_production | character varying(255) |
nom_responsable_extrem | character varying(80) |
nom_responsable_global | character varying(80) |
nd | character varying(100) |
nd_support | character varying(10) |
num_voie | character varying(38) |
pabx_ft | boolean |
old_poids | numeric(5,1) |
projet_osm | character varying(200) |
ref_support_nominal | character varying(1000) |
ref_support_secours | character varying(1000) |
service_satin | character varying(15) |
siret | character varying(15) |
statut_ado | character varying(30) |
tel_contact | character varying(30) |
telephone_demandeur | character varying(30) |
type_operation | character varying(30) |
type_production | character varying(30) |
affaire_interne | integer |
associable | character varying(1) |
offre | integer |
ado_code_postal | character varying(40) |
alert_ado | boolean | default false
association_manuelle | boolean |
pvcly | boolean |
lib_voie_assoc | character varying(100) |
date_creation_sam | timestamp without time zone |
compte_client_contrat | character varying(32) |
date_modification_sam | timestamp without time zone |
reference_commande_ihm | character varying(60) | not null
date_modification_ado | timestamp without time zone |
nds | character varying(100) |
old_etiquette | character varying(30) |
nd_cible | character varying(10) |
ado_ui_installation | character varying(45) |
nom_ip_pabx | character varying(250) |
nom_client_titulaire | character varying(100) |
tel_chef_projet | character varying(20) |
masque | character varying(18) |
gateway | character varying(15) |
eas_client | character varying(15) |
interface_site_client | character varying(60) |
perimetre_rai | boolean | not null default true
date_mad | timestamp without time zone |
date_saisie_datemad | timestamp without time zone |
date_cloture | timestamp without time zone |
date_facturation | timestamp without time zone |
heures_realisees | numeric(13,4) |
taux_avancement | numeric(13,4) |
date_contractuelle_debut_travaux | timestamp without time zone |
date_debut_rdv_client | timestamp without time zone |
date_fin_rdv_client | timestamp without time zone |
commentaire_date_contractuelle | character varying(50) |
commentaire_date_rdv_client | character varying(50) |
origine_commande | character varying(50) |
type_operation_sam | character varying(30) |
priorite | numeric(3,1) |
nom_pole_production | character varying(30) |
tel_pole_production | character varying(15) |
adresse_livraison | character varying(500) |
engagement_date_mes | boolean |
ref_cmd_materiel | character varying(255) |
nom_eas | character varying(20) |
cause_retard | character varying(10) |
old_id_inter_rdv_client | integer |
old_prochain_item_checklist | character varying(20) |
old_commentaire_prochain_item | character varying(50) |
batiment | character varying(20) |
ensemble | character varying(20) |
escalier | character varying(2) |
etage | character varying(50) |
porte | character varying(5) |
nsc | character varying(2) |
articletech | character varying(18) |
articletechlibelle | character varying(40) |
nbpaires | character varying(40) |
idcore | character varying(60) |
nomsitecore | character varying(50) |
ipsupervision_exta | character varying(15) |
ipmanager_exta | character varying(15) |
dps_actif | character varying(30) |
old_qualification | character varying(20) |
salto_seule | boolean |
alerte_recue_aacq | boolean |
alerte_emise_aacq | boolean |
mail_contact_ort | character varying(255) |
type_poste | character varying(4) |
old_commentaire_qualification | character varying(28) |
process | character varying(10) |
ref_support_repris | character varying(10) |
hotline_operateur | character varying(10) |
telephone_responsable_global | character varying(20) |
mail_responsable_global | character varying(255) |
salto_prioritaire | boolean |
poids_initial | numeric(5,1) |
mode_pilotage | character varying(30) |
nom_rac_ort | character varying(50) |
typage_obs | character varying(4) |
remoteid | character varying(30) |
remoteid_plaque | character varying(25) |
constit42c_1 | character varying(25) |
constit42c_2 | character varying(25) |
constit42c_3 | character varying(25) |
constit42c_4 | character varying(25) |
code_insee_nra | character varying(8) |
reference_erdv | character varying(64) |
Indexes:
"commande_pkey" PRIMARY KEY, btree (reference_commande)
"fki_affaire" btree (affaire_interne)
"idx_commande_ado" btree (ado)
"idx_commande_alert_ado" btree (alert_ado)
"idx_commande_client" btree (nom_client)
"idx_commande_projet_osm" btree (projet_osm)
"idx_commande_siret" btree (siret)
"idx_devis_materiel" btree (devis_materiel)
"idx_nb" btree (nd)
"idx_nd_cible" btree (nd_cible)
"idx_nd_support" btree (nd_support)
"idx_reference_commande" btree (reference_commande)
"idx_reference_commande_ihm" btree (reference_commande_ihm)
Foreign-key constraints:
"commande_affaire_interne_fkey" FOREIGN KEY (affaire_interne) REFERENCES affaire(identifiant)
"fkdff06e9a13d9a247" FOREIGN KEY (offre) REFERENCES offre(id_offre)
Referenced by:
TABLE "alarme" CONSTRAINT "alarme_reference_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "alerte" CONSTRAINT "alerte_fkey_commande" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "ancienne_adresse" CONSTRAINT "ancienne_adresse_reference_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_comma
nde)
TABLE "avp_commande" CONSTRAINT "avp_commande_cmd_fk" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "checklist" CONSTRAINT "checklist_fkey_commande" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "commande_prepa_intervention" CONSTRAINT "commande_prepa_intervention_fkey_commande" FOREIGN KEY (reference_commande) REFERENCES commande(ref
erence_commande)
TABLE "consigne" CONSTRAINT "consigne_fkey_commande" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "cr_fop" CONSTRAINT "cr_fop_reference_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "d42c_commande" CONSTRAINT "d42c_commande_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande) ON DELETE C
ASCADE
TABLE "etancheite" CONSTRAINT "etancheite_ref_commande" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "tache" CONSTRAINT "fk4cd4ef3b4faee05" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "historique_rdv" CONSTRAINT "historique_rdv_commande" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "nd_commande" CONSTRAINT "nd_commande_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "pilotage_commande" CONSTRAINT "pilotage_commande_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "prestation" CONSTRAINT "prestation_reference_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
TABLE "verrou" CONSTRAINT "verrou_reference_commande_fkey" FOREIGN KEY (reference_commande) REFERENCES commande(reference_commande)
Triggers:
trig_bef_insert_update_commande BEFORE INSERT OR UPDATE ON commande FOR EACH ROW EXECUTE PROCEDURE function_insert_update_commande()
et celle de la table w_dm
=> \d w_dm
Table "xxx.w_dm"
Column | Type | Modifiers
-----------------------------+-----------------------------+-----------
reference_commande | character varying(30) |
num_dm_origine | character varying(30) |
date_echeance | character varying(10) |
statut_dossier | character varying(70) |
magasin_origine | character varying(112) |
num_dm | character varying(30) |
code_magasin | character varying(10) |
nom_magasin | character varying(50) |
ville_magasin | character varying(50) |
type_transfert_livraisonbdd | character varying(30) |
magasin_secondaire | character varying(255) |
transfert_livraison | character varying(255) |
code_alliance_createur | character varying(12) |
code_magasin_secondaire | character varying |
nom_magasin_secondaire | character varying |
cp_magasin_secondaire | character varying |
ville_magasin_secondaire | character varying |
rue_magasin_secondaire | character varying |
type_transfert_livraison | character varying(30) |
date_echeance_precedente | timestamp without time zone |
Hors ligne
Bonjour,
Voici le résultat de l'auto_explain avec les paramètres activés :
- log_analyze
- log_buffers
- log_timing
- log_triggers
2018-06-22 17:22:09 CEST;1376;ps3a01owner;ps3a01;LOG: duration: 3090107.500 ms plan:
Query Text: SELECT w_dm.num_dm, w_dm.num_dm_origine, to_date(w_dm.date_echeance,'YYYY-MM-DD'), w_dm.statut_dossier, w_dm.code_magasin, w_dm.nom_magasin, w_dm.ville_magasin, commande.reference_commande FROM commande, (select * from w_dm where w_dm.reference_commande is null OR w_dm.reference_commande = '') w_dm, (select reference_commande_ihm, max(date_creation_sam)as maxDateCreation from commande c where reference_commande like 'BAC%' group by reference_commande_ihm) derniereCommande where commande.reference_commande like 'BAC%' and w_dm.num_dm= substring(commande.reference_commande_ihm from 5 for (char_length(commande.reference_commande)-4)) and commande.reference_commande_ihm = derniereCommande.reference_commande_ihm and commande.date_creation_sam = derniereCommande.maxDateCreation
Nested Loop (cost=94943.18..102185.48 rows=1 width=647) (actual time=679.458..3089866.978 rows=20240 loops=1)
Join Filter: ("substring"((commande.reference_commande_ihm)::text, 5, (char_length((commande.reference_commande)::text) - 4)) = (w_dm.num_dm)::text)
Rows Removed by Join Filter: 3544133940
Buffers: shared hit=128743000 read=77580
-> Hash Join (cost=94943.18..98733.79 rows=1 width=39) (actual time=457.790..1148.117 rows=38717 loops=1)
Hash Cond: (((c.reference_commande_ihm)::text = (commande.reference_commande_ihm)::text) AND ((max(c.date_creation_sam)) = commande.date_creation_sam))
Buffers: shared hit=8975 read=77580
-> HashAggregate (cost=47272.16..47651.22 rows=37906 width=26) (actual time=233.527..614.368 rows=38717 loops=1)
Group Key: c.reference_commande_ihm
Buffers: shared hit=4502 read=38774
-> Seq Scan on commande c (cost=0.00..47072.74 rows=39885 width=26) (actual time=0.032..162.362 rows=39120 loops=1)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
Rows Removed by Filter: 264617
Buffers: shared hit=4502 read=38774
-> Hash (cost=47072.74..47072.74 rows=39885 width=47) (actual time=224.005..224.005 rows=39120 loops=1)
Buckets: 65536 Batches: 1 Memory Usage: 3286kB
Buffers: shared hit=4470 read=38806
-> Seq Scan on commande (cost=0.00..47072.74 rows=39885 width=47) (actual time=0.040..204.466 rows=39120 loops=1)
Filter: ((reference_commande)::text ~~ 'BAC%'::text)
Rows Removed by Filter: 264617
Buffers: shared hit=4470 read=38806
-> Seq Scan on w_dm (cost=0.00..3449.69 rows=100 width=626) (actual time=0.004..27.584 rows=91540 loops=38717)
Filter: ((reference_commande IS NULL) OR ((reference_commande)::text = ''::text))
Rows Removed by Filter: 24408
Buffers: shared hit=128734025
Hors ligne
Le problème vient à priori de statistiques erronnées sur la table w_dm. Postgres pense trouver 100 lignes alors qu'il en récupère 91540, ce qui fait qu'il choisit une nested loop plutôt qu'un Hash join. Ajouter un "ANALYZE w_dm" dans votre traitement (voire même un ANALYZE global) avant cette requête devrait corriger le problème.
Julien.
https://rjuju.github.io/
Hors ligne
Bonjour, désolé pour le délai, mais vacances et disponibilité des équipes obligent ...
Le projet me dit que l'ajout d'un analyze en début de batch n'a pas eu l'effet escompté.
Partant de votre observation, j'ai testé l'exécution du job avec enable_nestloop à OFF. Le résultat est spectaculaire.
Test avec enable_nestloop = OFF
real 4m14.822s
user 0m24.033s
sys 0m3.180s
Test avec enable_nestloop = ON (mode par défaut)
real 52m44.130s
user 0m24.047s
sys 0m2.690s
La solution serait donc de positionner
set enable_nestloop to OFF;
Pour la session exécutant ce batch.
Par ailleurs, j'ai testé aussi enable_nestloop to OFF pour une autre requête qui mets 70mn, avec 4 milliards de ligne filtrées du fait de nesteed loop.
On passe à 2s.
Merci pour l'analyse que vous avez faite.
Henri
Hors ligne
Pages : 1
