Roads ? - where we're going, we don't need roads ...
ass.awk | ORA600
ORA600 content Content RSS
Oracle ORA600 News RRSS Oracle News RSS
ORA600 blog Blog RSS
ORA600 blog Blog Atom

User login

ass.awk

Oracle ASS - one time it will save yours !


For those who don't know Oracle ASS - it's an awk script that is hidden in Oracle's LTOM (aka Lite Onboard Monitoring).
You can download it from metalink - see note ID 352363.1.

It's an awk script that formats system state dumps. I now and then use it to format massive trace files to something I can actually use.

A couple of months ago I had to investigate why a 2 node RAC on windows kept on crashing.
The dba managing it didn't really bother to check the system state dump - instead they just open a call with Oracle and uploaded the trace files.
As usual, the dba blamed the developers - 'it's the app - it's the app' - and I had to defuse the situation and as the developers couldn't see anything wrong and the relationship started to turn sour.
I wasn't allowed access to the system but I was able to have a look at the trace files - or as the dba called it 'a very complex logfile'.

Fair enough - the system state dump was several megabytes larges but luckely I had Oracle ASS ;-)
Within minutes I kind of figured out what the problem was. 

Just looking at some of the wait events from the output below:
SGA: allocation forcing component growth
cursor: pin S wait on X
row cache lock

This looks like an sga resize operation, at which point library cache locks arise.
A sga resize operation can hang the database for brief moments of time especially when the shared pool needs to be resized.
However it this case, the instance was crashing.

With no access to the system I told the dba to have a look v$sga_resize_ops. If there are excessive resize operations, the sga might simply be sized too small.
I also got hand of the alert logs - as the instances were frequently crashing, I could see the startup in the alert.log, showing me sga settings.
And I kid you not - these 2 nodes were configure with SGA_TARGET=256M !!! I was surprise this thing even started !
Bumping up sga_target basically solved all issues.

This puppy was running in production for a month, had lots of issues and yet, the dba hadn't even bothered to check even the most basics settings.
Instead, they just blamed the app, opened a call with oracle, getting some general advise and be done with it. Amazing...


awk -f ass109.awk tracefile.trc > out

Starting Systemstate 1
..............................................................................
.................................................................
Ass.Awk Version 1.0.9 - Processing xyz_ora_4948.trc

System State 1
~~~~~~~~~~~~~~~~
1:                                      
2:  waiting for 'pmon timer'            
3:  waiting for 'DIAG idle wait'        
4:  waiting for 'rdbms ipc message'     
5:  waiting for 'rdbms ipc message'    [Latch received-location:] 
6:  waiting for 'ges remote message'    
7:  waiting for 'gcs remote message'    
8:  waiting for 'gcs remote message'    
9:  waiting for 'gcs remote message'    
10: waiting for 'gcs remote message'    
11: waiting for 'gcs remote message'    
12: waiting for 'gcs remote message'    
13: last wait for 'rdbms ipc message'   
14: waiting for 'rdbms ipc message'     
15: waiting for 'rdbms ipc message'     
16: waiting for 'rdbms ipc message'     
17: waiting for 'rdbms ipc message'     
18: waiting for 'rdbms ipc message'     
19: waiting for 'SGA: allocation forcing component growth' 
20: waiting for 'enq: DR - contention' [Enqueue DR-00000000-00000000] 
21: waiting for 'SGA: allocation forcing component growth' 
22: waiting for 'SGA: allocation forcing component growth' 
23: waiting for 'SGA: allocation forcing component growth' 
24: waiting for 'rdbms ipc message'     
25: waiting for 'SGA: allocation forcing component growth' 
     Cmd: Select
26: waiting for 'ASM background timer'  
27: waiting for 'rdbms ipc message'     
28: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
29: waiting for 'rdbms ipc message'     
30: waiting for 'rdbms ipc message'     
31: waiting for 'Streams AQ: qmn coordinator idle wait' 
32: waiting for 'cursor: pin S wait on X' 
     Cmd: Select
33: waiting for 'PX Deq: Parse Reply'   
34: waiting for 'SQL*Net message from client' 
35: waiting for 'PX Deq: Parse Reply'   
     Cmd: Select
36: waiting for 'cursor: pin S wait on X' 
     Cmd: Select
37: waiting for 'cursor: pin S wait on X' 
     Cmd: Select
38: waiting for 'cursor: pin S wait on X' 
     Cmd: Select
39: waiting for 'cursor: pin S wait on X' 
     Cmd: Select
40: waiting for 'SGA: allocation forcing component growth' 
     Cmd: Select
41: waiting for 'Streams AQ: qmn slave idle wait' 
42: waiting for 'PX Deq: Parse Reply'   
     Cmd: Select
43: for 'Streams AQ: waiting for time management or cleanup tasks' 
44: waiting for 'PX Deq: Execution Msg' 
     Cmd: Select
45: waiting for 'PX Deq: Parse Reply'   
     Cmd: Select
46: waiting for 'PX Deq: Execution Msg' 
     Cmd: Select
47: waiting for 'PX Deq: Parse Reply'   
     Cmd: Select
48: waiting for 'enq: PS - contention' [Enqueue PS-00000002-00000E0C] 
     Cmd: Select
49: waiting for 'class slave wait'      
50: waiting for 'SGA: allocation forcing component growth' 
     Cmd: PL/SQL Execute
51:                                     
52: waiting for 'PX Deq: Parse Reply'   
53: waiting for 'SGA: allocation forcing component growth' 
     Cmd: PL/SQL Execute
54: waiting for 'PX Deq: Execution Msg' 
     Cmd: Select
55: waiting for 'PX Deq: Parse Reply'   
     Cmd: Select
56: waiting for 'PX Deq: Parse Reply'   
57: waiting for 'SGA: allocation forcing component growth' 
58: waiting for 'PX Deq: Execution Msg' 
     Cmd: Select
59: waiting for 'SGA: allocation forcing component growth' 
     Cmd: Select
60: waiting for 'SGA: allocation forcing component growth' 
     Cmd: Select
61: waiting for 'PX Deq: Execution Msg' 
     Cmd: Select
62: waiting for 'PX Deq: Parse Reply'   
63: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
64: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
65: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
66: waiting for 'PX Deq: Parse Reply'   
67: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
68: waiting for 'SGA: allocation forcing component growth' 
69: last wait for 'ksdxexeotherwait'   [Rcache object=000007FF88BFD200,] 
70: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
71: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
72: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
73: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
74: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
75: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
76: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
77: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
78: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
79: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
80: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
81: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
82: waiting for 'row cache lock'       [Rcache object=000007FF88AC2658,] 
83: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
84: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
85: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
86: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
87: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
88: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
89: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
90: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
91: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
92: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
93: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
94: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
95: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
96: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
97: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
98: waiting for 'row cache lock'       [Rcache object=000007FF88AC2658,] 
99: waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
100:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
101:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
102:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
103:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
104:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
105:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
106:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
107:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
108:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
109:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
110:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
111:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
112:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
113:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
114:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
115:waiting for 'row cache lock'       [Rcache object=000007FF88AC2658,] 
116:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
117:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
118:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
119:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
120:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
121:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
122:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
123:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
124:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
125:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
126:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
127:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
128:waiting for 'row cache lock'       [Rcache object=000007FF88AC2658,] 
129:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
130:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
131:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
132:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
133:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
134:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
135:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
136:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
137:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
138:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
139:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
140:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
141:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
142:waiting for 'row cache lock'       [Rcache object=000007FF88BFD200,] 
143:waiting for 'row cache lock'       [Rcache object=000007FF88AC2658,] 
Blockers
~~~~~~~~

Above is a list of all the processes. If they are waiting for a resource
then it will be given in square brackets. Below is a summary of the
waited upon resources, together with the holder of that resource.
Notes:
~~~~~
o A process id of '???' implies that the holder was not found in the
  systemstate.

                    Resource Holder State
    Latch received-location:    ??? Blocker
Enqueue DR-00000000-00000000    ??? Blocker
Rcache object=000007FF88BFD200,    57: waiting for 'SGA: allocation forcing component growth'
Enqueue PS-00000002-00000E0C    48: Self-Deadlock
Rcache object=000007FF88AC2658,    68: waiting for 'SGA: allocation forcing component growth'

Query Co-Ordinator to Query Slave Mapping
~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~
QC=  33:  [Count=1]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0E)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
QC=  35:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0F)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E0F)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
  44: PS-01-0E0F   1   00000,         35:         44:  DTA,     FRE     STRE    0
QC=  42:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0D)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E0E)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
  46: PS-01-0E0E   1   00000,         42:         46:  DTA,     FRE     STRE    0
QC=  45:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E07)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E09)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
  61: PS-01-0E09   1   00000,         45:         61:  DTA,     FRE     STRE    0
QC=  47:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0B)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E0C)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
  54: PS-01-0E0C   1   00000,         47:         54:  DTA,     FRE     STRE    0
QC=  48:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0C)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E0D)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
QC=  52:  [Count=1]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E0A)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
QC=  55:  [Count=2]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E08)
           Communicates with Slave 0 (hex) on instance 1 (PS-01-0E0A)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
  58: PS-01-0E0A   1   00000,         55:         58:  DTA,     FRE     STRE    0
QC=  56:  [Count=1]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E05)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
QC=  62:  [Count=1]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E06)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
QC=  66:  [Count=1]
           Communicates with Slave 0 (hex) on instance 2 (PS-02-0E09)
Slave     Info Msg    State        From          To  Type  Status     Mode  Err
                         ------------------------
STATUS Key:
  DEQ = buffer has been dequeued
  EML = buffer on emergency message list
  ENQ = buffer has been enqueued
  FLST= buffer is on SGA freelist
  FRE = buffer is free (unused)
  GEB = buffer has been gotten for enqueuing
  GDB = dequeued buffer has been gotten 
  INV = buffer is invalid (non-existent)
  QUE = buffer on queue message list
  RCV = buffer has been received 
  NOFL= not on freelist (just removed)
                              ------------------------

Object Names
~~~~~~~~~~~~
Latch received-location:              last post received-location: kjmdrms
Enqueue DR-00000000-00000000                              
Rcache object=000007FF88BFD200,                              
Enqueue PS-00000002-00000E0C                              
Rcache object=000007FF88AC2658,                              


53697 Lines Processed.




Howto's
See DUDE primer for info

Get Support

Europe

Belgium :
Kurt Van Meerbeeck
ORA600 bvba
E-mail
dude@ora600.be
Cell : +32 495 580714

Denmark :
Michael Môller
Service & Support Manager
Miracle AS
E-mail :
hra@miracleas.dk
Cell: +45 53 74 71 27


North America

USA :
Tim Gorman
Evdbt Inc
E-mail
tim@evdbt.com
Cell : +1 303 885 4526

Canada :
Pythian
E-mail
dude@pythian.com
Contact


Latin America

Brazil :
HBtec
E-mail
dude@hbtec.com.br
Cell : +55 47 88497639
Contact


Africa

South Africa :
Kugendran Naidoo
NRG Consulting
E-mail
k@nrgc.co.za
Cell : +27 82 7799275


East Asia Pacific

Australia
Andre Araujo
Pythian Australia
E-mail
dude@pythian.com
Cell : +61 2 9191 7427 ext. 1270