Problème performance oracle : Elapsed Time d'un Fetch énorme!

Bonjour,

Une application DELPHI /Oracle 9.2 tourne actuellement sur un poste classique de façon correcte. Tout est sur le même serveur (application delphi + serveur oracle). Le poste est sous Windows XP.

Cette même application a été placé sur un nouveau serveur plus performant (XEON 3ghz double coeur, disques durs SCSI en RAID 1, sous windows 2003...) et les performances lors de l'exécution d'un traitement ont été divisé par 3/4 ce qui n'est pas acceptable.

On m'a chargé de détecter les causes de cette mauvaise performance.
Pendant les tests, il a été détecté qu'un seul coeur du processeur sur les 2 est utilisé par l'application en delphi ainsi que le serveur oracle. Cependant, cela ne semble pas être ce qui bride les performances puisque le processeur est rarement à 50 % (50% représentant la totalité de l'un des deux coeurs)

Un bench des disques dur a montré que les performances sont acceptables.

Une analyse des traces oracle du traitement avec TKPROF (800mo de traces oracle) donne les résultats suivants (certaines requêtes ont été enlevées pour que ce soit moins long) qui sont très étonnants au niveau du elapsed time du FETCH du "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS", tout en bas

Le traitement dure de l'ordre de 24h au lieu de 5-6 heures sur l'ancien serveur.

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 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274

TKPROF: Release 9.2.0.6.0 - Production on Wed Dec 19 18:11:28 2007 Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved. Trace file: s2008_ora_4140.trc Sort options: prscpu execpu fchcpu ******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ******************************************************************************** select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.00 0.01 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 15 1158.25 1318.85 93922 1156005 0 1565 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 25 1158.25 1318.87 93922 1156005 0 1565 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 134 FILTER 16734 NESTED LOOPS 61193 HASH JOIN 949001 TABLE ACCESS BY INDEX ROWID REP_PR 980877 NESTED LOOPS 31875 TABLE ACCESS FULL REP_FICHE 949001 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032) 322033 TABLE ACCESS FULL DEM_PR 16734 TABLE ACCESS BY INDEX ROWID DEM_FICHE 61193 INDEX UNIQUE SCAN PK_DEM_FICHE (object id 6866) 15177 INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 7028) ******************************************************************************** update Dem_Fiche set Traite = :1 where No_Demande_Rff = :2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 35285 0.68 0.56 0 0 0 0 Execute 35285 64.84 65.57 110 105973 178489 35285 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 70570 65.53 66.14 110 105973 178489 35285 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 1 TABLE ACCESS BY INDEX ROWID DEM_FICHE 1 INDEX RANGE SCAN IX_DEM_FICHE_03 (object id 6869) ******************************************************************************** ANALYZE TABLE REP_PR COMPUTE STATISTICS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 62.51 90.82 31219 36093 30 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 62.51 90.82 31219 36093 30 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 ******************************************************************************** INSERT INTO Correspondance (Id, Id_Dossier, Id_Rep_Fiche,CAS) VALUES (Sq_Correspondance_01.NEXTVAL, :1, :2,:3) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 40544 0.57 0.64 0 0 0 0 Execute 40544 26.31 30.84 380 42258 550101 40544 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 81088 26.89 31.48 380 42258 550101 40544 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ******************************************************************************** update dem_fiche set traite=null call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 43 0 0 Execute 1 25.82 29.25 62 8336 166676 47470 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 25.82 29.25 62 8379 166676 47470 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 47470 TABLE ACCESS FULL DEM_FICHE ******************************************************************************** INSERT INTO Ecart (Id, Id_Fiche_Sncf, Rang, Id_Fiche_Rep, Id_Pr_Rep, Type_Ecart, Description) VALUES (Sq_Ecart_01.NEXTVAL, :1, :2, :3, :4, :5, :6) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 30988 0.40 0.42 0 5 0 0 Execute 30988 17.92 18.58 34 31408 348505 30988 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 61976 18.32 19.01 34 31413 348505 30988 Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ******************************************************************************** select Heure_Local_Arr, Heure_Local_Dep, Ci_Pr from Dem_Pr where Rang = :1 and Id_Fiche = :2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 177926 3.29 2.35 0 0 0 0 Execute 177926 5.85 5.38 0 0 0 0 Fetch 355852 6.98 23.29 4359 889629 0 177926 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 711704 16.14 31.03 4359 889629 0 177926 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID DEM_PR 1 INDEX RANGE SCAN IX_DEM_PR_01 (object id 6876) ******************************************************************************** ANALYZE TABLE DEM_PR COMPUTE STATISTICS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 11.42 12.67 1686 6175 8 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 11.42 12.67 1686 6175 8 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 ******************************************************************************** ******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 780651 13.09 11.46 3 138 0 0 Execute 780651 270.87 337.93 62476 661420 2080424 298576 Fetch 1000494 1191.574154500164.68 155322 3913556 15 686045 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2561796 1475.544154500514.08 217801 4575114 2080439 984621 Misses in library cache during parse: 61 Misses in library cache during execute: 3 OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 287495 5.12 4.79 6 278 0 0 Execute 590483 35.32 48.31 2437 327949 284873 161652 Fetch 435566 10.51 55.24 12000 1474151 2 435124 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 1313544 50.96 108.35 14443 1802378 284875 596776 Misses in library cache during parse: 134 Misses in library cache during execute: 2 994853 user SQL statements in session. 73295 internal SQL statements in session. 1068148 SQL statements in session. ******************************************************************************** Trace file: s2008_ora_4140.trc Trace file compatibility: 9.02.00 Sort options: prscpu execpu fchcpu 1 session in tracefile. 994853 user SQL statements in trace file. 73295 internal SQL statements in trace file. 1068148 SQL statements in trace file. 191 unique SQL statements in trace file. 14728913 lines in trace file.

---

