Monday, August 1, 2011

System State Dumps when Database is Hang

If the database is hung then we need to gather system state dumps to try to determine what is happening. At least 3 dumps should be taken as follows:

Login to sqlplus as the internal user:
sqlplus "/ as sysdba"

rem -- set trace file size to unlimited:

alter session set max_dump_file_size = unlimited;

alter session set events '10998 trace name context forever, level 1';
alter session set events 'immediate trace name systemstate level 10';
alter session set events 'immediate trace name systemstate level 10';
alter session set events 'immediate trace name systemstate level 10';

or (If using 10G or higher)

(a) Non-Rac
sqlplus "/ as sysdba"

oradebug setmypid
oradebug unlimit
oradebug dump systemstate 266
wait 90 seconds
oradebug dump systemstate 266
wait 90 seconds
oradebug dump systemstate 266
quit

(b) RAC
$ sqlplus '/ as sysdba'
oradebug setmypid
oradebug unlimit
oradebug setinst all
oradebug -g all hanganalyze 4


Examples:-


SQL*Plus: Release 10.2.0.3.0 - Production on Mon Aug 1 13:23:33 2011

Copyright (c) 1982, 2006, Oracle. All Rights Reserved.

SQL>
SQL>
SQL> conn / as sysdba
Connected.
SQL>
SQL>
SQL> oradebug setmypid
Statement processed.
SQL>
SQL>
SQL> oradebug unlimit
Statement processed.
SQL>
SQL>
SQL> oradebug dump systemstate 266
Statement processed.
SQL>
SQL>
SQL> oradebug dump systemstate 266
Statement processed.
SQL>
SQL>
SQL> oradebug dump systemstate 266
Statement processed.
SQL>
SQL>
SQL> host
Microsoft Windows [Version 5.2.3790]
(C) Copyright 1985-2003 Microsoft Corp.

C:\Documents and Settings\Administrator>cd ..

C:\Documents and Settings>cd ..

C:\>e:

E:\>cd E:\oracle\admin\ORCL\udump


E:\oracle\admin\ORCL\udump>dir
Volume in drive E is New Volume
Volume Serial Number is 34E5-9E8C

Directory of E:\oracle\admin\orcl\udump

08/01/2011 01:24 PM

.
08/01/2011 01:24 PM ..
08/01/2011 01:25 PM 11,013,674 orcl_ora_4940.trc
07/31/2011 05:30 PM 1,187 ORCL_ora_5812.trc
08/01/2011 01:19 PM 10,661,311 ORCL_ora_796.trc
3 File(s) 21,676,172 bytes
2 Dir(s) 2,226,208,768 bytes free

E:\oracle\admin\ORCL\udump>
E:\oracle\admin\ORCL\udump>
E:\oracle\admin\ORCL\udump>




Sample content of dump trace file :-

Dump file e:\oracle\admin\ORCL\udump\ORCL_ora_4940.trc
Mon Aug 01 13:24:53 2011
ORACLE V10.2.0.3.0 - Production vsnsta=0
vsnsql=14 vsnxtr=3
Oracle Database 10g Enterprise Edition Release 10.2.0.3.0 - Production
With the Partitioning, OLAP and Data Mining options
Windows NT Version V5.2 Service Pack 2
CPU : 4 - type 586, 2 Physical Cores
Process Affinity : 0x00000000
Memory (Avail/Total): Ph:6591M/8190M, Ph+PgF:8599M/10041M, VA:1228M/2047M
Instance name: ORCL

Redo thread mounted by this instance: 1

Oracle process number: 30

Windows thread id: 4940, image: ORACLE.EXE (SHAD)


