[10g] Lenteur et erreur GES: Potential blocker [Résolu]

[korian]

Bonjour,

Configuration : 10gR2 en RAC et ASM sur des serveurs SUN.

Depuis quelques jours, notre plateforme connait des ralentissements et des dysfonctionnements que je n'arrive pas à expliquer.

Pour information : Suite à un incendie dans notre bâtiment, la base a été violemment coupée électriquement malgré nos onduleurs. Après vérification, la base ne semblait pas corrompue et a été remise en production il y a 2 semaines. Elle est arrêtée et redémarrée chaque soir.

Cette coupure a été accusée de tous les maux mais j'ai pu montrer que les problèmes ne venaient pas de la base mais de traitements applicatifs.

Seulement depuis, il existe toujours des "ralentissements" voire des pertes de connexions "étonnantes".

Dans l'alert_log, les seules traces inquiétantes sont des lignes du type :

Code :

1
2
GES: Potential blocker (pid=17381) ON resource TX-000A0019-0002B660;
 enqueue info IN file /BASE/bdump/bdd_lmd0_13830.trc AND DIAG trace file

Extrait du fichier bdd_lmd0_13830.trc

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
*** 2011-07-26 09:36:44.564
ENQUEUE DUMP REQUEST: FROM 1.11489 ON [0xc002e][0x1c277],[TX] FOR reason 2 mtype 0
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0xc002e][0x1c277],[TX]
----------resource 0x3f5ab7600----------------------
resname       : [0xc002e][0x1c277],[TX]
LOCAL node    : 0
dir_node      : 0
master_node   : 0
hv idx        : 4
hv last r.inc : 4
current inc   : 4
hv STATUS     : 0
hv master     : 1
open options  : dd
grant_bits    : KJUSERNL KJUSEREX
GRANT mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
count         : 1         0         0         0         0         1
val_state     : KJUSERVS_NOVALUE
valblk        : 0x00000000000000000000000000000000 .
access_node   : 0
vbreq_state   : 0
state         : x0
resp          : 3f5ab7600
ON Scan_q?    : N
Total accesses: 443
Imm.  accesses: 396
Granted_locks : 1
Cvting_locks  : 1
value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 3fcc2ad28 gl KJUSEREX rp 3f5ab7600 [0xc002e][0x1c277],[TX]
  master 0 gl owner 3fc4c3798 possible pid 17344 xid 1002-002C-00000002 bast 0 rseq 21 mseq 0 history 0x4977d495
  open opt KJUSERDEADLOCK
CONVERT_Q:
lp 3fcc2afc8 gl KJUSERNL rl KJUSEREX rp 3f5ab7600 [0xc002e][0x1c277],[TX]
  master 0 owner 1  bast 1 rseq 16 mseq 0x1 history 0x77d497ad
  convert opt KJUSERGETVALUE
----------enqueue 0x3fcc2ad28------------------------
LOCK version     : 5
Owner node       : 0
grant_level      : KJUSEREX
req_level        : KJUSEREX
bast_level       : KJUSERNL
notify_func      : 0
resp             : 3f5ab7600
procp            : 3fcaa7320
pid              : 13830
proc version     : 0
oprocp           : 0
opid             : 0
GROUP LOCK owner : 3fc4c3798
possible pid     : 17344
xid              : 1002-002C-00000002
dd_time          : 0.0 secs
dd_count         : 0
timeout          : 0.0 secs
On_timer_q?      : N
On_dd_q?         : N
lock_state       : GRANTED
Open Options     : KJUSERDEADLOCK
Convert options  : KJUSERNOQUEUE
History          : 0x4977d495
Msg_Seq          : 0x0
res_seq          : 21
valblk           : 0x00000000000000000000000000000000 .
Potential blocker (pid=17344) ON resource TX-000C002E-0001C277
DUMP LOCAL BLOCKER: initiate state dump FOR TIMEOUT
  possible owner[44.17344]
Submitting asynchronized dump request [28]

Et là je suis perdu
Je ne comprends pas par où poursuivre l'enquête.

Comme demandé dans d'autres posts, je vous joins un extrait d'un rapport AWR d'aujourd'hui qui correspond à une période standard d'occupation du serveur (8h à 16h)

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
LOAD Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:             46,178.68             26,575.41
              Logical reads:              3,079.20              1,772.05
              Block changes:                173.64                 99.93
             Physical reads:                 88.20                 50.76
            Physical writes:                 54.53                 31.38
                 User calls:                307.17                176.78
                     Parses:                 26.29                 15.13
                Hard parses:                 13.24                  7.62
                      Sorts:                 13.00                  7.48
                     Logons:                  0.02                  0.01
                   Executes:                242.20                139.38
               Transactions:                  1.74
 
  % Blocks changed per READ:    5.64    Recursive Call %:    27.10
 Rollback per transaction %:   67.81       Rows per Sort:   290.69

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   98.64       Redo NoWait %:   99.97
            Buffer  Hit   %:   97.72    In-memory Sort %:  100.00
            Library Hit   %:   95.82        Soft Parse %:   49.66
         Execute TO Parse %:   89.14         Latch Hit %:   99.21
Parse CPU TO Parse Elapsd %:   85.88     % Non-Parse CPU:   98.92
 
 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   78.57   70.18
    % SQL WITH executions>1:   85.24   87.85
  % Memory FOR SQL w/exec>1:   88.04   88.84
 
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
enq: TX - row LOCK contention       301,966     149,823    496   91.0 Applicatio
CPU time                                          7,546           4.6
db file sequential READ           1,920,392       3,444      2    2.1   User I/O
gc buffer busy                    1,252,999       1,824      1    1.1    Cluster
gc current block 2-way            1,050,626         589      1    0.4    Cluster

Merci d'avance pour l'aide apportée.

[jkofr]

Hello,

Code :

1
2
3
 
 
SELECT name, is_top_plan FROM v$rsrc_plan;

Cela donne quoi?

Regarde ici: http://kr.forums.oracle.com/forums/t...sageID=3736894

Merci
jko

[Mohamed.Houri]

Bonjour,

Quelle est la durée de ce rapport? c'est très important d'avoir un rapport AWR qui couvre uniquement la période où la base de données est en souffrance. Autrement, à cause des moyennes faites par le rapport AWR, une large période ne peut être d'aucune plus value.

Il serait intéressant de montrer cette partie de l'AWR

Code :

1
2
3
4
5
6
7
8
 
 
              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     28669 09-Feb-11 13:00:34       174      47.6
  End Snap:     28670 09-Feb-11 14:00:17       166      49.7
   Elapsed:               59.70 (mins)
   DB Time:               30.25 (mins)

En attendant, la partie Top 5 Timed Events de votre rapport reproduite ici

Code :

1
2
3
4
5
6
7
8
9
10
 
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
enq: TX - row LOCK contention       301,966     149,823    496   91.0 Applicatio
CPU time                                          7,546           4.6
db file sequential READ           1,920,392       3,444      2    2.1   User I/O
gc buffer busy                    1,252,999       1,824      1    1.1    Cluster
gc current block 2-way            1,050,626         589      1    0.4    Cluster

montre que la majeure partie du temps de réponse(91%) de votre base de données a été passée dans un TX - row lock contention qui veut dire probablement tentative d'insertion de deux valeurs identiques de clé primaire à partir de deux sessions concurrentes.

Cependant vous avez un très large nombre de 'db file sequential read' qui veut dire lecture à partir d'index. Il faut bien noter néanmoins que le temps moyen de lecture à partir d'un index est excellent (2 ms).

Ce "wait event" corrélé avec l'autre event "gc buffer busy" me conduit à penser que vous avez plusieurs neuds (nodes) qui veulent modifier le même block au même moment.

le "gc buffer busy" est l'equivalent RAC de "buffer busy waits" en non RAC. Bien que ce dernier ait été décomposé en deux "wait events" depuis la 10g

(1) read by other sessions
(2) buffer busy waits

Afin de differencier entre les sessions qui attendent que le block soit lu du disque et placé dans le "buffer cache" de celles qui attendent que la session finisse d'inserer ou d'updater le block qu'elles veulent modifier.


Dans votre cas, vous devriez consulter les deux parties suivantes de votre rapport

(1) SQL ordered by cluster wait time
ceci vous montrera le code sql qui est probablement le plus concerné avec votre problème

(2) Segments by Global Cache Buffer Busy Waits
alors que celui ci va vous dire quel est l'objet qui est le plus solliciter ici

Il semblerait bien que cela est dû à des unique indexes basés sur des séquences avec un faible cache.

Bien cordialement

Mohamed Houri

[korian]

Merci beaucoup pour vos réponses et votre attention.

@Jkofr

Code :

1
2
3
SYS@SQL> SELECT name, is_top_plan FROM v$rsrc_plan;
 
no rows selected

J'ai lu le lien, post intéressant.
J'ai donc fait cette requête sur v$lock :

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
SYS@SQL> SELECT * FROM v$lock WHERE type = 'TX';
 
ADDR             KADDR                   SID TY        ID1        ID2      LMODE    REQUEST      CTIME      BLOCK
---------------- ---------------- ---------- -- ---------- ---------- ---------- ---------- ---------- ----------
00000003F7AA6F50 00000003F7AA6F88        155 TX     720927     407370          6          0       1299          2
00000003FC618018 00000003FC618038        155 TX     327717     654446          0          6       1299          0
00000003FC6181E0 00000003FC618200        156 TX    1048609     130169          0          6        961          0
00000003F7A5E140 00000003F7A5E178        156 TX     458806     164247          6          0        961          2
00000003F7A9EC38 00000003F7A9EC70        157 TX     589920     199193          6          0       1070          2
00000003FC618148 00000003FC618168        157 TX     327717     654446          0          6       1070          0
00000003FC6102C8 00000003FC6102E8        158 TX     786493     115874          0          6       2492          0
00000003F7A92CC0 00000003F7A92CF8        159 TX    1507331        880          6          0          0          2
00000003F7A484D0 00000003F7A48508        160 TX     262191     600080          6          0       1083          2
00000003FC6180B0 00000003FC6180D0        160 TX    1048609     130169          0          6       1083          0
00000003F7A9E398 00000003F7A9E3D0        161 TX     655366     175317          6          0       2155          2
00000003FC6106F0 00000003FC610710        161 TX     327717     654446          0          6       2155          0
00000003F7A9DAF8 00000003F7A9DB30        162 TX     196643     628038          6          0       2343          2
00000003F7A7A530 00000003F7A7A568        163 TX     327717     654446          6          0       2400          1
00000003F7A6D478 00000003F7A6D4B0        164 TX     786493     115874          6          0       2492          1
00000003FC6108B8 00000003FC6108D8        165 TX     327717     654446          0          6       1477          0
00000003F7A6A0B8 00000003F7A6A0F0        165 TX     131091     554680          6          0       1477          2
 
17 rows selected.

Le bdd_lmd0_16075.trc de ce matin donnait par exemple ces warnings :

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
*** 2011-07-27 09:29:59.575
ENQUEUE DUMP REQUEST: FROM 1.2999 ON [0x5002a][0x9fcc9],[TX] FOR reason 2 mtype 0
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0x5002a][0x9fcc9],[TX]
----------resource 0x3f57a3638----------------------
resname       : [0x5002a][0x9fcc9],[TX]
LOCAL node    : 0
dir_node      : 0
master_node   : 0
hv idx        : 82
hv last r.inc : 4
current inc   : 4
hv STATUS     : 0
hv master     : 1
open options  : dd
grant_bits    : KJUSERNL KJUSEREX
GRANT mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
count         : 6         0         0         0         0         1
val_state     : KJUSERVS_NOVALUE
valblk        : 0x00000000000000000000000000000000 .
access_node   : 0
vbreq_state   : 0
state         : x0
resp          : 3f57a3638
ON Scan_q?    : N
Total accesses: 4418
Imm.  accesses: 3880
Granted_locks : 1
Cvting_locks  : 6
value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 3fccd93d8 gl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c60f8 possible pid 29933 xid 1003-0033-00000002 bast 0 rseq 46 mseq 0 history 0x14951495
  open opt KJUSERDEADLOCK
CONVERT_Q:
lp 3fccd9528 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4ba6c8 possible pid 29959 xid 1003-0034-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcd5b628 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c4c48 possible pid 29326 xid 1002-002B-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fccd9930 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c0e38 possible pid 29351 xid 1002-002E-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcc20798 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 owner 1  bast 1 rseq 99 mseq 0x1 history 0xd8d497ad
  convert opt KJUSERGETVALUE
lp 3fcd5ae30 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4bf988 possible pid 29386 xid 1002-002F-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcd5be08 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4b9218 possible pid 29970 xid 1003-0035-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
----------enqueue 0x3fccd93d8------------------------
LOCK version     : 40125
Owner node       : 0
grant_level      : KJUSEREX
req_level        : KJUSEREX
bast_level       : KJUSERNL
notify_func      : 0
resp             : 3f57a3638
procp            : 3fcab5ef0
pid              : 29959
proc version     : 0
oprocp           : 0
opid             : 0
GROUP LOCK owner : 3fc4c60f8
possible pid     : 29933
xid              : 1003-0033-00000002
dd_time          : 0.0 secs
dd_count         : 0
timeout          : 0.0 secs
On_timer_q?      : N
On_dd_q?         : N
lock_state       : GRANTED
Open Options     : KJUSERDEADLOCK
Convert options  : KJUSERNOQUEUE
History          : 0x14951495
Msg_Seq          : 0x0
res_seq          : 46
valblk           : 0x00000000000000000000000000000000 .
Potential blocker (pid=29933) ON resource TX-0005002A-0009FCC9
DUMP LOCAL BLOCKER: initiate state dump FOR TIMEOUT
  possible owner[51.29933]