Est-ce que vous avez une explication de ce fetch énorme ? (d'ailleurs les valeurs sont si grandes que cela ne peut pas être possible)

A quoi correspond exactement le "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" ?

Code:

---

1 2 3 4 5 6 7 8 9 10 11

******************************************************************************** OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 780651 13.09 11.46 3 138 0 0 Execute 780651 270.87 337.93 62476 661420 2080424 298576 Fetch 1000494 1191.574154500164.68 155322 3913556 15 686045 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2561796 1475.544154500514.08 217801 4575114 2080439 984621

---

je n'ai pas la main sur le serveur. Avant que je puisse faire de nouvelles demandes de test, je dois avoir une piste sérieuse...

Merci pour votre aide!

y'a un problème si un seul core est utilisé... faut quand même se pencher sur ce problème. Quand au elapsed très grand, c'est juste un bug, aucune requête n'a un tel elapsed. Faudrait une trace au moins de niveau 8 pour voir les événements d'attente. Utilises-tu le parallélisme ?

Est-ce qu'il y d'autres éléments qui ont changé en changeant de machine :

• la version d'Oracle côté serveur ou côté client
• la façon de calculer les statistiques (DBMS_STATS ou ANALYZE)
• des paramètres d'initialisation de l'instance
• le code applicatif côté client

Est-ce que vous pouvez comparer les résultats TKPROF avec les mêmes données et les mêmes requêtes sur les 2 environnements ?

Les chiffres "OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" correspondent à la somme des temps d'exécutions pour tout le SQL analysé par TKPROF (SQL non récursif = le SQL directement soumis par l'application).

La version oracle au niveau du serveur est la 9.2 sur les 2 environnements.
Je ne sais pas au niveau du client.

La façon de calculer les stats est la même sur les 2 environnements (le calcul des stats est fait régulièrement par l'appli en Delphi)

Qu'entends-tu exactement par paramètres d'initialisation de l'instance ?

Le code applicatif est exactement le même.

Une analyse TKPROF a été fait sur un poste de développement.
Lors des traitements, les traces sont trop grosses (on atteint rapidement plusieurs centaines de mo) pour être complètes. Les traces sont donc désactivées lorsque les fichiers de traces sont importants (800mo à 1go). On n'a donc pas à chaque fois des traces correspondant exactement au même nombre de requêtes.

Ci-dessous le fichier tkprof en environnement de développement. Il n'est pas possible de générer des traces oracle sur le poste qui fonctionne (il est utilisé en production)
Le fetch est plus normal ici.

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 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185 186 187 188 189 190 191 192 193 194 195 196 197 198 199 200 201 202 203 204 205 206 207 208 209 210 211 212 213 214 215 216 217 218 219 220 221 222 223 224 225 226 227 228 229 230 231 232 233 234 235 236 237 238 239 240 241 242 243 244 245 246 247 248 249 250 251 252 253 254 255 256 257 258 259 260 261 262 263 264 265 266 267 268 269 270 271 272 273 274 275 276 277 278 279 280 281 282 283 284 285 286 287 288 289 290 291 292 293 294 295 296 297 298 299 300 301 302 303 304 305 306 307 308 309 310 311 312 313 314 315

TKPROF: Release 9.2.0.6.0 - Production on Tue Dec 4 16:53:49 2007   Copyright (c) 1982, 2002, Oracle Corporation. All rights reserved.   Trace file: s2008_ora_724.trc Sort options: prscpu execpu fchcpu ******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ********************************************************************************   EXPLAIN PLAN option disabled. ********************************************************************************   INSERT INTO Ecart (Id, Id_Fiche_Sncf, Rang, Id_Fiche_Rep, Id_Pr_Rep, Type_Ecart, Description) VALUES (Sq_Ecart_01.NEXTVAL, :1, :2, :3, :4, :5, :6)   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 134977 4.51 4.00 0 0 0 0 Execute 134977 104.08 108.25 146 136589 1520897 134977 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 269954 108.60 112.26 146 136589 1520897 134977   Misses in library cache during parse: 1 Misses in library cache during execute: 5 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE   ********************************************************************************   update Dem_Fiche set Traite = :1 where No_Demande_Rff = :2     call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 35382 1.16 1.01 0 0 0 0 Execute 35382 73.26 75.94 22 106228 178642 35382 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 70764 74.42 76.95 22 106228 178642 35382   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 1 TABLE ACCESS BY INDEX ROWID DEM_FICHE 1 INDEX RANGE SCAN IX_DEM_FICHE_03 (object id 6123)   ********************************************************************************   select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3))   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.01 0.00 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 9 41.36 69.45 7342 137267 0 70 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 19 41.37 69.45 7342 137267 0 70   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 0 FILTER 522 NESTED LOOPS 2080 HASH JOIN 36006 TABLE ACCESS BY INDEX ROWID REP_PR 40946 NESTED LOOPS 4939 TABLE ACCESS FULL REP_FICHE 36006 INDEX RANGE SCAN IX_REP_PR_01 (object id 6271) 303507 TABLE ACCESS FULL DEM_PR 522 TABLE ACCESS BY INDEX ROWID DEM_FICHE 2080 INDEX UNIQUE SCAN PK_DEM_FICHE (object id 6120) 296 INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 6267)   ********************************************************************************   INSERT INTO Correspondance (Id, Id_Dossier, Id_Rep_Fiche,CAS) VALUES (Sq_Correspondance_01.NEXTVAL, :1, :2,:3)   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 39730 1.50 1.50 0 0 0 0 Execute 39730 33.38 36.98 157 41579 537307 39730 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 79460 34.89 38.49 157 41579 537307 39730   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE   ********************************************************************************   update dem_fiche set traite=null     call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 23 0 0 Execute 1 32.65 35.75 0 4742 88721 43393 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 32.65 35.75 0 4765 88721 43393   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 43393 TABLE ACCESS FULL DEM_FICHE   ********************************************************************************   UPDATE Dem_Fiche SET Etat_Fiche = :1, Date_Modif = :2 WHERE Id_Fiche_Sncf = :3   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 15248 0.37 0.43 0 0 0 0 Execute 15248 31.02 32.79 30 45830 46267 15248 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 30496 31.39 33.23 30 45830 46267 15248   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 1 TABLE ACCESS BY INDEX ROWID DEM_FICHE 1 INDEX RANGE SCAN IX_DEM_FICHE_01 (object id 6121)   ********************************************************************************   select Heure_Local_Arr, Heure_Local_Dep, Ci_Pr from Dem_Pr where Rang = :1 and Id_Fiche = :2   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 169888 5.32 4.99 0 0 0 0 Execute 169888 8.82 8.74 0 0 0 0 Fetch 339776 14.26 22.28 824 849440 0 169888 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 679552 28.41 36.02 824 849440 0 169888   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25   Rows Row Source Operation ------- --------------------------------------------------- 1 TABLE ACCESS BY INDEX ROWID DEM_PR 1 INDEX RANGE SCAN IX_DEM_PR_01 (object id 6130)   ********************************************************************************   COMMIT WORK     call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 150225 3.48 3.00 0 0 0 0 Execute 150225 22.44 21.53 0 0 150229 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 300450 25.92 24.54 0 0 150229 0   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 25 ********************************************************************************   UPDATE GRILLE SET NOM_DEMANDEUR = :B10 , NUM_SILLON_DOSSIER = :B16 , NO_DEMANDE_RFF = :B9 , NUM_SILLON_FICHE = :B8 , STATUT_FICHE = :B7 , ETAT_FICHE = :B6 , DATE_RECEPTION_SL = :B5 , DATE_ENVOI_RFF = :B4 , NB_FICHES_TRACES = :B15 , GARE_DEPART = :B3 , HEURE_DEPART = :B14 , GARE_ARRIVEE = :B2 , HEURE_ARRIVEE = :B13 , REGIME_TRADUIT = :B12 , LISTE_TCT = :B1 WHERE ID_FICHE_SNCF = :B11     call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 50631 0.84 0.75 0 0 0 0 Execute 94023 20.81 49.86 1987 189270 101957 94023 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 144654 21.66 50.61 1987 189270 101957 94023   Misses in library cache during parse: 1 Misses in library cache during execute: 1 Optimizer goal: CHOOSE Parsing user id: 25 (recursive depth: 1)   Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 43389 INDEX RANGE SCAN IX_GRILLE_02 (object id 6144)         ********************************************************************************   OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1049999 33.42 30.32 4 150 0 0 Execute 1049999 412.46 579.35 87408 1077735 3821527 576081 Fetch 979722 95.74 726.67 68304 2850371 13 677985 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 3079720 541.63 1336.34 155716 3928256 3821540 1254066   Misses in library cache during parse: 61 Misses in library cache during execute: 8     OVERALL TOTALS FOR ALL RECURSIVE STATEMENTS   call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 480345 13.65 12.66 3 46 0 0 Execute 761786 75.39 103.53 2049 368666 515872 276753 Fetch 492696 14.52 110.97 11023 1572630 0 492260 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 1734827 103.57 227.18 13075 1941342 515872 769013   Misses in library cache during parse: 128 Misses in library cache during execute: 2   1353817 user SQL statements in session. 176529 internal SQL statements in session. 1530346 SQL statements in session. 0 statements EXPLAINed in this session. ******************************************************************************** Trace file: s2008_ora_724.trc Trace file compatibility: 9.02.00 Sort options: prscpu execpu fchcpu 1 session in tracefile. 1353817 user SQL statements in trace file. 176529 internal SQL statements in trace file. 1530346 SQL statements in trace file. 185 unique SQL statements in trace file. 18777181 lines in trace file.

---

Un petit report de statspack serait utile.
Coté RAM, le nouveau serveur a t-il une quantité >= à l'ancien ?
Tout est fait sur le serveur ? Il n'y a pas une sonde ou un antivirus entre le poste client et le serveur qui ralentirait le traffic de data ?

Les paramètres d'initialisation = le contenu du fichier init.ora (pfile ou spfile).

On voit que votre environnement de développement n'a pas les mêmes données (il y a beaucoup moins de lignes dans les tables).

Il faudrait essayer de faire sauter la limitation sur le fichier trace sinon on ne peut pas même pas être sûr d'avoir les requêtes les plus lourdes. Et comme déjà demandé, il faudrait avoir les waits.

Concernant la ram, il y a sur les 2 serveurs 1GO.

(le passage à 2Go de ram ne serait pas superflu)

Cela me parait difficile de ne pas arrêter les traces oracle avant la fin, sinon cela prendra trop de place.

L'antivirus a été désactivé.
On m'a fourni plusieurs captures d'écran du gestionnaire des tâches pendant la durée des traitements, le processus oracle est celui qui utilise le plus le CPU. Ensuite l'application en delphi est la 2ème plus gourmande. Cependant, le CPU est en dessous de 50%.


Je vais essayer de récupérer le fichier init.ora demain...
Pour avoir les waits, quelle est la méthode la plus simple?

Merci

Ci-dessous une liste de paramètres oracle (identiques sur les 2 plateformes) Il y a aussi le GETHITRATIO du nouveau serveur (plus élevé que l'autre serveur en prod actuellement)

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 29 30 31 32 33 34 35 36 37 38

NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ sga_max_size big integer 328016000   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ shared_pool_size big integer 16777216   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ shared_pool_reserved_size big integer 838860   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ sort_area_size integer 65536   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_cache_size big integer 293601280   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ db_block_size integer 8192   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ optimizer_features_enable string 9.2.0   NAME TYPE VALUE ------------------------------------ ----------- ------------------------------ pga_aggregate_target big integer 83886080     SELECT gethitratio FROM v$librarycache WHERE namespace = 'SQL AREA'; GETHITRATIO ----------- ,898646035

---

et la volumétrie est la même ? T'es sûr que l'OS ne swappe pas ?

y'a un truc qui m'échappe : dans le tkprof, la somme n'a rien à voir avec le détail... 8O

Soit il manque des requêtes, soit le TKProf n'est pas de confiance....
Dans tous les cas, on n'a pas les billes....:oops:

j'avais enlevé certaines parties du premier résultat tkprof (nouveau serveur) , mais le 2ème est bien complet (serveur de développement).

Au niveau de la volumétrie des données en base, c'est sûr qu'elle n'est pas plus importante sur le nouveau serveur par rapport à l'ancien qui fonctionne correctement pour une configuration matérielle inférieure...

Concernant le swap de l'OS, je ne peux pas le dire de façon certaine. Je viens de lire cette page http://shsc.info/WindowsMemoryManagement qui m'a appris qu'il n'est pas facile de savoir s'il manque de la mémoire ou non.
J'ai les captures suivantes du task manager pendant le traitement (malheureusement je n'ai pas l'onglet performance, bien que je l'avais demandé à la personne qui a fait les captures...)
On voit en bas la quantité de mémoire utilisée 1833992K / 3094716K (le serveur a 1go de RAM)
Il y a pas mal de page faults, mais étant donné le grand nombre de lecture/écriture, je ne suis pas sûr que cela soit choquant.
http://img406.imageshack.us/img406/1141/66zw0.jpg
http://img88.imageshack.us/img88/237/72th1.jpg

