Discussion :

[scheu]

Bonjour

Je deviens fou depuis ce matin sur un traitement PL/SQL qui ne se termine jamais. Ce traitement ouvre 33 curseurs, et pour chaque curseur fait un "FOR I IN CURSEUR ... UPDATE TABLE ..."
Sauf que sur un des curseurs, la requête SELECT qui initialise le curseur consomme 100% de CPU et ne se termine jamais, alors que les stats sont à jour, le plan d'exécution et bon (pour preuve je lance la même requête manuellement et le résultat est instantané, la requête ne renvoyant aucune ligne)
Le SELECT contient 2 bind variables mais le plan d'exécution est le même avec les bind variables qu'avec les valeurs réelles dans la requête


Les infos de la session en question, si ça peut aider :

buffer is pinned count 1882 2114788352 9223372036854775807
session logical reads 629 660527616 9223372036854775807
consistent gets from cache 629 660481536 9223372036854775807
consistent gets 628 660481536 9223372036854775807
no work - consistent read gets 628 660139456 9223372036854775807
table fetch by rowid 628 737942592 9223372036854775807
index scans kdiixs1 627 649409728 9223372036854775807
buffer is not pinned count 1 10908267 9223372036854775807
logons cumulative 0 1 0
logons current 0 1 0
opened cursors cumulative 0 178 0
opened cursors current 0 45 0
user commits 0 60 0
user calls 0 26 0
recursive calls 0 10411 0
recursive cpu usage 0 14683 0
CPU used when call started 0 14440 0
CPU used by this session 0 14691 0
DB time 0 19759 0
user I/O wait time 0 5369 0
session connect time 0 1213969280 0
process last non-idle time 0 1213969280 0
session uga memory 0 2614512 0
session uga memory max 0 4350768 0
messages sent 0 70 0
session pga memory 0 3086368 0
session pga memory max 0 5183520 0
enqueue requests 0 334 0
enqueue releases 0 333 0
physical read total IO requests 0 19407 0
physical read total multi block requests 0 652 0
physical read total bytes 0 489848832 0
db block gets 0 46094 0
db block gets from cache 0 46094 0
consistent gets - examination 0 340598 0
physical reads 0 27376 0
physical reads cache 0 27376 0
physical read IO requests 0 19407 0
physical read bytes 0 489848832 0
db block changes 0 53225 0
consistent changes 0 4302 0
change write time 0 19 0
redo synch writes 0 4 0
redo synch time 0 5 0
free buffer requested 0 28974 0
dirty buffers inspected 0 702 0
pinned buffers inspected 0 5 0
hot buffers moved to head of LRU 0 11576 0
free buffer inspected 0 29751 0
commit cleanout failures: block lost 0 130 0
commit cleanout failures: buffer being written 0 24 0
commit cleanout failures: callback failure 0 1 0
commit cleanouts 0 1934 0
commit cleanouts successfully completed 0 1779 0
CR blocks created 0 1 0
switch current to new buffer 0 646 0
write clones created in foreground 0 9 0
physical reads cache prefetch 0 7969 0
shared hash latch upgrades - no wait 0 67 0
calls to kcmgcs 0 615 0
calls to kcmgas 0 1101 0
calls to get snapshot scn: kcmgss 0 4651 0
redo entries 0 25485 0
redo size 0 7096468 0
redo ordering marks 0 361 0
redo subscn max counts 0 1062 0
undo change vector size 0 2918072 0
transaction tables consistent reads - undo records applied 0 185 0
transaction tables consistent read rollbacks 0 1 0
cleanouts only - consistent read gets 0 595 0
immediate (CURRENT) block cleanout applications 0 1653 0
immediate (CR) block cleanout applications 0 595 0
deferred (CURRENT) block cleanout applications 0 118 0
commit txn count during cleanout 0 597 0
active txn count during cleanout 0 116 0
cleanout - number of ktugct calls 0 712 0
IMU commits 0 42 0
IMU Flushes 0 18 0
IMU undo allocation size 0 526456 0
IMU Redo allocation size 0 444776 0
table scans (short tables) 0 93 0
table scans (long tables) 0 1 0
table scan rows gotten 0 6476732 0
table scan blocks gotten 0 82669 0
table fetch continued row 0 185269 0
cluster key scans 0 77 0
cluster key scan block gets 0 258 0
rows fetched via callback 0 209 0
index crx upgrade (positioned) 0 33 0
index fast full scans (full) 0 5 0
index fetch by key 0 442 0
heap block compress 0 223 0
sql area purged 0 5 0
session cursor cache hits 0 60 0
session cursor cache count 0 20 0
cursor authentications 0 25 0
workarea memory allocated 0 1300 0
workarea executions - optimal 0 102 0
parse time cpu 0 2 0
parse time elapsed 0 21 0
parse count (total) 0 162 0
parse count (hard) 0 10 0
execute count 0 8981 0
bytes sent via SQL*Net to client 0 6001 0
bytes received via SQL*Net from client 0 4047 0
SQL*Net roundtrips to/from client 0 15 0
sorts (memory) 0 41 0
sorts (rows) 0 35650 0

Statistiques d'exécution (sous la Grid Console) :
Total Par exécution Par ligne
Exécutions 9 1 0,00
Temps UC (s) 20 037,26 2 226,36 3,12
Lectures en mémoire tampon (Buffer Gets) 3 070 203 462 341 133 718,00 478 001,47
Lectures sur disque 21 895 2 432,78 3,41
Ecritures directes 0 0,00 0,00
Lignes 6 423 713,67 1
Extractions 72 8,00 0,01

Je suis en 10.2.0.4, auto SGA 4 Go, PGA 7 Go, aucune attente visible avec AWR dans la Grid Console, ce n'est que de la consommation CPU (que du vert niveau couleurs )
Comment puis-je investiguer sur cette requête qui m'a l'air figée et qui prend 100% de la CPU ?
Est-ce normal d'avoir "buffer is pinned count" à 2529004032 et "buffer is not pinned count" à 10935364

Merci de votre aide

[philcero]

T'as jeté un oeil dans V$SESSION_LONGOPS afin de voir ce qui se passe ?

[scheu]

Finalement c'était un PL/SQL développé comme un bourrin qui faisait des dizaines de select/update très courts mais construits dynamiquement (sans bind variables ni soft parsing) dans des boucles, ça avait tellement saturé ma CPU que l'AWR n'était apparemment pas capable de me dire quelle requête consommait ...

Merci quand-même