Submitting asynchronized dump request [28]

Ou

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
*** 2011-07-27 09:29:59.575
ENQUEUE DUMP REQUEST: FROM 1.2999 ON [0x5002a][0x9fcc9],[TX] FOR reason 2 mtype 0
DUMP LOCAL BLOCKER/HOLDER: block level 5 res [0x5002a][0x9fcc9],[TX]
----------resource 0x3f57a3638----------------------
resname       : [0x5002a][0x9fcc9],[TX]
LOCAL node    : 0
dir_node      : 0
master_node   : 0
hv idx        : 82
hv last r.inc : 4
current inc   : 4
hv STATUS     : 0
hv master     : 1
open options  : dd
grant_bits    : KJUSERNL KJUSEREX
GRANT mode    : KJUSERNL  KJUSERCR  KJUSERCW  KJUSERPR  KJUSERPW  KJUSEREX
count         : 6         0         0         0         0         1
val_state     : KJUSERVS_NOVALUE
valblk        : 0x00000000000000000000000000000000 .
access_node   : 0
vbreq_state   : 0
state         : x0
resp          : 3f57a3638
ON Scan_q?    : N
Total accesses: 4418
Imm.  accesses: 3880
Granted_locks : 1
Cvting_locks  : 6
value_block:  00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
GRANTED_Q :
lp 3fccd93d8 gl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c60f8 possible pid 29933 xid 1003-0033-00000002 bast 0 rseq 46 mseq 0 history 0x14951495
  open opt KJUSERDEADLOCK
CONVERT_Q:
lp 3fccd9528 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4ba6c8 possible pid 29959 xid 1003-0034-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcd5b628 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c4c48 possible pid 29326 xid 1002-002B-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fccd9930 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4c0e38 possible pid 29351 xid 1002-002E-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcc20798 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 owner 1  bast 1 rseq 99 mseq 0x1 history 0xd8d497ad
  convert opt KJUSERGETVALUE
lp 3fcd5ae30 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4bf988 possible pid 29386 xid 1002-002F-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
lp 3fcd5be08 gl KJUSERNL rl KJUSEREX rp 3f57a3638 [0x5002a][0x9fcc9],[TX]
  master 0 gl owner 3fc4b9218 possible pid 29970 xid 1003-0035-00000002 bast 0 rseq 46 mseq 0 history 0x1495149a
  convert opt KJUSERGETVALUE
----------enqueue 0x3fccd93d8------------------------
LOCK version     : 40125
Owner node       : 0
grant_level      : KJUSEREX
req_level        : KJUSEREX
bast_level       : KJUSERNL
notify_func      : 0
resp             : 3f57a3638
procp            : 3fcab5ef0
pid              : 29959
proc version     : 0
oprocp           : 0
opid             : 0
GROUP LOCK owner : 3fc4c60f8
possible pid     : 29933
xid              : 1003-0033-00000002
dd_time          : 0.0 secs
dd_count         : 0
timeout          : 0.0 secs
On_timer_q?      : N
On_dd_q?         : N
lock_state       : GRANTED
Open Options     : KJUSERDEADLOCK
Convert options  : KJUSERNOQUEUE
History          : 0x14951495
Msg_Seq          : 0x0
res_seq          : 46
valblk           : 0x00000000000000000000000000000000 .
Potential blocker (pid=29933) ON resource TX-0005002A-0009FCC9
DUMP LOCAL BLOCKER: initiate state dump FOR TIMEOUT
  possible owner[51.29933]
Submitting asynchronized dump request [28]

Comment faire le lien entre les infos v$lock et ces traces ?

@Mohamed.Houri
Ok j'ai régénéré le rapport AWR entre 8h et 12h hier, période où les ralentissements ont été les plus fréquents. C'est un exemple pertinent.

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
LOAD Profile
~~~~~~~~~~~~                            Per Second       Per Transaction
                                   ---------------       ---------------
                  Redo size:             49,835.93             26,197.55
              Logical reads:              5,386.67              2,831.64
              Block changes:                154.74                 81.34
             Physical reads:                183.49                 96.46
            Physical writes:                106.76                 56.12
                 User calls:                497.66                261.61
                     Parses:                 42.54                 22.36
                Hard parses:                 20.58                 10.82
                      Sorts:                 20.63                 10.84
                     Logons:                  0.01                  0.00
                   Executes:                394.24                207.24
               Transactions:                  1.90
 
  % Blocks changed per READ:    2.87    Recursive Call %:    25.24
 Rollback per transaction %:   69.72       Rows per Sort:   206.27
 
Instance Efficiency Percentages (Target 100%)
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
            Buffer Nowait %:   98.76       Redo NoWait %:   99.96
            Buffer  Hit   %:   97.30    In-memory Sort %:  100.00
            Library Hit   %:   95.99        Soft Parse %:   51.62
         Execute TO Parse %:   89.21         Latch Hit %:   99.20
Parse CPU TO Parse Elapsd %:   86.50     % Non-Parse CPU:   99.05
 
 Shared Pool Statistics        Begin    End
                              ------  ------
             Memory Usage %:   78.57   40.27
    % SQL WITH executions>1:   85.24   84.99
  % Memory FOR SQL w/exec>1:   88.04   89.42
 
Top 5 Timed Events                                         Avg %Total
~~~~~~~~~~~~~~~~~~                                        wait   Call
Event                                 Waits    Time (s)   (ms)   Time Wait Class
------------------------------ ------------ ----------- ------ ------ ----------
enq: TX - row LOCK contention       209,443     103,910    496   89.5 Applicatio
CPU time                                          5,783           5.0
db file sequential READ           1,808,035       3,114      2    2.7   User I/O
gc buffer busy                      883,330       1,427      2    1.2    Cluster
gc current block 2-way              952,323         537      1    0.5    Cluster

J'ajoute la partie demandée :

Code :

1
2
3
4
5
6
              Snap Id      Snap Time      Sessions Curs/Sess
            --------- ------------------- -------- ---------
Begin Snap:     27038 26-Jul-11 07:59:50        61       3.5
  End Snap:     27042 26-Jul-11 11:59:52        63      15.2
   Elapsed:              240.04 (mins)
   DB Time:            1,935.10 (mins)

Puis les 2 suivantes :

Code :

1
2
3
4
5
6
7
8
9
10
SQL ordered BY Cluster Wait TimeDB/Inst: xxxx  Snaps: 27038-270
 
      Cluster   CWT % of     Elapsed         CPU
Wait Time (s) Elapsd Tim     Time(s)     Time(s)     Executions    SQL Id
------------- ---------- ----------- ----------- -------------- -------------
     2,177.85       30.9    7,044.23    1,917.29              3 608dk0typb4p1
Module: JDBC Thin Client
SELECT A0.blob$entrySetadHocAcl,A0.classnameA2A2,A0.branchIdA2typeDefinitionRefe
,A0.idA3A2ownership,A0.classnamekeydomainRef,A0.entrySetadHocAcl,A0.statestate,A
0.idA3domainRef,A0.classnamekeyA2ownership,A0.idA2A2,NVL(A0.classnameA2A2,'xxx'),A0B.noi wtsort0,A0.position wtsort1 FROM Ar A0,ArM

Comment puis-je récupérer le code SQL complet avec ce SQLID ?

Code :

1
2
3
4
5
6
7
8
9
10
11
12
13
Segments BY Global Cache Buffer BusyDB/Inst: xxxxx  Snaps: 27038-
-> % of Capture shows % of GC Buffer Busy FOR each top segment compared
-> WITH GC Buffer Busy FOR ALL segments captured BY the Snapshot
 
                                                                      GC
           Tablespace                      Subobject  Obj.        Buffer    % of
Owner         Name    Object Name            Name     Type          Busy Capture
---------- ---------- -------------------- ---------- ----- ------------ -------
PRO TS_SCA     AR                              TABLE      863,412   97.96
PRO IS_SCA_C7  AR$IDA3MASTERREFEREN            INDEX       11,637    1.32
PRO USERS      WORKITEM                        TABLE        5,264     .60
PRO USERS      FICHEARTICLE                    TABLE          933     .11
PRO INDX       PK_LISTEARTICLE                 INDEX           51     .01

AR est une table centrale de notre système.

Vos déductions semblent pertinentes même si je ne comprends toujours pas comment vous y parvenez

Quelle piste dois-je suivre maintenant svp ?

[jkofr]

Hello,

Dans le rapport AWR tu devrais avoir l'SQL non?

Tu peux générer aussi un rapport ASH en filtrer directement sur tes SID.

Question: entre le plantage DB et le début de tes ennuis, quels changements structurels on été effectues?
As tu vérifié tes objects?
As tu des index qui sont devenus unuseable?

Jko

[korian]

Envoyé par jkofr

Hello,

Merci de ton aide

Envoyé par jkofr

Dans le rapport AWR tu devrais avoir l'SQL non?

oui mais pas complet. Mais je le trouverais dans v$sql.

Envoyé par jkofr

Question: entre le plantage DB et le début de tes ennuis, quels changements structurels on été effectues?

Que veux tu dire par structurels ?
Il n'y a pas eu de changement physiques sur la baie.
A priori aucun changement logique à part une evolution de code mais qui est loin de tout ça.
Alors que la base est en RAC avec 2 instances, un arrêt brutal d'une instance par shutdown abort a été faite. Une influence ?

Envoyé par jkofr

As tu vérifié tes objects?

Comment fait-on ?

Envoyé par jkofr

As tu des index qui sont devenus unuseable?

Des index qui ne sont pas valides ? non, aucun

[jkofr]

Envoyé par korian

Que veux tu dire par structurels ?

Oui, structurel n'est peut-être pas le bon terme.
Nouveaux index, nouvelles requêtes, fonctionnalités.

Pour les objets invalides ou index inutilisable:
Depuis le user applicatif.

Code :

1
2
3
 
SELECT object_name,object_type FROM user_objects WHERE STATUS='INVALID';
SELECT index_name,table_name FROM user_indexes WHERE STATUS='UNUSABLE';

Concernant le shutdown abort, si il avait été problématique pas sur que tu aurais pu ouvrir ta base normalement.

Question: c quoi l'évolution de code?

Essais de récupérer les requêtes via ASH qui correspondent aux SID cités.

Jko

[korian]

Il y a 3 objets récents non valides.

L’évolution du code correspondait à la prise en compte de nouvelles recherches applicatives : nouvelle table, nouvelles vues (2 non-valides), un package (non valide).

Après le reste du code était surtout applicatif, peu d'impact sur la base.
Je vais éplucher le patch plus précisément la semaine prochaine.

[Mohamed.Houri]

Bonjour,

Pour votre information, lorsque votre base de données souffre d'un "lock", il suffit pour cela de générer un rapport AWR d'un dizaine de minutes pendant cette période.
C'est largement suffisant. Ceci dit, votre base semble souffrir d'un TX (transaction) "lock" au niveau d'un enregistrement (row lock transaction) sur un mode 6 et un "request"
de 6 également comme votre select sur v$lock l'a montré (ce qui exclut la possibilité d'un lock provenant de "foreign keys" non indexéss qui auquel cas aurait été du type TM et non TX comme c'est le cas ici).

Il faudrait trouver les sqls qui sont en collision afin de bien affiner votre recherche. Pour cela je vous conseille d'utiliser les scripts contenus dans le blog suivant

http://jonathanlewis.wordpress.com/2...ng-2/#more-320

et affiner jusqu'à arriver aux sqls qui bloquent.

Bon courage

Mohamed Houri

[korian]

Encore merci pour vos réponses.

Notre enquête interne nous a mené aussi sur d'autres directions.
Une piste sur la shared_pool avait été émise par par notre correspondant Oracle dans le cadre de la maintenance Sun (Donc pas un support Oracle à proprement parlé mais une aide appréciable)

La SGA_TARGET a été mise à niveau de SGA_MAX_SIZE et la valeur minimale de la SHARED_POOL a été augmenté en se basant sur les résultats de V$SHARED_POOL_ADVICE.

De plus, les stats de nos tables un peu obsolètes (quelques mois pour certaines tables de 40M de lignes) ont été recalculées.

Mais le plantage est revenu et nous avons pu identifié le problème
Notre applicatif, lors du rattrapage d'une modification multiple mal terminée, est confronté à un environnement data sans doute incohérent et n'arrive pas géré la fin de sa transaction.
Il verrouille certaines tables et les locks s'empilent jusqu'au clash.
Il nous reste plus qu'à découvrir quelles données lui posent problème et/ou corriger son comportement.

Merci pour votre aide.