Gestion_Sillons c'est l'application en Delphi qui entre autre exécute les requêtes.

Citation:

---

Envoyé par matd53

j'avais enlevé certaines parties du premier résultat tkprof (nouveau serveur) , mais le 2ème est bien complet (serveur de développement).

---

oui, mais s'il ne représente pas ce qui se passe là où il y a le problème...

je comprends que c'est pas jouable d'uploader 800 Mo mais va falloir trouver quelque chose pour qu'on ait les infos !!

par contre, les 140 000 fautes de pages sur le process Oracle, c'est pas top...
http://www.developpez.net/forums/sho...d.php?t=155205

==> Il swap...

1.8G de mémoire utilisée alors que tu as 1Go de RAM... on peut donc penser que ça swappe :?

Ensuite, faudrait trouver la requête qui prend le plus de temps et vérifier que le plan est le même sur les 2 instances.

le hit ratio est comment ?

si le hit ratio est bon, comme il swap, ça veut dire qu'Oracle croit avoir plus de mémoire qu'il n'en a réellement => baisser la SGA
si le hit ratio est mauvais, Oracle demande des lectures physiques et donc, on ne devrait pas avoit de fautes de pages.

Le Hit Ratio est de 0,898646035 sur le nouveau serveur qui a des pbs de performances.
Le SGA_max_size est de 328014848. Est-ce que cette valeur est trop importante?


Les temps d'exécution des requêtes ne sont pas importants par rapport à la durée totale du traitement. Je ne vois donc pas trop l'intérêt d'aller plus loin dans l'analyse de leurs plans d'exécution.

Seul le elapsed time des fetch pour l'"OVERALL TOTALS FOR ALL NON-RECURSIVE STATEMENTS" est vraiment étonnant...

Le résultat complet du rapport TKPROF des traces générées (800mo de traces analysées avec TKPROF qui ne représentent qu'une partie du traitement), est trop long pour l'afficher entièrement sur cette page...

Les logs applicatifs montrent que c'est tout le traitement qui est plus long que la normale et pas une partie en particulier.

Merci pour l'aide que vous m'avez déjà apporté!

un SGA_MAX_SIZE de 300Mo c'est pas délirant mais faut voir ce qui est sur le serveur parce que là visiblement ça swape... et si tu avais bien voulu faire une trace de level 8 tu pourrais probablement voir des waits sur les I/O :roll:

Je viens de voir dans le fichier tkprof des traces du nouveau serveur la requête suivante que j'avais enlevé dans la partie affichée sur le forum :oops: et qui a un fetch énorme (mais un temps CPU très faible):

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

select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is null and r.heure_local_dep is not null     call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 41472 0.84 0.61 0 0 0 0 Execute 41472 1.25 1.33 0 0 0 0 Fetch 41472 3.064154498643.93 18673 291584 0 39832 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 124416 5.154154498645.89 18673 291584 0 39832   Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23   Rows Row Source Operation ------- --------------------------------------------------- 1 NESTED LOOPS 1 TABLE ACCESS BY INDEX ROWID REP_FICHE 1 INDEX UNIQUE SCAN PK_REP_FICHE (object id 7020) 1 TABLE ACCESS BY INDEX ROWID REP_PR 1 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032)

---

Votre analyse la dessus? Un bug de tkprof?

pouvez-vous uploader le zip de la trace avant tkprof concernant simplement cette requête ?

Pour l'analyse level 8, je vais essayer d'en obtenir une. Cependant ça ne va pas être possible rapidement... (vacances oblige...)

Citation:

---

Envoyé par LeoAnderson

pouvez-vous uploader le zip de la trace avant tkprof concernant simplement cette requête ?

---

Je ne comprends pas comment faire cela?
Comment isoler cette requête appelée de nombreuses fois du fichier de traces?

la requête est dans combien de fichiers ?

J'ai un fichier de traces de 800mo dans lequel la requête est appelée de nombreuses fois.


Le fichier init.ora :

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 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116

# ========== # Noms Base de donnees, Instance, Service # ========== db_name = S2008 instance_name = S2008 service_names = S2008   # ========== # Fichiers de controle # ========== control_files = ("C:\oradata\S2008\S2008_control01.ctl", "D:\oradata\S2008\S2008_control02.ctl")   # ========== # Taille du bloc Oracle # ========== db_block_size = 8192   # ========== # Buffers # ========== # db_block_buffers = 8192 # 64 Mo # shared_pool_size = 6291456 # 6 Mo # shared_pool_reserved_size = 1048576 # 1 Mo db_cache_size = 274M shared_pool_size = 16M pga_aggregate_target = 80M large_pool_size = 0 # 0 Mo java_pool_size = 0 # 0 Mo Pas de Java   log_buffer = 262144 sort_area_size = 65536 sort_area_retained_size = 65536   # ========== # Divers # ========== log_checkpoint_interval = 10000 log_checkpoint_timeout = 1800 processes = 100 open_cursors = 100 session_cached_cursors = 100 max_enabled_roles = 30   # audit_trail = false # if you want auditing # timed_statistics = true # if you want timed statistics max_dump_file_size = 10000 # limit trace file size to 5M each   # ========== # Archivage des Redo Logs # ========== # log_archive_start = true # log_archive_dest = "$ORACLE_DPG_BASE/archive" # log_archive_format = arc%t_%s.dbf   # ========== # Rollback Segments # ========== # rollback_segments = (RBS1, RBS2, RBS3, RBS4)   # ========== # Undo TableSpace # ========== undo_management = auto undo_tablespace = S2008_undo01   # Global Naming -- enforce that a dblink has same name as the db it connects to # global_names = false   # Uncomment the following line if you wish to enable the Oracle Trace product # to trace server activity. This enables scheduling of server collections # from the Oracle Enterprise Manager Console. # Also, if the oracle_trace_collection_name parameter is non-null, # every session will write to the named collection, as well as enabling you # to schedule future collections from the console. # oracle_trace_enable = true   # ========== # Repertoire trace # ========== background_dump_dest = "D:\oracle\ora92\database\S2008\bdump" core_dump_dest = "D:\oracle\ora92\database\S2008\cdump" user_dump_dest = "D:\oracle\ora92\database\S2008\udump"   #utl_file_dir = /oracle/admin/dpg/udump   #Uncomment this parameter to enable resource management for your database. #The SYSTEM_PLAN is provided by default with the database. #Change the plan name if you have created your own resource plan. # resource_manager_plan = system_plan   #remote_login_passwordfile = none   os_authent_prefix = ""   #mts_dispatchers = "(protocol=TCP)(DISP=1)(mul=OFF)(pool=OFF)" #mts_max_dispatchers = 5 #mts_servers = 1 #mts_max_servers = 20   compatible = "9.2.0"   # ========== # Parametres pour l'utilisation de DBMS_JOB # ========== # JOB_QUEUE_PROCESSES = 1 # JOB_QUEUE_INTERVAL = 60   # ========== # Parametre pour permettre l'enregistrement des stats # ========== # utl_file_dir = *   # ========== # Parametres pour l'utilisation de UTL_FILE # ========== UTL_FILE_DIR = 'c:\Saisie des sillons\Requete'