*** 2011-08-01 13:24:53.953
*** SERVICE NAME:(SYS$USERS) 2011-08-01 13:24:53.953
*** SESSION ID:(74.20430) 2011-08-01 13:24:53.953
===================================================
SYSTEM STATE
------------
System global information:
processes: base 3463BE84, size 150, cleanup 3464B26C
allocation: free sessions 346893F0, free calls 00000000
control alloc errors: 0 (process), 0 (session), 0 (call)
PMON latch cleanup depth: 0
seconds since PMON's last scan for dead processes: 61
system statistics:
223621 logons cumulative
37 logons current
60710576 opened cursors cumulative
417 opened cursors current
582526 user commits
19867 user rollbacks
41102921 user calls
937288061 recursive calls
2347168 recursive cpu usage
2873519071 session logical reads
0 session stored procedure space
4351578 CPU used when call started
4829273 CPU used by this session
619915009 DB time
0 cluster wait time
12186252884 concurrency wait time
13327956119 application wait time
294918081229 user I/O wait time
1311853036 session connect time
1312183230 process last non-idle time
409411033118376 session uga memory
175540294696 session uga memory max
2651256 messages sent
2651260 messages received
17443047 background timeouts
198259136188 session pga memory
327793236932 session pga memory max
39128 enqueue timeouts
13868 enqueue waits
0 enqueue deadlocks
57691467 enqueue requests
1327193 enqueue conversions
57652220 enqueue releases
0 global enqueue gets sync
0 global enqueue gets async
0 global enqueue get time
0 global enqueue releases
88916765 physical read total IO requests
24662924 physical read total multi block requests
2722900021760 physical read total bytes
9625787 physical write total IO requests
1562095 physical write total multi block requests
203178034176 physical write total bytes
0 IPC CPU used by this session
0 gcs messages sent
0 ges messages sent
0 global enqueue CPU used by this session
212843812 db block gets
212836978 db block gets from cache
6834 db block gets direct
2660675259 consistent gets
2611356599 consistent gets from cache
402072651 consistent gets - examination
49318660 consistent gets direct
329332119 physical reads
276710762 physical reads cache
52621356 physical reads direct
87337228 physical read IO requests
2697888718848 physical read bytes
146443225 db block changes
61764976 consistent changes
487 recovery blocks read
11835763 physical writes
7471349 physical writes direct
4364414 physical writes from cache
3120233 physical write IO requests
96958570496 physical write bytes
10168509 physical writes non checkpoint
22282455 summed dirty queue length
2555802 DBWR checkpoint buffers written
208419 DBWR thread checkpoint buffers written
9 DBWR tablespace checkpoint buffers written
452 DBWR parallel query checkpoint buffers written
2799 DBWR object drop buffers written
73431 DBWR transaction table writes
640104 DBWR undo block writes
1034 DBWR revisited being-written buffer
0 DBWR make free requests
0 DBWR lru scans
6569 DBWR checkpoints
0 DBWR fusion writes
0 prefetch clients - keep
0 prefetch clients - recycle
49 prefetch clients - default
0 prefetch clients - 2k
0 prefetch clients - 4k
0 prefetch clients - 8k
0 prefetch clients - 16k
0 prefetch clients - 32k
62681 change write time
2088143 redo synch writes
142300 redo synch time
1 exchange deadlocks
282976747 free buffer requested
1356510 dirty buffers inspected
12866 pinned buffers inspected
29971201 hot buffers moved to head of LRU
283485323 free buffer inspected
0 commit cleanout failures: write disabled
23055 commit cleanout failures: block lost
35 commit cleanout failures: cannot pin
0 commit cleanout failures: hot backup in progress
26 commit cleanout failures: buffer being written
20649 commit cleanout failures: callback failure
7275988 commit cleanouts
7232223 commit cleanouts successfully completed
0 recovery array reads
0 recovery array read time
313583 CR blocks created
2632 current blocks converted for CR
1689223 switch current to new buffer
1242 write clones created in foreground
72251 write clones created in background
0 write clones created for recovery
197664950 physical reads cache prefetch
14692 physical reads prefetch warmup
1289117 prefetched blocks aged out before use
7255 prefetch warmup blocks aged out before use
0 prefetch warmup blocks flushed out before use
0 physical reads retry corrupt
394 physical reads direct (lob)
3273094 physical reads direct temporary tablespace
730 physical writes direct (lob)
7451971 physical writes direct temporary tablespace
0 cold recycle reads
5741258 shared hash latch upgrades - no wait
19 shared hash latch upgrades - wait
0 physical reads for flashback new
425990 calls to kcmgcs
0 calls to kcmgrs
6166219 calls to kcmgas
230594925 calls to get snapshot scn: kcmgss
6128 redo blocks read for recovery
43839595 redo entries
12978872464 redo size
3921 redo buffer allocation retries
252572632 redo wastage
134 redo writer latching time
979170 redo writes
26702593 redo blocks written
465677 redo write time
3714 redo log space requests
20932 redo log space wait time
0 redo log switch interrupts
558228 redo ordering marks
1742726 redo subscn max counts
0 gc cr blocks served
0 gc cr block build time
0 gc cr block flush time
0 gc cr block send time
0 gc current blocks served
0 gc current block pin time
0 gc current block flush time
0 gc current block send time
0 gc cr blocks received
0 gc cr block receive time
0 gc current blocks received
0 gc current block receive time
0 gc local grants
0 gc remote grants
0 gc blocks lost
0 gc claim blocks lost
0 gc blocks corrupt
0 gc CPU used by this session
0 total number of slots
0 instance recovery database freeze count
287 background checkpoints started
287 background checkpoints completed
0 number of map operations
0 number of map misses
0 flashback log writes
0 serializable aborts
0 transaction lock foreground requests
0 transaction lock foreground wait time
0 transaction lock background gets
0 transaction lock background get time
3934055552 undo change vector size
33117 transaction tables consistent reads - undo records applied
50 transaction tables consistent read rollbacks
836940 data blocks consistent reads - undo records applied
2183915569 no work - consistent read gets
459281 cleanouts only - consistent read gets
94312 rollbacks only - consistent read gets
221885 cleanouts and rollbacks - consistent read gets
0 RowCR attempts
0 RowCR hits
0 RowCR - row contention
0 RowCR - resume
4127694 rollback changes - undo records applied
5037 transaction rollbacks
633777 immediate (CURRENT) block cleanout applications
681166 immediate (CR) block cleanout applications
4156551 deferred (CURRENT) block cleanout applications
529598 commit txn count during cleanout
337449 active txn count during cleanout
827788 cleanout - number of ktugct calls
0 immediate CR cleanouts (index blocks)
0 deferred CUR cleanouts (index blocks)
9510 Commit SCN cached
856646221 Cached Commit SCN referenced
0 auto extends on undo tablespace
0 drop segment calls in space pressure
0 total number of undo segments dropped
3354 doubling up with imu segment
0 tune down retentions in space pressure
0 steps of tune down ret. in space pressure
0 space was found by tune down
0 space was not found by tune down
5417 commit batch/immediate requested
33 commit batch requested
5384 commit immediate requested
5417 commit batch/immediate performed
33 commit batch performed
5384 commit immediate performed
0 commit wait/nowait requested
0 commit nowait requested
0 commit wait requested
0 commit wait/nowait performed
0 commit nowait performed
0 commit wait performed
0 global undo segment hints helped
0 global undo segment hints were stale
0 local undo segment hints helped
0 local undo segment hints were stale
0 undo segment header was pinned
8248 total number of times SMON posted
10 SMON posted for undo segment recovery
0 SMON posted for txn recovery for other instances
0 SMON posted for instance recovery
399 SMON posted for undo segment shrink
11 SMON posted for dropping temp segment
0 SMON posted for supplemental logging cleanup
479225 IMU commits
94092 IMU Flushes
1222 IMU contention
162 IMU recursive-transaction flush
0 IMU undo retention flush
22263 IMU ktichg flush
0 IMU bind flushes
0 IMU mbu flush
179563 IMU pool not allocated
38927 IMU CR rollbacks
1509280200 IMU undo allocation size
285284696 IMU Redo allocation size
179563 IMU- failed to get a private strand
242 Misses for writing mapping
3524877 table scans (short tables)
136996 table scans (long tables)
43 table scans (rowid ranges)
0 table scans (cache partitions)
8 table scans (direct read)
53946061228 table scan rows gotten
1028117596 table scan blocks gotten
1788517817 table fetch by rowid
1511150 table fetch continued row
24972023 cluster key scans
44352616 cluster key scan block gets
61446702 rows fetched via callback
0 queue update without cp update
0 index crx upgrade (prefetch)
2 index crx upgrade (found)
3911874 index crx upgrade (positioned)
38083 leaf node splits
15181 leaf node 90-10 splits
580 branch node splits
155 failed probes on index block reclamation
0 recursive aborts on index block reclamation
0 native hash arithmetic execute
0 native hash arithmetic fail
637320 lob reads
52550942 lob writes
52550942 lob writes unaligned
10597 index fast full scans (full)
967565 index fast full scans (rowid ranges)
492036 index fast full scans (direct read)
208435218 index fetch by key
178942767 index scans kdiixs1
0 queue splits
0 queue flush
0 queue position update
0 queue single row
0 queue ocp pages
0 queue qno pages
1159235 heap block compress
8171 sql area purged
1204833 sql area evicted
0 CCursor + sql area evicted
55540677 session cursor cache hits
2847702 session cursor cache count
0 java call heap total size
0 java call heap total size max
0 java call heap used size
0 java call heap used size max
0 java call heap live size
0 java call heap live size max
0 java call heap object count
0 java call heap object count max
0 java call heap live object count
0 java call heap live object count max
0 java call heap gc count
0 java call heap collected count
0 java call heap collected bytes
0 java session heap used size
0 java session heap used size max
0 java session heap live size
0 java session heap live size max
0 java session heap object count
0 java session heap object count max
0 java session heap live object count
0 java session heap live object count max
0 java session heap gc count
0 java session heap collected count
0 java session heap collected bytes
957837 cursor authentications
7916 queries parallelized
0 DML statements parallelized
12 DDL statements parallelized
9174 DFO trees parallelized
9174 Parallel operations not downgraded
0 Parallel operations downgraded to serial
0 Parallel operations downgraded 75 to 99 pct
0 Parallel operations downgraded 50 to 75 pct
0 Parallel operations downgraded 25 to 50 pct
0 Parallel operations downgraded 1 to 25 pct
15165057 PX local messages sent
15164706 PX local messages recv'd
0 PX remote messages sent
0 PX remote messages recv'd
3005899850 buffer is pinned count
974810284 buffer is not pinned count
32 no buffer to keep pinned count
0 table lookup prefetch client count
12108 workarea memory allocated
12166591 workarea executions - optimal
56 workarea executions - onepass
1 workarea executions - multipass
459992 parse time cpu
568264 parse time elapsed
27788105 parse count (total)
3074353 parse count (hard)
2094 parse count (failures)
0 frame signature mismatch
89918569 execute count
10679708941 bytes sent via SQL*Net to client
5201687905 bytes received via SQL*Net from client
40820429 SQL*Net roundtrips to/from client
0 bytes sent via SQL*Net to dblink
0 bytes received via SQL*Net from dblink
0 SQL*Net roundtrips to/from dblink
23683029 sorts (memory)
124 sorts (disk)
1646989090 sorts (rows)
0 OTC commit optimization attempts
0 OTC commit optimization hits
0 OTC commit optimization failure - setup
Orapids on dead process list: [count = 0]
PROCESS 1:
----------------------------------------
SO: 3464AC7C, type: 2, owner: 00000000, flag: INIT/-/-/0x00
(process) Oracle pid=1, calls cur/top: 00000000/00000000, flag: (20) PSEUDO
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 0
last post received-location: No post
last process to post me: none
last post sent: 0 0 0
last post sent-location: No post
last process posted by me: none
(latch info) wait_event=0 bits=0
O/S info: user: , term: , ospid:
OSD pid info: Windows thread id: 0, image: PSEUDO
Dump of memory from 0x3463C4B8 to 0x3463C63C
3463C4B0 00000000 00000000 [........]
3463C4C0 00000000 00000000 00000000 00000000 [................]
Repeat 22 times
3463C630 00000000 00000000 00000000 [............]
PROCESS 2:
----------------------------------------
SO: 3464B26C, type: 2, owner: 00000000, flag: INIT/-/-/0x00
(process) Oracle pid=2, calls cur/top: 34761374/34761374, flag: (e) SYSTEM
int error: 0, call error: 0, sess error: 0, txn error 0
(post info) last post received: 0 0 18
last post received-location: ksuxfd
last process to post me: 3464b26c 1 14
last post sent: 0 0 18
last post sent-location: ksuxfd
last process posted by me: 3464b26c 1 14
(latch info) wait_event=0 bits=0
Process Group: DEFAULT, pseudo proc: 34682F50
O/S info: user: SYSTEM, term: TESTDB, ospid: 1956
OSD pid info: Windows thread id: 1956, image: ORACLE.EXE (PMON)
Short stack dump:
_ksdxfstk+14<-_ksdxcb+1481<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadStart@4+819<-77E64826<-00000000<-_sntevaque+54<-_ntevque+582<-_nsevwait+724<-_ksnwait+91<-_ksliwat+1521<-_kslwaitns_timed+30<-_kskthbwt+219<-_kslwait+58<-_ksuclnwt+137<-_ksucln+673<-_ksbrdp+808<-_opirip+674<-_opidrv+857<-_sou2o+45<-_opimai_real+227<-_opimai+92<-_BackgroundThreadStart@4+495<-77E64826
Dump of memory from 0x3463C63C to 0x3463C7C0
3463C630 0000001B [....]
3463C640 33C36254 00000005 0003139D 33C361F8 [Tb.3.........a.3]

No comments: