Forums PostgreSQL.fr

Henri Couroussé

Membre

Requête de SELECT très longue

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)

rjuju

Administrateur

Re : Requête de SELECT très longue

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/

Henri Couroussé

Membre

Re : Requête de SELECT très longue

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

Henri Couroussé

Membre

Re : Requête de SELECT très longue

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))

Henri Couroussé

Membre

Re : Requête de SELECT très longue

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 |

Henri Couroussé

Membre

Re : Requête de SELECT très longue

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

rjuju

Administrateur

Re : Requête de SELECT très longue

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/

Henri Couroussé

Membre

Re : Requête de SELECT très longue

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