---

il me semble me rappeller qu'il y a un but sur le elapsed...

j'ai de scripts magique à vous proposer, mais il faut réussier à sortir cette requête de la trace, sans tout synthétiser.. :oops:

Compressé, le fichier de traces ne fait plus que 36mo au lieu de 800, mais je ne peux pas l'envoyer par le système d'upload de free par exemple car c'est bloqué par le proxy... et il y a tellement de requêtes éparpillées dans le fichier que cela me semble difficile de faire le tri...

Je peux toutefois en afficher deux exemples qui sont intéressants, on voit bien un elapsed time énorme!!!
Dans les traces, a chaque fois , il y a 2 requêtes à la suite qui sont proches (not null pas au même endroit), une qui se passe bien, et l'autre non.

1er exemple des 2 requêtes dans les traces:

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 29

===================== PARSING IN CURSOR #4 len=168 dep=0 uid=23 oct=3 lid=23 tim=1470997201 hv=289369495 ad='111f5ed4' select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is null and r.he ure_local_dep is not null END OF STMT PARSE #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1470997197 EXEC #4:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1470997335 FETCH #4:c=0,e=4023,p=1,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=1471001394 XCTEND rlbk=0, rd_only=1 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=7017 op='TABLE ACCESS BY INDEX ROWID REP_FICHE ' STAT #4 id=3 cnt=1 pid=2 pos=1 obj=7020 op='INDEX UNIQUE SCAN PK_REP_FICHE ' STAT #4 id=4 cnt=1 pid=1 pos=2 obj=7021 op='TABLE ACCESS BY INDEX ROWID REP_PR ' STAT #4 id=5 cnt=1 pid=4 pos=1 obj=7032 op='INDEX RANGE SCAN IX_REP_PR_01 ' ===================== PARSING IN CURSOR #4 len=168 dep=0 uid=23 oct=3 lid=23 tim=1471003646 hv=1978721461 ad='111ec248' select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and r.heure_local_dep is null END OF STMT PARSE #4:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471003641 EXEC #4:c=0,e=34,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471003784 FETCH #4:c=0,e=54,p=0,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=1471003875 XCTEND rlbk=0, rd_only=1 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=7017 op='TABLE ACCESS BY INDEX ROWID REP_FICHE ' STAT #4 id=3 cnt=1 pid=2 pos=1 obj=7020 op='INDEX UNIQUE SCAN PK_REP_FICHE ' STAT #4 id=4 cnt=1 pid=1 pos=2 obj=7021 op='TABLE ACCESS BY INDEX ROWID REP_PR ' STAT #4 id=5 cnt=6 pid=4 pos=1 obj=7032 op='INDEX RANGE SCAN IX_REP_PR_01 ' =====================

---

2eme exemple des 2 requêtes dans les traces:

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

===================== PARSING IN CURSOR #4 len=168 dep=0 uid=23 oct=3 lid=23 tim=1471141347 hv=289369495 ad='111f5ed4' select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is null and r.h ure_local_dep is not null END OF STMT PARSE #4:c=0,e=15,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471141342 EXEC #4:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471141484 FETCH #4:c=0,e=10180,p=2,cr=7,cu=0,mis=0,r=1,dep=0,og=4,tim=1471151701 XCTEND rlbk=0, rd_only=1 STAT #4 id=1 cnt=1 pid=0 pos=1 obj=0 op='NESTED LOOPS ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=7017 op='TABLE ACCESS BY INDEX ROWID REP_FICHE ' STAT #4 id=3 cnt=1 pid=2 pos=1 obj=7020 op='INDEX UNIQUE SCAN PK_REP_FICHE ' STAT #4 id=4 cnt=1 pid=1 pos=2 obj=7021 op='TABLE ACCESS BY INDEX ROWID REP_PR ' STAT #4 id=5 cnt=1 pid=4 pos=1 obj=7032 op='INDEX RANGE SCAN IX_REP_PR_01 ' ===================== PARSING IN CURSOR #4 len=168 dep=0 uid=23 oct=3 lid=23 tim=1471153960 hv=1978721461 ad='111ec248' select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and r.heure_local_dep is null END OF STMT PARSE #4:c=0,e=14,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471153955 EXEC #4:c=0,e=35,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=1471154099 FETCH #4:c=0,e=5129,p=1,cr=8,cu=0,mis=0,r=0,dep=0,og=4,tim=1471159265 XCTEND rlbk=0, rd_only=1 STAT #4 id=1 cnt=0 pid=0 pos=1 obj=0 op='NESTED LOOPS ' STAT #4 id=2 cnt=1 pid=1 pos=1 obj=7017 op='TABLE ACCESS BY INDEX ROWID REP_FICHE ' STAT #4 id=3 cnt=1 pid=2 pos=1 obj=7020 op='INDEX UNIQUE SCAN PK_REP_FICHE ' STAT #4 id=4 cnt=0 pid=1 pos=2 obj=7021 op='TABLE ACCESS BY INDEX ROWID REP_PR ' STAT #4 id=5 cnt=11 pid=4 pos=1 obj=7032 op='INDEX RANGE SCAN IX_REP_PR_01 '

---

On retrouve bien ces résultats dans l'analyse de tkprof ci -dessous.
Requête tkpof qui se passe bien :

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

select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and r.heure_local_dep is null call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 39832 0.59 0.59 0 0 0 0 Execute 39832 1.51 1.24 0 0 0 0 Fetch 39832 4.14 57.04 13307 303305 0 38027 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 119496 6.25 58.89 13307 303305 0 38027 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 NESTED LOOPS 1 TABLE ACCESS BY INDEX ROWID REP_FICHE 1 INDEX UNIQUE SCAN PK_REP_FICHE (object id 7020) 1 TABLE ACCESS BY INDEX ROWID REP_PR 16 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032) ********************************************************************************

---

Requête tkprof qui se passe mal :

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

******************************************************************************** select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is null and r.heure_local_dep is not null call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 41472 0.84 0.61 0 0 0 0 Execute 41472 1.25 1.33 0 0 0 0 Fetch 41472 3.064154498643.93 18673 291584 0 39832 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 124416 5.154154498645.89 18673 291584 0 39832 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 NESTED LOOPS 1 TABLE ACCESS BY INDEX ROWID REP_FICHE 1 INDEX UNIQUE SCAN PK_REP_FICHE (object id 7020) 1 TABLE ACCESS BY INDEX ROWID REP_PR 1 INDEX RANGE SCAN IX_REP_PR_01 (object id 7032)

---

Orafrance, je ne comprends pas ce que tu veux dire par là ? but ?

Citation:

---

il me semble me rappeller qu'il y a un but sur le elapsed...

---

Conclusion : tkprof ne bug pas.
donc l'elapsed est réellement important

donc là, faut avoir les wait. il n'y a plus le choix !
Il suffit de lancer 1 requête en trace level 8 et d'uploader la trace

y'a peut-être pas de bug mais passé d'un e=10180 à elapsed 4154498643.93 ça me parait pas très catholique :koi:

M'enfin, n'en reste pas moins qu'on a toujours pas le wait :mrgreen:

En effet, il y a bien quelque chose qui cloche dans mon analyse. Surtout que je n'avais pas bien vu que même pour la requête suivante il y a parfois des temps de fetch importants.

select f.regime_circ from rep_pr r,rep_fiche f where r.ci_pr= :1 and r.id_fiche=:2 and r.id_fiche=f.id and r.heure_local_arr is not null and
r.heure_local_dep is null


Dans les traces oracles brutes, d'après ce que j'ai lu, c'est en centièmes de secondes. Donc quand il y a 10180 cela fait tout de même 101 secondes! Et cette requête est appelée 41472 fois dans les traces qui ne représentent qu'une partie du traitement! Il semble donc bien qu'il y ait un pb ici. (100 seconde par requête * 40000 requêtes = 4 million de secondes tout de même) On n'atteint cependant pas les 4154498645 indiqué par TKPROF.

Citation:

---

M'enfin, n'en reste pas moins qu'on a toujours pas le wait :mrgreen:

---

Je suis désolé :aie: J'aimerais aussi pouvoir les avoir mais je n'ai pas la main sur le serveur... ça va malheureusement devoir attendre 2 semaines ...

tu peux pas lancer la requête et regarder v$session_wait ? Statspack ne serait pas installé par hasard ? :ange:

Durant les 24h de traitements, n'y a t-il pas d'autres traitements en cours (calculs d'agrégats, bilan comptable, sauvegarde, refresh de statistiques...) ?
Le serveur est-il bien dédié à la base Oracle ?
Comment a été copiée la BD sur ce nouveau serveur (exp/imp, copie datafiles, duplicate rman...) ?
Même niveau de patch sur les 2 serveurs ?
Je ne connais pas windows mais sur unix, les file system avec cache sont parfois pénalisant coté perf. Oracle préfère accéder directement au disque. Si c'est idem sur windows, il y a peut être un problème coté cache disque.

4 millions de secondes = 1111 heures = 46 jours....

les chiffres ne sont pas aussi élevés que ça... il y a donc bien un bug quelque part... en plus de la lenteur !

comment avez-vous activé la trace ?
quelle est la version exacte ? (OS, level, ...)

Citation:

---

Durant les 24h de traitements, n'y a t-il pas d'autres traitements en cours (calculs d'agrégats, bilan comptable, sauvegarde, refresh de statistiques...) ?
Le serveur est-il bien dédié à la base Oracle ?
Comment a été copiée la BD sur ce nouveau serveur (exp/imp, copie datafiles, duplicate rman...) ?
Même niveau de patch sur les 2 serveurs ?
Je ne connais pas windows mais sur unix, les file system avec cache sont parfois pénalisant coté perf. Oracle préfère accéder directement au disque. Si c'est idem sur windows, il y a peut être un problème coté cache disque.

---

Non, il n'y a pas d'autres traitements.
Pour la copie de la base sur le serveur, j'avoue que je ne connais pas la façon dont cela a été fait.
Tout est sur le même serveur : Application en Delphi et serveur oracle.
Oracle 9.2.0 est installé sur les 2 serveurs.
Pour le cache disque, je ne vois pas trop comment regarder cela. Les disques sont des SCSI en raid 1. (1 paire de disques 146 go SCSI 10000 tours/min et une paire de disques 36go 15000 tours / min)

Citation:

---

4 millions de secondes = 1111 heures = 46 jours....

les chiffres ne sont pas aussi élevés que ça... il y a donc bien un bug quelque part... en plus de la lenteur !

comment avez-vous activé la trace ?
quelle est la version exacte ? (OS, level, ...)

---

L'activation des traces a été faite au niveau par défaut, avec les commandes suivantes :

Code:

---

1 2 3 4 5 6 7 8 9

Détection de la session oracle correspondant à l'appli: select sid,serial#,username,program from v$session;   Démarrage des traces : exec dbms_system.set_sql_trace_in_session(<SID>, <SERIAL#>,true) ; Traitement Arret des traces : exec dbms_system.set_sql_trace_in_session(<SID>, <SERIAL#>,false) ;

---

Je fais une petite pause sur ce pb... mais je vais m'y remettre dans 2 semaines ;)
Merci pour l'aide que vous m'avez apporté!

Je suis de retour sur ce pb.
Un test avec 2Go de Ram au lieu de 1Go a été fait. Les performances ne sont pas améliorées.

J'ai demandé à ce qu'un test avec les traces oracle de niveau 8 soit effectué après que des traces classiques aient été faites (pour avoir plus d'infos sur les waits).
Cependant, cela n'a pas pu être faite car le processus de l'application n'est pas actif d'après oracle 8O. La connexion à sqlplus était bien faite en tant que sysdba. Je ne comprends pas pourquoi l'activation n'a pas fonctionné.

En particulier la ligne suivante qui aurait dû fonctionner :

Code:

---

oradebug setospid 832

---

http://www.developpez.net/forums/att...1&d=1201099226



Pendant le traitement, le processeur n'est pas surchargé :
http://www.developpez.net/forums/att...1&d=1201099467


C'est vraiment frustrant ce problème de perf :)

Peut-on savoir quelle est la version précise de windows ? Est-on en 32 bits ou en 64 bits ? Sur les deux serveurs ?

ora-72 : pas le bon spid/pid

ora-73 : commande pas terminée correctement

insistez auprès du support oracle pour qu'il vous aide jusqu'au bout !!!

Concernant la version de windows, dans un premier temps, des tests avaient été fait sous windows 2003 server.

Etant donné que les perfs n'étaient pas bonnes, Windows 2000 Sp4 (32bits) a été installé à la place .
Le processeur est un Xeon 3ghz bi-coeur 32 bits.

A priori, un nouveau test devrait être fait lundi ou mardi, on va réessayer d'activer les traces de niveau 8.

Ok, je voulais être sûr :)

Extrait de la note Metalink 161546.1 :

"...
Microsoft has certified the Windows 2000, Windows XP 32-Bit and Windows 2003
32-Bit operating systems to run on the AMD 64-Bit Opteron processor and the
Intel 64-Bit Xeon processor (Xeon processors with Intel EM64T support). From
version 9.2.x Oracle has certified its 32-Bit database and client software to
run on these 32-Bit operating systems running on these 64-Bit processors.
..."

Reste maintenant à savoir si la version d'Oracle installée est une version 32-bits ou 64-bits ?

4 milliards, c'est la limite haute d'un entier non signé sur 32-bits (pour être plus précis : 4294967296 - 1).

Ah et peut-être qu'en fouillant cela
tu trouveras des infos.

Good luck!

Merci pour ces infos.

Après un nouveau test, ce fetch énorme n'est pas réapparu sur la même requête , mais sur une autre requête !
En fait maintenant je suis à peu près sur que c'est un bug de la génération des traces oracle puisque la nouvelle requête sur laquelle le pb est apparu s'est effectuée correctement dans un temps normal. En plus, j'ai pu retrouver dans les traces oracle brutes les 5 exécutions de la requête avec des valeurs qui sont parfois énormes:

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 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185

===================== PARSING IN CURSOR #1 len=896 dep=0 uid=23 oct=3 lid=23 tim=2791630472 hv=276931049 ad='111b3968' select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) END OF STMT PARSE #1:c=0,e=23280,p=6,cr=6,cu=0,mis=1,r=0,dep=0,og=0,tim=2791630466 ===================== ... ===================== PARSING IN CURSOR #1 len=896 dep=0 uid=23 oct=3 lid=23 tim=3039375808 hv=276931049 ad='111b3968' select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) END OF STMT PARSE #1:c=0,e=98,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3039375802 EXEC #1:c=0,e=54,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=3039376139 *** 2008-01-31 14:28:47.000 FETCH #1:c=4578125,e=18446744067633889042,p=24209,cr=89913,cu=0,mis=0,r=1,dep=0,og=4,tim=18446744070673265216 XCTEND rlbk=0, rd_only=1 *** 2008-01-31 14:29:15.000 FETCH #1:c=26765625,e=27835654,p=1797,cr=16043,cu=0,mis=0,r=200,dep=0,og=4,tim=18446744070701101546 *** 2008-01-31 14:29:40.000 FETCH #1:c=24593750,e=25302878,p=1541,cr=11759,cu=0,mis=0,r=200,dep=0,og=4,tim=18446744070726405350 *** 2008-01-31 14:30:26.000 FETCH #1:c=44359375,e=45590131,p=2280,cr=21264,cu=0,mis=0,r=200,dep=0,og=4,tim=18446744070771996158 *** 2008-01-31 14:31:11.000 FETCH #1:c=43562500,e=45087384,p=2171,cr=28645,cu=0,mis=0,r=200,dep=0,og=4,tim=18446744070817084229 *** 2008-01-31 14:31:33.000 FETCH #1:c=21078125,e=21799783,p=1549,cr=14161,cu=0,mis=0,r=147,dep=0,og=4,tim=18446744070838884785 ===================== ... ===================== PARSING IN CURSOR #1 len=896 dep=0 uid=23 oct=3 lid=23 tim=18446744070850669503 hv=276931049 ad='111b3968' select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) END OF STMT PARSE #1:c=0,e=42,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744070850669497 EXEC #1:c=0,e=53,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744070850669817 *** 2008-01-31 14:33:00.000 FETCH #1:c=7343750,e=75612202,p=25219,cr=91451,cu=0,mis=0,r=1,dep=0,og=4,tim=18446744070926282054 XCTEND rlbk=0, rd_only=1 *** 2008-01-31 14:35:43.000 FETCH #1:c=157593750,e=162223085,p=9043,cr=73178,cu=0,mis=0,r=54,dep=0,og=4,tim=18446744071088505831 ===================== ... ===================== PARSING IN CURSOR #1 len=896 dep=0 uid=23 oct=3 lid=23 tim=18446744071089301748 hv=276931049 ad='111b3968' select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) END OF STMT PARSE #1:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744071089301742 EXEC #1:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744071089302062 *** 2008-01-31 14:36:58.000 FETCH #1:c=7437500,e=74924791,p=25788,cr=91495,cu=0,mis=0,r=1,dep=0,og=4,tim=18446744071164226888 XCTEND rlbk=0, rd_only=1 *** 2008-01-31 14:39:40.000 FETCH #1:c=157484375,e=162109754,p=9037,cr=73315,cu=0,mis=0,r=119,dep=0,og=4,tim=18446744071326337316 ===================== ... ===================== PARSING IN CURSOR #1 len=896 dep=0 uid=23 oct=3 lid=23 tim=18446744071328324885 hv=276931049 ad='111b3968' select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) END OF STMT PARSE #1:c=0,e=17,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744071328324879 EXEC #1:c=0,e=52,p=0,cr=0,cu=0,mis=0,r=0,dep=0,og=4,tim=18446744071328325199 *** 2008-01-31 14:43:15.000 FETCH #1:c=140921875,e=212773704,p=33160,cr=150129,cu=0,mis=0,r=1,dep=0,og=4,tim=18446744071541098938 XCTEND rlbk=0, rd_only=1 *** 2008-01-31 14:43:40.000 FETCH #1:c=23921875,e=24742240,p=1842,cr=12751,cu=0,mis=0,r=1,dep=0,og=4,tim=18446744071565841861 =====================

---

Requêtes qui prennent le plus de temps (avec le bug présent sur la première requête):

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 29 30 31 32 33 34 35 36 37 38 39 40 41 42 43 44 45 46 47 48 49 50 51 52 53 54 55 56 57 58 59 60 61 62 63 64 65 66 67 68 69 70 71 72 73 74 75 76 77 78 79 80 81 82 83 84 85 86 87 88 89 90 91 92 93 94 95 96 97 98 99 100 101 102 103 104 105 106 107 108 109 110 111 112 113 114 115 116 117 118 119 120 121 122 123 124 125 126 127 128 129 130 131 132 133 134 135 136 137 138 139 140 141 142 143 144 145 146 147 148 149 150 151 152 153 154 155 156 157 158 159 160 161 162 163 164 165 166 167 168 169 170 171 172 173 174 175 176 177 178 179 180 181 182 183 184 185

******************************************************************************** count = number of times OCI procedure was executed cpu = cpu time in seconds executing elapsed = elapsed time in seconds executing disk = number of physical reads of buffers from disk query = number of buffers gotten for consistent read current = number of buffers gotten in current mode (usually for update) rows = number of rows processed by the fetch or execute call ******************************************************************************** select d.id_fiche_sncf,r.id as idRep from dem_fiche d, dem_pr dr, rep_fiche r, rep_pr pr where r.Liste_id_fiche_sncf is null and r.parite is null and d.id = dr.id_fiche and r.id = pr.id_fiche and pr.ci_pr=dr.ci_pr and pr.ch_pr=dr.ch_pr and (( r.num_sillon_reponse = d.num_sillon1 ) or ( r.num_sillon_reponse = d.num_sillon2 )) and d.id_fiche_sncf like :1 and not exists (select id_rep_fiche from correspondance where id_rep_fiche = r.id) and ((dr.heure_local_dep is null and pr.heure_local_dep is null and dr.heure_local_arr is not null and pr.heure_local_arr is not null) or (dr.heure_local_arr is null and pr.heure_local_arr is null and dr.heure_local_dep is not null and pr.heure_local_dep is not null)) and ((abs(to_number(dr.heure_local_arr) - to_number(pr.heure_local_arr)) <= :2) or (abs(to_number(dr.heure_local_dep) - to_number(pr.heure_local_dep)) <= :3)) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 5 0.00 0.00 0 0 0 0 Execute 5 0.00 0.00 0 0 0 0 Fetch 14 825.934154499735.23 173793 849453 0 1139 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 24 825.934154499735.24 173793 849453 0 1139 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 14 FILTER 6852 NESTED LOOPS 36508 HASH JOIN 956626 TABLE ACCESS BY INDEX ROWID REP_PR 983686 NESTED LOOPS 27059 TABLE ACCESS FULL REP_FICHE 956626 INDEX RANGE SCAN IX_REP_PR_01 (object id 7635) 379408 TABLE ACCESS FULL DEM_PR 6852 TABLE ACCESS BY INDEX ROWID DEM_FICHE 36508 INDEX UNIQUE SCAN PK_DEM_FICHE (object id 7516) 6312 INDEX RANGE SCAN IX_CORRESPONDANCE_02 (object id 7631) ******************************************************************************** INSERT INTO Ecart (Id, Id_Fiche_Sncf, Rang, Id_Fiche_Rep, Id_Pr_Rep, Type_Ecart, Description) VALUES (Sq_Ecart_01.NEXTVAL, :1, :2, :3, :4, :5, :6) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 412128 6.60 5.27 0 5 0 0 Execute 412128 232.15 592.11 109 495156 4997668 400141 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 824256 238.76 597.39 109 495161 4997668 400141 Misses in library cache during parse: 1 Misses in library cache during execute: 2 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ******************************************************************************** ANALYZE TABLE REP_PR COMPUTE STATISTICS call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 1 0.00 0.00 0 0 0 0 Execute 1 123.75 181.05 70675 71570 50 0 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 2 123.75 181.06 70675 71570 50 0 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 ******************************************************************************** update seq$ set increment$=:2,minvalue=:3,maxvalue=:4,cycle#=:5,order$=:6, cache=:7,highwater=:8,audit$=:9,flags=:10 where obj#=:1 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 476558 16.78 15.37 0 0 0 0 Execute 476558 62.89 64.13 15 476595 973509 476558 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 953116 79.67 79.51 15 476595 973509 476558 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: SYS (recursive depth: 1) Rows Row Source Operation ------- --------------------------------------------------- 1 UPDATE 1 INDEX UNIQUE SCAN I_SEQ1 (object id 107) ******************************************************************************** update Dem_Fiche set Traite = :1 where No_Demande_Rff = :2 call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 43976 0.78 0.68 0 0 0 0 Execute 43976 68.25 69.74 88 132108 222611 43976 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 87952 69.03 70.42 88 132108 222611 43976 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 0 UPDATE 1 TABLE ACCESS BY INDEX ROWID DEM_FICHE 1 INDEX RANGE SCAN IX_DEM_FICHE_03 (object id 7519) ******************************************************************************** INSERT INTO Correspondance (Id, Id_Dossier, Id_Rep_Fiche,CAS) VALUES (Sq_Correspondance_01.NEXTVAL, :1, :2,:3) call count cpu elapsed disk query current rows ------- ------ -------- ---------- ---------- ---------- ---------- ---------- Parse 64420 1.00 0.88 0 0 0 0 Execute 64420 35.98 49.64 807 67061 891846 64420 Fetch 0 0.00 0.00 0 0 0 0 ------- ------ -------- ---------- ---------- ---------- ---------- ---------- total 128840 36.98 50.53 807 67061 891846 64420 Misses in library cache during parse: 1 Optimizer goal: CHOOSE Parsing user id: 23 Rows Row Source Operation ------- --------------------------------------------------- 1 SEQUENCE ********************************************************************************

---

Bref, maintenant je commence à écarter la piste de problème oracle qui expliquerait les mauvaises perf de l'application.

tout ça pour en arriver au résultat du 2° post de cette discussion... Oracle nous réserve parfois de sales coups :mouarf: