Debugging Oracle Instance Hangs

Author: [Link]@[Link]
Version: 2.1, Updated: 5/27/07
Download the most recent version (make sure to clear your web-browser file cache):
[Link]

Version Changes
2.1 Update "What about Windows?" section, plus minor revisions
2.0 New section "Debugging Hangs Outside of the Lrgs", added PQ script to "Component Specific Debugging
Techniques", new content in "Basic Oracle Architecture", miscellaneous improvements

Contents:
 Document Overview
 Basic Oracle Architecture
o Hang Analysis Dump Intro
o Identifying Foregrounds / Shared Servers
o Reading Call Stacks
o Analyzing Call Stacks of Hung Processes
o Wait Events and Hang Analysis Dump Details
o Hang Analysis Dump Scope
 Lrg Hang Detection Architecture
 Determining the Root Cause of the Hang (Step-by-Step Method)
 Component Specific Debugging Techniques
 Examples
 What about Windows?
 Still Can't Debug the Hang?
 Debugging Hangs Outside of the Lrgs
 Enhancement Requests

Document Overview:

This document is primarily aimed at helping triage hangs encountered in our RDBMS lrg (long-
regression) runs. The lrg symptom abstract of such a hang is "-- oradump called". The focus will
be on the 11gr1 infrastructure, however where possible we will document older releases. We also
detail how to map the lrg-hang triaging techniques to hangs encountered outside our lrgs.

For those not familiar with our hang triaging infrastructure, it's best to read this document in two
passes. In the first pass skim through every section except the examples section. The examples
section shows step by step how to apply the techniques described in this document.

The goals of the document:

 Document our RDBMS lrg hang triaging infrastructure: Our infrastructure is somewhat
sophisticated and has significantly improved in 11gr1 yet most people are not aware of
the details and therefore do not take advantage of it.

The hope is that as our infrastructure evolves this document will be kept up to date so
that everyone can be aware of latest techniques and infrastructure improvements for
hang triaging.

This document avoids documenting component specific triaging techniques (though a

section is provided for component owners to add links such to documents). Instead, this
document showcases how the improved 11gr1 hang analysis dumps can be used to
easily triage hangs without requiring any component specific knowledge. For the first time

Page 1 of 32
 ever, via the hang analysis dump, you can see the short-stacks, current sql, and wait
information for all interesting processes throughout the cluster in a single trace file.

 Provide a step-by-step approach to triaging hangs: This allows every member of the st
organization to quickly and correctly triage hangs without component specific knowledge.
Furthermore, even for those who triage hangs on a regular basis, the checklist in this
section can be used to help diagnose unusual hangs.

Basic Oracle Architecture:

This section contains details on the basic oracle architecture that is required to triage Oracle
instance hangs.

Hang Analysis Dump Intro:

Hang analysis is an oracle dump used to determine why the instance is hung. It outputs which
sessions are blocking other sessions based on hang analysis callbacks implemented by the
resource layer owners. The hang analysis output contains the current wait, current sql, short
stack, and wait history for each interesting session. Uninteresting sessions like idle sessions are
automatically skipped.

Since reading the hang analysis dumps requires understanding the basic Oracle Architecture,
towards the end of the basic architecture section we will detail how to read the hang analysis
dumps. Note that in the examples section we have provided a few sample hang analysis dumps
( [example1] [example2] ).

See kgslhng.h for a detailed overview of hang analysis.

Identifying Foregrounds / Shared Servers:

When you determine that oratst is waiting for sqlplus sessions or oci clients to complete, the first
thing to do is find the OSID's of the oracle processes executing the client sql so that you can
check if the oracle processes are spinning, blocked, etc.

There are two primary mechanisms by which clients can execute sql in oracle processes:
dedicated server and shared server. In the dedicated server model there is a process, known as
a foreground, that executes the sql. In the shared server model there is a pool of background
processes that execute the sql.

Identifying dedicated servers:

 In the ps output search for processes with names like "oracle…(LOCAL=…)". In the
example below processes 19804, 19806, and 19808 are all foregrounds.

-- ps output --
aime3 19781 1 0 12:22 ? 00:00:01 ora_cjq0_aime3
aime3 19785 1 0 12:22 ? 00:00:00 ora_q000_aime3
aime3 19787 1 0 12:22 ? 00:00:00 ora_q001_aime3
aime3 19804 1 0 12:22 ? 00:00:00 oracleaime3
(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
aime3 19806 1 0 12:22 ? 00:00:00 oracleaime3
(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))
aime3 19808 1 0 12:22 ? 00:00:00 oracleaime3
(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))

 In the hang analysis output search for processes with name " oracle@… (TNS…)"

os id: 19804
process id: 23, oracle@stawn11 (TNS V1-V3)
...

Page 2 of 32
 os id: 19808
process id: 25, oracle@stawn11 (TNS V1-V3)

Identifying shared servers. Shared servers are oracle backgrounds. Their background name
starts with an S and is followed by 3 numeric digits:
 Backgrounds in the ps output for database instances are identified by "ora_<4 letter
background name>_<oracle_sid>". For ASM instances they are identified by "asm_<4
letter background name>_<oracle_sid>". In the example below processes 20785 and
20787 are shared servers.

-- ps output --
aime3 19781 1 0 12:22 ? 00:00:01 ora_cjq0_aime3
aime3 20785 1 0 12:22 ? 00:00:00 ora_s000_aime3
aime3 20787 1 0 12:22 ? 00:00:00 ora_s001_aime3

 In hang analysis the background name is in parenthesis.

os id: 20785
process id: 30, oracle@stahi16 (S000)

Reading Call Stacks:

There are several common mechanisms through which the call stacks of Oracle processes are
obtained:
 error stack dump : this is a dump that is usually seen when an error occurs in an oracle
process. Our hang diagnostic infrastructure attempts to explicitly invoke this dump on
every oracle process and the output is in the per process trace file.
 gdb / pstack output : our diagnostic scripts use gdb / pstack to obtain the call stack
 short stack : this is the stack dump in a condensed form.

The error stack and gdb / pstack output are similarly formatted. The bottom most routine is the
initial entry point and the top most routine is the routine that the process is currently executing. In
the example below __libc_start_main() is the starting routine for the thread. This routine
invoked / called main(). main() called ssthrdmain(). And so on.

*** 2007-04-02 03:22:40.353

Received ORADEBUG command (#5) 'dump errorstack 3' from process 'Unix process pid: 3457,
image: <none>'
*** 2007-04-02 03:22:40.354
----- Error Stack Dump -----
----- Current SQL Statement for this session (sql_id=0000000000000) -----
GRANT "EXP_FULL_DATABASE" TO "DBA"
----- Call Stack Trace -----
calling call entry argument values in hex
location type point (? means dubious value)
-------------------- -------- -------------------- ----------------------------
skdstdst()+38 call kgdsdst() BFFF3070 ? 3 ?
ksedst1()+88 call skdstdst() BFFF3070 ? 1 ? 1 ? 97C0A2E ?
97C1440 ? 97C0A2E ?
ksedst()+33 call ksedst1()+8 0 ? B7FC161C ? 2050025 ? 0 ?
FF ? 2004 ?
dbkedDefDump()+845 call ksedst() 1 ? 0 ? 0 ? 0 ? 0 ? 0 ?
ksedmp()+47 call dbkedDefDump() 3 ? 0 ?
ksdxfdmp()+1432 call 00000000 3 ? 0 ? 0 ? 0 ? 0 ? 0 ?
ksdxcb()+1560 call 00000000 BFFF3910 ? 11 ? 3 ?
BFFF3B1C ? BFFF3ACC ?
sspuser()+102 call 00000000 1 ? 2000 ? 0 ? 0 ? 0 ? 0 ?
semtimedop()+36 signal 00000000 C ? BFFF3DE8 ? BFFF3E68 ?
sskgpwwait()+286 call 00000000 3E48002 ? BFFF430C ? 1 ?
BFFF4304 ?
skgpwwait()+142 call sskgpwwait() BFFF43D8 ? EB79D60 ?
305D4E4C ? 2DC6C0 ? 0 ?
ksliwat()+1587 call skgpwwait() BFFF43D8 ? EB79D60 ?
305D4E4C ? 2DC6C0 ? 0 ?

Page 3 of 32
kslwaitctx()+97 call ksliwat() 3073D894 ? 3073D894 ? 12C ?
kqrget()+947 call kslwaitctx() BFFF458C ? 12C ?
kqrLockAndPinPo()+3 call kqrget() 2B9F5084 ? 5 ? 7FFFFFFF ?
64
kqrpre1()+819 call kqrLockAndPinPo() A ? 2CBE86B4 ? 2F1CC220 ? 5 ?
0 ? 0 ? 0 ?
kqrpre()+57 call kqrpre1()+13 A ? BFFF51D4 ? BFFF520C ? 5 ?
...
opimai_real()+196 call sou2o() BFFF9E4C ? 3C ? 4 ?
BFFF9E68 ?
ssthrdmain()+111 call opimai_real() 2 ? BFFF9F70 ?
main()+198 call ssthrdmain() 2 ? BFFF9F70 ?
__libc_start_main() call 00000000 2 ? BFFFA034 ? BFFFA040 ?
+211 5E9C06 ? 720FF4 ? 0 ?

A caveat to what is said above is Oradebug captured call stacks. Oradebug is the RDBMS's
debugging framework. Oradebug allows for one process to execute commands in the context of
another process. The way remote oradebug commands are implemented on unix is that the
command issuer signals the process being debugged a SIGUSR2 signal and inside the signal
handler the debugged process performs the requested dump. sspuser() is the oracle signal
handler for SIGUSR2. Therefore when analyzing stack dumps ignore the sspuser() frame and
every routine called by sspuser(). In the example above the routine the session was executing
when it received the oradebug dump command was semtimedop().

The short stack output is similar to the normal stack output except that the symbol "<-" in the
context "x() <- y()" means that function y() called function x(). In the example below the routine
the process was executing when it received the short stack command was semtimedop().
Furthermore, sskgpwwait() called semtimedop(), skgpwwait() called sskgpwwait(), and so on.

short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-semtimedop()

+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-kslwait()+703<-
kwqidexfcy()+3010<-kwqidsc80i()+1170<-kwqidrdq()+1092...

Analyzing Call Stacks of Hung Processes:

When you see that a process is hung with a particular call stack and would like to know why it is
stuck you need to determine which operation it is stuck in so you can contact the operation
owner. In order to do this you need to use the following steps:
 First leverage as many stack dumps as you can find to eliminate any functions that are
changing in the stack dumps you have collected. Analyze only the part of the stack that is
the same in all the stack dumps.
 Once you have isolated the static part of the stack you need to filter away the service
layer functions. A function is a service layer functions if it performs a basic service
requested by a calling layer. If you are unsure if a given function is a service layer
function or not go to the source code and look at the comments for the function. If the
function appears to be performing a basic task requested by the calling layer (i.e. get
lock) then the function is a service function. Common service layers are enqueues (ksq),
post-wait and latches (ksl), library cache pins and locks (kgl), and row cache locks (kqr).
 The first non-service layer function on the stack represents the current operation that the
process is stuck executing. Use "$ whodefs <function_name>" and "$ owner
<function_file_name>" to find the owner of the module declaring the function.
 A common mistake that people make is assigning hangs to owners of idle processes. If
you use the hang analysis dumps as detailed in the upcoming sections, the idle
processes will be automatically filtered out.

In the stack below the function that the process is currently executing is semtimedop(). The first
non-service layer in the stack representing the current operation is ktatminextsz().

Short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-semtimedop()

+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-kqrget()+947<-

Page 4 of 32
kqrLockAndPinPo()+364<-kqrpre1()+819<-kqrpre()+57<-ktatminextsz()+52<-
qerhjComputeFanoutAndBPS.()+195<-kkejnc()+6664<-kkojnp()+21310<-kkocnp()+232<-kkooqb()

$ whodefs ktatminextsz
…/kta.c ktatminextsz
$ owner kta.c

Wait Events and Hang Analysis Dump Details:

Every wait that an oracle process can enter is demarcated with an Oracle wait event. There is a
text string that is associated with every wait event and serves as its name/text identifier. Waits
that represent one Oracle session waiting for another should ideally have a hang analysis
callback defined by the wait event owner. The hang analysis callback allows us to display the
blocker of an Oracle session in the hang analysis dump.

In the hang analysis output below the wait event name for the wait that process 23 is in is 'enq:
UL - contention'. Process 23 is blocked by process 25. Process 25 is also waiting with wait event
'enq: UL - contention'. Process 25 is blocked by process 24. Process 24 is waiting with wait event
'Streams AQ: waiting for messages in the queue'.

Oracle session identified by:

{
instance: 1 (aime3.aime3)
os id: 19804
process id: 23, oracle@stawn11 (TNS V1-V3)
session id: 92
session serial #: 7
}
is waiting for 'enq: UL - contention' with wait info:
{
p1: 'name|mode'=0x554c0004
p2: 'id'=0x4
p3: '0'=0x0
time in wait: 68 mins
timeout after: never
wait id: 136
blocking: 0 sessions
current sql: BEGIN [Link]; END;
short stack: ...
wait history: ...
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (aime3.aime3)
os id: 19808
process id: 25, oracle@stawn11 (TNS V1-V3)
session id: 89
session serial #: 1
}
which is waiting for 'enq: UL - contention' with wait info:
{
p1: 'name|mode'=0x554c0006
p2: 'id'=0x3
p3: '0'=0x0
time in wait: 68 mins
timeout after: never
wait id: 151
blocking: 1 session
current sql: BEGIN [Link]; END;
short stack: ...
wait history: ...
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (aime3.aime3)

Page 5 of 32
 os id: 19806
process id: 24, oracle@stawn11 (TNS V1-V3)
session id: 93
session serial #: 8
}
which is waiting for 'Streams AQ: waiting for messages in the queue' with wait info:
{
p1: 'queue id'=0xeb75
p2: 'process#'=0x2a1da3b8
p3: 'wait time'=0x7fffffff
time in wait: 0.894231 secs
heur. time in wait: 83.118140 secs
timeout after: 9.105769 secs
wait id: 609
blocking: 2 sessions
current sql: BEGIN tkaq_navdeq('APP1_Q2DEF'); END;
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-
kslwait()+703<-kwqidexfcy()+3010<-kwqidsc80i()+1170<-kwqidrdq()+1092<-kwqidsfmp()+592<-
kwqidafm0()+5693<-kwqididqx()+5429<-kwqidxdeq0()+1924<-kwqidxdeq102.()+763<-kwqiadtdeq()
+795<-spefcmpa()+438<-spefmccallstd()+453<-pextproc()+183<-peftrusted()+170<-psdexsp()
+556<-rpiswu2.()+1186<-psdextp()+868<-pefccal()+580<-pefcal()+893<-pevm_FCAL.()+60<-
pfrinstr_FCAL()+76<-pfrrun_
wait history:
1. event: 'Streams AQ: waiting for messages in the queue'
wait id: 608 p1: 'queue id'=0xeb75
time waited: 2.197861 secs p2: 'process#'=0x2a1da3b8
p3: 'wait time'=0x7fffffff
2. event: 'Streams AQ: waiting for messages in the queue'
wait id: 607 p1: 'queue id'=0xeb75
time waited: 10.002149 secs p2: 'process#'=0x2a1da3b8
p3: 'wait time'=0x7fffffff
3. event: 'Streams AQ: waiting for messages in the queue'
wait id: 606 p1: 'queue id'=0xeb75
time waited: 10.003058 secs p2: 'process#'=0x2a1da3b8
p3: 'wait time'=0x7fffffff
}

Take a moment to familiarize yourself with the information exposed in the hang analysis output.
This output includes the current sql, short stack, current wait information, and wait history. With
regards to the current wait information see the "time in wait" and "timeout after" values for the
'enq: UL - contention' waits and the 'Streams AQ: waiting for messages in the queue' wait.

For both the 'enq: UL - contention' waits we see the "time in wait" as being 68 minutes with a
timeout value of "never". Indicating that the sessions are going to wait as long as it takes to get
the enqueue:

time in wait: 68 mins

timeout after: never

For the 'Streams AQ: waiting for messages in the queue' wait we see that the time in wait is a
small value. Furthermore there is also a field called "heuristic time in wait" which is a slightly
larger value. The "heuristic time in wait" is computed by using the heuristic that if the wait event,
wait parameter 1 (p1), wait parameter 2 (p2), and wait parameter 3 (p3) are the same for back-to-
back waits, then the wait is really for the same resource. Therefore the "heuristic time in wait" is
the time that the wait event, p1, p2, and p3 have been the same for back-to-back waits. This
heuristic was introduced since not all waits have switched to the 11gr1 wait API. With the old wait
API there was ambiguity if a wait was part of the same resource wait vs. if the resource wait
completed, the resource was released, and then the resource was requested for again.

time in wait: 0.894231 secs

heur. time in wait: 83.118140 secs
timeout after: 9.105769 secs

Page 6 of 32
Note that just because the time in wait is a small value it does not necessarily mean that the final
blocker is not stuck. The final blocking session can be performing different waits periodically but
still not make any progress.

Regarding the format of the hang analysis output, if you remove everything between the braces
the hang analysis output is structured like an English sentence. So the way you would read the
above output is as follows:

Oracle session identified by {}

is waiting for 'enq: UL - contention' with wait info {}
and is blocked by
=> Oracle session identified by {}
which is waiting for 'enq: UL - contention' with wait info {}
and is blocked by
=> Oracle session identified by {}
which is waiting for 'Streams AQ: waiting for messages in the queue' with wait info {}

Sometimes you may find an Oracle wait for which no hang analysis callback is defined and
therefore you need component specific knowledge to find the blocker. Or you may want more
information about why a process is in the wait that it is in. In these cases it may be helpful to
contact the owner of the code that used the wait event. Note that vastly different code paths can
use the same Oracle wait event when their Oracle session waits. There are two ways to find the
code owner of the code using the wait event in context of the hang you are investigating:

a) Look at the short stack for the first routine that calls a "kslw" prefixed function. This is the
wait API entry point prefix. In the example above the code owner that initiated the wait
"Streams AQ: waiting for messages in the queue" is kwqidexfcy since in the short stack
this was the first function that called a "kslw" prefixed function ("kslwait()+703<-
kwqidexfcy()+3010"). Using "$ whodefs kwqidexfcy" (or "$ whorefs kwqidexfcy" when
whodefs fails) we can see that this routine is declared in kwqid.c. So for more information
you could contact the owner of kwqid.c ("$ owner kwqid.c").

Under certain circumstances the wait event is passed as a parameter eventually to the
post-wait code-layer (the prefix of code in this layer is "ksl"). In these cases we want to
ask the top-level client that specified the wait what the wait means in their context.
Therefore its always good to investigate the actual code doing the wait to see if you need
to go a couple layers up the stack to find the real initiator of the wait. For example, code
in libgeneric that uses ksl invokes the ksl apis through callbacks defined in the "ksf" layer
(kgsf callbacks). Thus in this case you need to go to the invoker of ksf to find the code
path using a given wait event.

short stack: ksedsts()+286<-ksdxfstk()+48<-ksdxcb()+2452<-sspuser()+102<-

semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+145<-ksliwat()+1523<-kslwaitctx()
+97<-ksfwaitctx()+14<-kgllkal()+2707<-kglget()+1477

In the stack above kgllkal is routine that is initiating the wait.

b) You can also grep for the wait event declaration in the rdbms header files ("$ cd hdir")
and then do whorefs to see all the usages of it. Then you can contact the owner of the file
whose usage you are interested in. Note that method (a) is the preferred and fastest way
to contact the right owner.

$ cd hdir
$ grep -B 1 'Streams AQ: waiting for messages in the queue' *.h

kwqi.h-#define kwqiqw KSLEVTDN(kwqiqw_)

kwqi.h:KSLEVTDX3(kwqiqw_, "Streams AQ: waiting for messages in the queue",

$ whorefs kwqiqw

Page 7 of 32
For more information see ksl.h and kgslhng.h.

Hang Analysis Dump Scope:

The hang analysis dump can be invoked either just on the current instance or cluster-wide using
the "-g" option. We detail later on how to find and distinguish the automatically collected hang
analysis dumps in the lrgs. When cluster-wide hang analysis output is available you should use
that instead of the per-instance hang analysis output.

Hang analysis cannot currently build a graph between multi-database clusters or between a
database and an ASM cluster (ASM is Oracle's storage manager). Therefore if a session in one
cluster is blocked on a session in another cluster you have to manually piece together the hang
analysis graphs. In 11gr2+ we intend to build cross-cluster graphs.

Furthermore, hang analysis graphs are currently only built for Oracle instances (database
instances or ASM instances). If you have a hang in CRS, OSS, etc. you are on your own for now.
In 11gr2+ we will start building the architecture to make cross-product graphs possible.

Lrg Hang Detection Architecture:

For a given lrg the results are stored in /net/aimerepos/results/<LRG_LABEL>/<lrg_id>. This

directory is the root directory that contains all information available to debug the lrg. Note that the
lrg results do not stay around forever (usually a week or two). Therefore if there is an old lrg that
you are investigating consider copying some of the results to your local machine.

All lrgs are run under an aime user, aimeX (where X is usually a number from 1-3). The usual
instance ORACLE_SID for non-ASM instances is aimeX[1-9] i.e. for user aime3 the
ORACLE_SID's of the non-ASM instances would be aime3, aime32, aime33, etc. For ASM
instances the usual ORACLE_SID is aimeX[11-19] i.e. for user aime3 the ORACLE_SID's of the
ASM instances would be aime311, aime312, aime313, etc. Since we collect diagnostics for all
instances you may see the same dumps repeated in our logs, but they are actually being done on
different instances. The oracle tracefiles are all prefixed with the ORACLE_SID
(<ORACLE_SID>_<proc_name>_<osid>.trc) so you can use that to help you distinguish on which
instance a dump was done.

The overall architecture for detecting and capturing diagnostic information for hangs in unix is
based on snoopy - $ADE_VIEW_ROOT/utl/snoopy. Snoopy is a perl script that monitors test
execution and decides whether or not a hang is happening. There are two primary ways in which
snoopy determines if an lrg is hung:
a) The test is not making progress for a duration greater than the hang limit. The oratst tlg
file is checked for updates to determine if progress is being made.
b) The test execution limit was exceeded.
The hang limit and test execution limit are parameters to snoopy (-h = hang limit in minutes and -
x = test execution limit in minutes). The defaults for these parameters can be modified by going
the lrg attributes db ([Link] -> LRG Attributes DB) and updating the
attributes snoopy_h and snoopy_x. Note that if you change the attributes you change them for all
future invocations of the lrg for all users. Therefore, please consult with the test owner prior to
making any changes to the lrg attribute db.

Once snoopy determines that a hang has been encountered it invokes oradump -
$ADE_VIEW_ROOT/utl/oradump. Oradump is a perl script that tries to gather as much diagnostic
information as possible. If there are additional diagnostics you would like to capture you can
update the oradump script (ask mkeihl for a code review ). It is good to read through the oradump
script contents at least once to get familiar with the various diagnostics collected. Below we
outline the most globally useful diagnostics collected.

Page 8 of 32
After encountering a hang in an lrg, oradump and snoopy snipe all processes spawned during the
current test so that we can continue to get coverage for the remainder of the tests in the lrg.
However, as can be expected, sniping processes creates miscellaneous diffs. When analyzing
the results do not be alarmed if there are additional diffs right after the "-- oradump called"
symptom.

Useful diagnostic information collected:

 snoopy
o [Link] : output from snoopy. Gives the reason why oradump was invoked.
Search for oradump in this file to find all the invocations of oradump.

If right above the oradump call in [Link] you see "elapsetime(xxx seconds) >
TimeLimit(xxxx seconds)" then your test has reached its test execution timelimit
and that is why oradump was invoked:

-- [Link]--
TLGLOOP: elapsetime(18006) > TimeLimit(18000)
Stopping test execution
Calling oradump, logfile /ade/aime1_stbcj03/oracle/work/[Link]...
Back from oradump

If right above the oradump call in [Link] you see "stuckclck(xxx seconds) >
HangLimit(xxx seconds)" then snoopy thinks your test is hung and has invoked
oradump.

-- [Link]--
TLGLOOP: stuckclck(3660) > HangLimit(3600)
ERR: Test execution believed to be hanging
ERR: Calling oradump, logfile /ade/aime3_stawn11/oracle/work/[Link],
at Mar 31 2007 13:24:02
ERR: Back from oradump

See comments at start of this section for more information on these two
conditions.
 oradump
o [Link] - contains output from the oradump script. Currently, if multiple
hangs are detected the oradump output goes to the same [Link] file.
There is a plan to split the output into separate files. Until then, you can look for
"oradump started" to see the line number at which the output of each oradump
started.

NOTE: Some diagnostics can fail to be captured because the state of the
instance or cluster prevented the diagnostic from being invoked (i.e. shutdown,
startup, severe hang prevented sessions from connecting, etc.). Additionally,
when oradump is invoked because the lrg execution time limit is hit, Oradump
does not freeze all processes to capture diagnostic information. It does a live
diagnostic dump. In this case instances can start or stop and processes can be
created and deleted since the test is not hung. Therefore, many diagnostics may
be missing because we may have tried to collect the diagnostics when the
instance was down or a targeted process had exited.

Key things to look for:

 tail of the test tlg file - this tells you why oratst is stuck; what it is waiting
for to complete.

In the example below oratst is waiting for 3 sqlplus sessions to complete:

> FORK Forking sqlf on Mar 31 2007 12:22:01
> FORK ENTRY = 19771 on Mar 31 2007 12:22:01

Page 9 of 32
 > FORK Forking sqlf on Mar 31 2007 12:22:06
> FORK ENTRY = 19789 on Mar 31 2007 12:22:06
> FORK Forking sqlf on Mar 31 2007 12:22:11
> FORK ENTRY = 19790 on Mar 31 2007 12:22:11
> WAIT Waiting on Mar 31 2007 12:22:16
> WAIT Waiting for 3 FORK(s) with WAIT option

 ps output - lists all currently running oracle processes for the aimeX user
that was running the lrg. The ps output is collected 3 times with 5
seconds of sleep between each collection. Note that the ps output has
two time columns. The first time column is the start time of the process.
The second time column represents the number of [hours]:[minutes]:
[seconds] of cpu time consumed by the process. The cpu time consumed
column is very useful for checking if a process is spinning.

show Oracle processes:

aime3 19690 1 0 12:21 ? 00:00:00 ora_pmon_aime3
aime3 19692 1 0 12:21 ? 00:00:00 ora_vktm_aime3
aime3 19694 1 0 12:21 ? 00:00:00 ora_diag_aime3
aime3 19696 1 0 12:21 ? 00:00:00 ora_dbrm_aime3
aime3 19698 1 0 12:21 ? 00:00:00 ora_psp0_aime3
aime3 19702 1 0 12:21 ? 00:00:00 ora_dia0_aime3
...
sleep for 5 seconds
aime3 19690 1 0 12:21 ? 00:00:00 ora_pmon_aime3
aime3 19692 1 0 12:21 ? 00:00:00 ora_vktm_aime3
aime3 19694 1 0 12:21 ? 00:00:00 ora_diag_aime3
aime3 19696 1 0 12:21 ? 00:00:00 ora_dbrm_aime3
aime3 19698 1 0 12:21 ? 00:00:00 ora_psp0_aime3
...
 top output - tells you if any processes on the machine were consuming
large amounts of cpu at the time that top was run. Since this contains
output from all users on the machine, you should primarily focus on
processes with the aimeX user name your lrg was run under.

show system info from the TOP command

top - 13:24:13 up 9:08, 0 users, load average: 1.04, 1.69, 2.10

Tasks: 237 total, 1 running, 236 sleeping, 0 stopped, 0
zombie
Cpu(s): 20.6% us, 8.1% sy, 0.0% ni, 40.0% id, 31.3% wa, 0.0% hi,
0.0% si
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+
COMMAND
8805 aime2 19 0 285m 15m 12m S 5.9 0.3 0:00.03 oracle

8692 aime2 16 0 285m 15m 12m S 2.0 0.3 0:00.06 oracle

…
19690 aime3 16 0 282m 19m 17m S 0.0 0.3 0:00.14
oracle
o oradump_<osid> - oradump invokes gdb/pstack three times on every oracle
process to capture multiple stack traces. There is a 5 second sleep between
each stack capture. The multiple stacks can help you distinguish processes that
are stuck from those that are making progress. The file named oradump_<osid>
contains the gdb/pstack stack traces.

example:
-- oradump_19806 --
Thread 1 (Thread -1211758912 (LWP 19806)):
#0 0x00a877a2 in _dl_sysinfo_int80 () from /lib/[Link].2
#1 0x00b6d274 in semtimedop () from /lib/tls/[Link].6
#2 0x0d0d6df8 in sskgpwwait ()
#3 0x0d0b7182 in skgpwwait ()
#4 0x0980d0f1 in ksliwat ()

Page 10 of 32
 #5 0x09802109 in kslwaitctx. ()
#6 0x09802503 in kslwait ()
#7 0x0c41fd82 in kwqidexfcy. ()
#8 0x0c411140 in kwqidsc80i ()
#9 0x0c40f052 in kwqidrdq ()
#10 0x0c4199f0 in kwqidsfmp ()
#11 0x0c41905f in kwqidafm0 ()

o Hang Analysis Dumps - Oradump invokes local hang analysis on every instance
and global hang analysis on every cluster. If the global hang analysis is available
you should use that instead of the local hang analysis output for members of that
cluster. To find the location of the hang analysis trace files search for "hang
analysis in" inside [Link]. The "-G all" indicates a cluster-wide hang
analysis:
-- [Link] --
SQL> oradebug hanganalyze 5
Hang Analysis in
/ade/aime2_stajw13/oracle/log/diag/asm/+asm/aime211/trace/aime211_ora_2152.
trc
SQL> oradebug hanganalyze 5
Hang Analysis in
/ade/aime2_stajw13/oracle/log/diag/asm/+asm/aime212/trace/aime212_ora_4008.
trc
SQL> oradebug -G all hanganalyze 1
Hang Analysis in
/ade/aime2_stajw13/oracle/log/diag/asm/+asm/aime211/trace/aime211_diag_1788
[Link]
Once you have found a trace file which contains the hang analysis output search
for " HANG ANALYSIS:" in the trace file to find the hang analysis result. The
hang analysis result will contain the names of the instances that were analyzed
for hangs:

*** 2007-01-18 15:56:48.256

==========================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): +asm.aime211, +asm.aime212
no oradebug node dumps
analysis initiated by oradebug
==========================================================================

NOTE: you can also explicitly search for the hang analysis from the lrg root
directory:
$ pwd
/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg8a3c
$ find . -name "*.trc" | xargs grep -A 1 'HANG ANALYSIS:'
./diag/.../aime3_ora_14213.trc:HANG ANALYSIS:
./diag/.../aime3_ora_14213.trc- instances (db_name.oracle_sid):
aime3.aime3

NOTE2: For our lrgs, we are in the process of changing the hang analysis dump
invocation mechanism to increase the situations under which we can collect hang
analysis dumps. Check future versions of this document for more info.

o System state dump - a system state dump is performed for each instance. This
contains the state object tree for every process along with some other instance
information (see ksudss). The system state dump is useful when hang analysis
does not have enough information because some layers have not written hang
analysis callbacks. Parsing the system state dump requires component specific
knowledge. See the "Component Specific Debugging Techniques" section for
more information.

Oradump tries both the sql way to capture the system state dump and also the
unsafe way of using gdb to attach to a process and then explicitly call ksudss. To

Page 11 of 32
 find the location of the SQL based system state dumps search for "dump
systemstate" and then the next oradebug command should output the trace file
name:
SQL> oradebug dump systemstate 11
Statement processed.
SQL> oradebug tracefile_name
/ade/aime2_stajw13/oracle/log/diag/asm/+asm/aime211/trace/aime211_ora_2152.
trc
SQL> oradebug dump systemstate 11
Statement processed.
SQL> oradebug tracefile_name
/ade/aime2_stajw13/oracle/log/diag/asm/+asm/aime212/trace/aime212_ora_4008.
trc
To locate the gdb invoked dumps search for " call ksudss_dbg after attaching".
This will contain the OSID of the process in which the system state dump was
performed. Use [Link] to find the trace file for the process by searching for
the osid:
using /usr/bin/gdb to call ksudss_dbg after attaching to RECO or DBW0 pid =
27118

NOTE: you can also explicitly search for the system state dumps from the lrg root
directory:
$ pwd
/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg8a3c
$ find . -name "*.trc" | xargs grep 'SYSTEM STATE '
./diag/.../aime3_ora_14213.trc:SYSTEM STATE (level=11, with short stacks)
./diag/.../aime3_reco_19714.trc:SYSTEM STATE (level=11, with short stacks)

 <lrg_name>.[Link] - Gives information on the CPU and IO resources consumed by

other tests executing on the same farm machine.
 [Link] - watson is a tool used to analyze oratst results. Its output is stored in
[Link]. This file gives a timeline of what happened before the hang so that you can
investigate the root cause. Hangs are identified in watson by the symptom " -- oradump
called". At the end of [Link] there are statistics. An important stat is the "lrg_runtime"
which is the duration the lrg took to complete:

-- [Link] --
SAT tkmain_8a3c.tlg 070331 12:17:34 OK tkaqmddl
U [Link] 070331 12:17:37 OK
SAT tkmain_8a3c.tlg 070331 12:21:42 OK tkaqmddl
U [Link] 070331 12:21:44 OK
HNG [Link] 070331 13:24:02 FAIL -- oradump called
DIF [Link] 070331 13:57:22 FAIL > ORA-03114: not connected to ORACLE
DIF [Link] 070331 13:57:22 FAIL > ORA-03114: not connected to ORACLE
DIF [Link] 070331 13:57:22 FAIL > ORA-03114: not connected to ORACLE
RUN tkmain_8a3c.tlg 070331 13:57:24 OK completed
SUM run_complete 070331 13:57:44 OK YES
SUM seeddb 070331 13:57:44 OK YES
SUM db_create 070331 13:57:44 OK 0
SUM lrg_runtime 070331 13:57:44 OK 3 hr 17 mins
SUM avg_runtime 070331 13:57:44 OK 312 sec
SUM tests_run 070331 13:57:44 OK 38
SUM difs 070331 13:57:44 OK 3
SUM sucs 070331 13:57:44 OK 35
SUM oradumps 070331 13:57:44 OK 1
SUM total_trc 070331 13:57:44 OK 0

 [Link] - contains the time sorted names of all interesting files created during the lrg
run. This is a super-set of the files that are actually copied. If there are processes that
you are investigating you can usually find the trace file location for that process by
searching for *_<osid>.trc inside [Link]. Oradump tries to dump the "errorstack"
dump at level 3 in every process, therefore the trace file will usually contain some
diagnostic information.

Page 12 of 32
 4357 Mar 31 13:24:25 oradump_19804
5737 Mar 31 13:24:40 oradump_19806
...
3023279 Mar 31 13:39:11 diag/rdbms/aime3/aime3/trace/aime3_ora_19804.trc
3096242 Mar 31 13:39:10 diag/rdbms/aime3/aime3/trace/aime3_ora_19806.trc

Summary of places to find process stack dumps for processes alive at hang detection time:
 <oradump>_<osid> - contains up to 3 stack dumps generated by Oradump's gdb/pstack
stack dumps
 per-process trace file *_<osid>.trc - there will be a stack dump in this file and it is
generated by Oradump's oradebug "errorstack dump" invocation
 hang analysis dump and system state dump trace files - short stacks are dumped during
these dumps

Page 13 of 32
Determining the Root Cause of the Hang (Step-by-Step Method):

The approach below is a systematic approach to analyzing hangs in the lrgs. As you become
more comfortable with analyzing hangs you'll probably create your own method for optimally
triaging hangs. You should read this section once and then go to the examples section.

Note that when you triage a bug or lrg it would be nice to jot-down your walk-through of this
checklist (or your checklist). This will help the new owner understand why you made the
conclusions you made. The example section contains my walk-through of the hangs I triaged. If
you explain your bug or lrg triaging similarly, I'm sure that the new owner of the bug/lrg will be
highly appreciative.

First, without getting into specifics, we'll outline the lrg-hang triaging checklist. After that we'll
detail how to apply the checklist in a step-by-step manner.

The Checklist:

1. Oradump was invoked because the lrg execution time limit was exceeded

a. There may have been unexpected errors that caused the lrg execution time to
increase
b. A new txn may have introduced a significant performance regression
c. New tests may have been added to the lrg causing the execution time to
increase
d. A bug in an Oracle background may have caused the background to consume
excessive CPU resources thus starving the foreground(s)
e. Excessive machine load may have caused the lrg to exceed its time limit

2. Oradump was invoked because snoopy thought the current test was hung

a. Oratst is waiting for something other than sqlplus / oci clients

b. Orast is waiting for sqlplus / oci clients

i. The foreground(s) could be spinning

ii. The foreground(s) could be making slow progress

1. A new txn could have introduced a performance regression in
one of the operations that the test executes
2. The operation being executed by the foreground(s) may be a
long operation
3. A bug in an Oracle background may have caused the
background to consume excessive CPU resources thus starving
the foreground(s)
4. Excessive machine load may have made your operation take
longer than expected

iii. The foreground(s) could be stuck

1. A prior issue in the test may cause the foreground(s) to hang /
infinitely wait
2. The foreground(s) could be blocked waiting for other processes
or could be incorrectly waiting due to a bug in the oracle code
(i.e. hand shaking / protocol failure).

Page 14 of 32
Applying the Checklist:

You have an lrg with the symptom "-- oradump called". The first thing to do is to open up
[Link]. As described earlier, search the [Link] file for "oradump" to determine why the
hang was detected. If the oradump you are triaging was caused by the lrg execution time limit
being exceeded you should see "elapsetime(xxx seconds) > TimeLimit(xxxx seconds)" in
[Link]. Otherwise oradump was invoked because snoopy though the current test was hung.

1. Oradump was invoked because the lrg execution time limit was exceeded: Lrgs can take
longer to execute for various reasons:

a. There may have been unexpected errors that caused the lrg execution time to
increase. Examine [Link] to see if there were any failures prior to the "--
oradump called" symptom. You can also scan the alert logs for unexpected
errors. Assign the lrg to the code owner that introduced the new errors.

b. A new txn may have introduced a significant performance regression. Check the
lrg execution time for labels before and after the label you're interested in. If after
a certain label the lrg runtime increases this may be the issue. The train is being
enhanced to automatically identify transactions like these. You may be able to
spot the cause of the regression by looking at the call stacks of all interesting
processes and see if there is new code-path which is causing the regression.
Contact the test owner to get a better understanding of what the lrg is testing and
which txns could have affected the lrg.

c. New tests may have been added to the lrg causing the execution time to
increase. Contact the test owner to see if this is the case. The lrg execution time
limit may need to be bumped in the lrg attribute db.

d. A bug in an Oracle background may have caused the background to consume

excessive CPU resources thus starving the foreground(s). Check the top output
in [Link] for any Oracle sessions that are actively consuming cpu.
Furthermore check the ps output to see if a large amount of cpu time was
consumed by the suspected spinning background. In this case analyze the call
stack of the background to find the operation that the background is stuck in.
Assign the lrg to the owner of that operation.

e. Excessive machine load may have caused the lrg to exceed its time limit. Check
<lrg_name>.[Link] to see if there was CPU and IO contention due to multiple
tests being run on the same farm machine. Contact the test owner to see if the
lrg execution time limit needs to be bumped in the lrg attribute db.

2. Oradump was invoked because snoopy thought the current test was hung:
Check the tail of the tlg file in the [Link] output to determine if oratst is waiting for
sqlplus / oci clients or some other script / program (example provided earlier).

a. Oratst is waiting for something other than sqlplus / oci clients: Investigate why the
script or program is not completing.

b. Orast is waiting for sqlplus / oci clients: Jot down the OSIDS of the oracle processes
that are executing the sql (how to do this is detailed at the start of the document).
There are several possible reasons your foregrounds could not be making progress:

Page 15 of 32
 i. The foreground(s) could be spinning: Check the ps output for the total cpu time
consumed. If you determine that the foreground is consuming a large amount of
cpu, analyze the stacks in the oradump_<osid> file and the process trace file to
find the operation that is spinning. Assign the lrg to the owner of that operation.

ii. The foreground(s) could be making slow progress. For each foreground look at
the hang analysis dump to see the time spent in the current wait and also
examine the prior waits in the wait history to see if they are different from the
current wait. They key thing to verify is that the session is not stuck waiting for
the same thing. If the wait is changing then most likely the session is making
progress but slowly. You can also examine the call stacks captured in
oradump_<osid> and the process trace file to see if different code paths are
being executed. If you believe that slow progress is being made there are several
reasons why this could happen:

1. A new txn could have introduced a performance regression in one of the

operations that the test executes. You may be able to spot the cause of the
regression by looking at the call stacks for all interesting processes and see if
there is new code-path which is causing the regression. Contact the test
owner to get a better understanding of what the test is testing and which txns
could have affected the test.

2. The operation being executed by the foreground(s) may be a long operation.

In this case contact the test owner and see if increasing the hang limit in the
lrg attribute db is the right solution or if the operation can be changed to
reduce its runtime.

3. A bug in an Oracle background may have caused the background to

consume excessive CPU resources thus starving the foreground(s). Check
the top output in [Link] for any Oracle sessions that are actively
consuming cpu. Furthermore check the ps output to see if a large amount of
cpu time was consumed by the suspected spinning background. In this case
analyze the call stack of the background to find the operation that the
background is stuck in. Assign the lrg to the owner of that operation.

4. Excessive machine load may have made your operation take longer than
expected. Check <lrg_name>.[Link] to see if there was machine CPU
and IO resource contention due to multiple tests being run on the same farm
machine. Contact the test owner to see if the hang limit needs to be bumped
in the lrg attribute db.

iii. The foreground(s) could be stuck

1. A prior issue in the test may cause the foreground(s) to hang / infinitely wait
 look at the [Link] timeline to see what happened prior to the "--
oradump called" symptom. If a process that the foreground was waiting
to hand-shake with unexpectedly died then the foreground could be
stuck.
 also examine the alert log for the instance and the trace file of the
foreground prior to the hang to see if anything out of the ordinary
happened.

2. The foreground(s) could be blocked waiting for other processes or could be

incorrectly waiting due to a bug in the oracle code (i.e. hand shaking /
protocol failure).

Page 16 of 32
 Go to the hang analysis output and search for the OSID's of the
foreground(s). If a foreground is not in the hang analysis output then either
the foreground completed its task or the foreground is in an idle wait and is
not blocking anyone. If you do see the foreground in a hang analysis chain
then follow the chain to the final blocker.

Analyze the stack of the final blocker and the cpu consumption of the final
blocker (ps output in [Link]). If the final blocker appears stuck in an
operation talk to the operation owner to see if the operation should be taking
that long or if critical resources should be released while that operation is in
progress.

If the hang analysis callback has not been written for the wait event of the
final blocker than you can also contact the code owner of the code that used
the wait event (described at the start of the doc) to help you triage why a
session would be in the given wait event and how to determine the actual
blockers.

If you encounter a cyclical chain / deadlock, assign the deadlock to the owner
of the current operation of one of sessions in the deadlock. We are working
to improve the diagnostics for deadlocks. One of the long-term goals is to
output the resource description and acquisition call-stack for each conflicting
resource in the hang analysis output.

Component Specific Debugging Techniques

All components should make an effort to define hang analysis callbacks for all their involuntary
waits (see kgslhng.h for details). By defining hang analysis callbacks you enable the entire
development organization to easily triage hangs and you reduce the amount of time you spend
analyzing hangs.

However, in the interim, components that have not defined or fully implemented their hang
analysis callbacks can put in this section a link to documentation that describes how to determine
the blockers for sessions waiting in their component. Usually this involves parsing the system
state dump.

Available Documentation:
 Parallel Query (to be moved to a dbdev web page with more info soon):
You can use the following script, provided by [Link], on a trace file containing the
system state dump to follow PQ wait chains.

$ awk -f /net/dlsun945/private/pamor/bin/[Link] <system_state_dump.trc>

Example:
If you see a PQ wait like below in the hang analysis dump and ddl5_ora_7527.trc
contains a system state dump, invoke Patrick's script to get the slaves the coordinator is
waiting for:

=> Oracle session identified by:

{
instance: 1 (ddl5.ddl5)
os id: 2821
process id: 80, oracle@stbef04 (TNS V1-V3)
session id: 1547
session serial #: 19
}

Page 17 of 32
 which is waiting for 'PX Deq: Parse Reply' with wait info:

$ awk -f /net/dlsun945/private/pamor/bin/[Link] ddl5_ora_7527.trc > pq_dump.txt

-- pq_dump.txt --
PROCESS 80: (TNS V1-V3) pid 2821
waiting for 'PX Deq: Parse Reply'
Client: PQ
QCQ: 0x9943e304 (Serial 26625 Inc inc:) Number of qrefs: 2
QRef to Slave P112 (local): 0x99431258 (Serial 26625 Seq 6)
QRef to Slave P054 (local): 0x994313e8 (Serial 26625 Seq 6)
PS enq held (mode S) on slave 112 Instance 1
PS enq held (mode S) on slave 54 Instance 1
TX enq held (mode 0x0) 00180001-00000003

So process 80 (osid 2821) has two slaves: P112 on instance 1 and P054 on instance 1.
You can search for these slave process names in the hang analysis output to find out
what these slaves are waiting for. We are working to add hang analysis callbacks for PQ
so you can avoid doing this manual work.

Requested Documentation:
 kgx mutex waits

Example 1: Unresolved Deadlock

In this example we will walk through the steps required to triage lrg 2899181 on the
RDBMS_MAIN_LINUX_070330 label. In the lrg console we see "-- oradump called" therefore we
know a hang occurred and we start to triage the hang.

Checklist start - check [Link] for the reason why oradump was invoked:

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/[Link]:
TLGLOOP: stuckclck(7260) > HangLimit(7200)
ERR: Test execution believed to be hanging
ERR: Calling oradump, logfile /ade/aime3_stamg12/oracle/work/[Link], at Apr 2 2007
03:05:32
ERR: Back from oradump

According to [Link] oradump was invoked because the hang limit was exceeded. Therefore,
proceed to step 2.

Checklist 2 - check to see what the test is waiting for

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/[Link]:
> EXEC Executing T_SYSTEM:imp w/ 9 argument(s), Redirected error >>
T_WORK:[Link]
> EXECARGV /ade/aime3_stamg12/rdbms/bin/imp system/manager file=tkdrim2w
buffer=250000 ignore=y grants=y rows=y full=y destroy=y commit=y
> EXEC PID = 21850 on Apr 02 2007 01:03:24

The test in this case is waiting for the import command to finish. Therefore most likely some
oracle session is stuck. Proceed to Step 2.b

Checklist 2.b - identify the oracle foreground(s) and investigate them

In the ps output we search for "oracle…(LOCAL=…)"

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/[Link]:
show Oracle processes:
…
aime3 21840 1 0 01:03 ? 00:00:00 ora_qmnc_aime3

Page 18 of 32
aime3 21852 1 0 01:03 ? 00:00:15 oracleaime3 (DESCRIPTION=(LOCAL=YES)
(ADDRESS=(PROTOCOL=beq)))
aime3 21857 1 0 01:03 ? 00:00:00 ora_q000_aime3
aime3 21859 1 0 01:03 ? 00:00:00 ora_q001_aime3

In this case we see one foreground. Process 21852.

Checklist 2.b.i - check to see if the foreground is spinning.

From the ps output above we can see that the cpu time consumed by the foreground is only 15
seconds.

Checklist [Link] - check to see if the foreground is making slow progress.

The fastest and most accurate way to check this is to go the hang analysis output

First we search for "Hang Analysis in" inside [Link]. We see one such result.

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/[Link]:
SQL> oradebug hanganalyze 5
Cycle 1: (1/120)--(1/81)
Hang Analysis in
/ade/aime3_stamg12/oracle/log/diag/rdbms/aime3/aime3/trace/aime3_ora_2641.trc

Then we open up the trace file containing the hang analysis output and search for "HANG
ANALYSIS:".

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/diag/rdbms/aime3/aime3/trace/
aime3_ora_2641.trc
*** 2007-04-02 03:14:36.450
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): aime3.aime3
oradebug_node_dump_level: 5
analysis initiated by oradebug
===============================================================================

Chains most likely to have caused the hang:

[a] Chain 1 Signature: 'row cache lock'<='row cache lock' (cycle)
Chain 1 Signature Hash: 0x75bdd0c

===============================================================================
Cycles:

-------------------------------------------------------------------------------
Chain 1:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (aime3.aime3)
os id: 21921
process id: 29, oracle@stamg12 (J004)
session id: 81
session serial #: 1
}
is waiting for 'row cache lock' with wait info:
{
p1: 'cache id'=0x7
p2: 'mode'=0x0
p3: 'request'=0x3
time in wait: 129 mins
timeout after: never
wait id: 836
blocking: 1 session

Page 19 of 32
 current sql: select count(*) from user$ u, [Link]$schema s where [Link]#
= :1 and [Link] = [Link].schema_owner and
([Link]$Extname2Intname([Link].schema_url, [Link].schema_owner) = :2)
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-
kqrget()+947<-kqrLockAndPinPo()+364<-kqrpre1()+819<-kqrpre()+57<-qm_init_sga_pass2()
+8135<-qm_init_uga_helper()+5016<-qm_run_as_ksys()+202<-qm_init_uga()+19<-
qmeGetResRelByHdl()+1391<-qmtkLookupSchemaOIDPath.()+587<-qmtkLookupSchemaOID()+161<-
qmtsExtName2IntName()+955<-spefcpfa()+143<-spefmccallstd()+376<-pextproc()+183<-
peftrusted()+170<-psdexsp()+556<-rpiswu2.()+1186<
wait history:
1. event: 'db file sequential read'
wait id: 835 p1: 'file#'=0x1
time waited: 0.000045 secs p2: 'block#'=0xc863
p3: 'blocks'=0x1
2. event: 'db file sequential read'
wait id: 834 p1: 'file#'=0x1
time waited: 0.000039 secs p2: 'block#'=0xc862
p3: 'blocks'=0x1
3. event: 'db file sequential read'
wait id: 833 p1: 'file#'=0x1
time waited: 0.000040 secs p2: 'block#'=0xa999
p3: 'blocks'=0x1
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (aime3.aime3)
os id: 21852
process id: 16, oracle@stamg12 (TNS V1-V3)
session id: 120
session serial #: 9
}
which is waiting for 'row cache lock' with wait info:
{
p1: 'cache id'=0x7
p2: 'mode'=0x0
p3: 'request'=0x5
time in wait: 130 mins
timeout after: never
wait id: 2147
blocking: 1 session
current sql: <none>
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-
kqrget()+947<-kqrLockAndPinPo()+364<-kqrpre1()+819<-kqrpre()+57<-kzdugt.()+210<-kzppsr()
+1634<-gradrv()+2285<-opiexe()+14498<-opiosq0()+5394<-opiosq()+19<-opiodr()+1955<-ttcpip()
+2936<-opitsk()+3511<-opiino()+1397<-opiodr()+1955<-opidrv()+993<-sou2o()+113<-
opimai_real()+196<-ssthrdmain()+111<-main()+198<-__libc_start_main()+211
wait history:
1. event: 'latch: row cache objects'
wait id: 2148 p1: 'address'=0x2f331858
time waited: 0.000024 secs p2: 'number'=0xf9
p3: 'tries'=0x0
2. event: 'row cache lock'
wait id: 2147 p1: 'cache id'=0x7
time waited: 60.013879 secs p2: 'mode'=0x0
p3: 'request'=0x5
3. event: 'SQL*Net message from client'
wait id: 2146 p1: 'driver id'=0x62657100
time waited: 0.000160 secs p2: '#bytes'=0x1
}
and is blocked by the session at the start of the chain.

Chain 1 Signature: 'row cache lock'<='row cache lock' (cycle)

Chain 1 Signature Hash: 0x75bdd0c
-------------------------------------------------------------------------------

We search for OSID 21852 and see that this foreground process is in a deadlock cycle. We also
see that the "time in wait" for the foreground is 130 minutes.

Page 20 of 32
At this point it's clear that the foreground is stuck and not making any progress.

Checklist [Link].1 - check to see if a prior test issue could have cause the hang

We're only doing this for completeness, but under normal circumstances we would skip this step
since we already know the session is in a deadlock.

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrgrr12/[Link]:
U [Link] 070402 00:41:58 OK
SAT tkmain_rr12.tlg 070402 01:01:55 OK tkdrim2b
U [Link] 070402 01:03:02 OK
HNG [Link] 070402 03:05:32 FAIL -- oradump called

From the [Link] output we don't see any other issues prior to the oradump, therefore some
prior issue causing the hang seems remote.

Checklist [Link].2 - check to see if the foreground is blocked or incorrectly waiting

From the hang analysis output it is clear that the foreground encountered an unexpected
deadlock. From the short stacks we can see that the first non service layer routine of the process
with osid 21921 (J004) is qm_init_sga_pass2(). And the first non-service layer routine of the
foreground is kzdugt(). Therefore one of the owners of the files that declare these functions would
be the right person to assign the lrg to so that they can determine why the deadlock happened.

Side note: You may be concerned that this deadlock is not automatically resolved. In future labels
this type of deadlock is automatically resolved and an incident is created whenever this issue is
encountered.

Example 2: RAC Hang

For this example we will triage a hang seen in the RDBMS_MAIN_LINUX_070330 label in
lrg9h4b.

Checklist start - check [Link] for the reason why oradump was invoked:

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/[Link]:
TLGLOOP: stuckclck(7260) > HangLimit(7200)
ERR: Test execution believed to be hanging
ERR: Calling oradump, logfile /ade/aime2_stahi16/oracle/work/[Link], at Apr 1 2007
12:53:25
ERR: Back from oradump

According to [Link] oradump was invoked because the hang limit was exceeded. Therefore,
proceed to step 2.

Checklist 2 - check to see what the test is waiting for

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/[Link]:
> INST Macro expansion on Apr 01 2007 10:51:06
> MACROARGV INST 1
> INSTANCE New (global) instance name = `aime2'
instance 1, connect string
(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/ade/aime2_stahi16/oracle/bin/oracle)
(ARGV0=oracleaime2)(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))
(CONNECT_DATA=(SID=aime2))), sid is aime2
> INST Finished macro on Apr 01 2007 10:51:06
> FORK Forking sesqlf on Apr 01 2007 10:51:06
> FORK ENTRY = 27355 on Apr 01 2007 10:51:06
> FORK Forking sesqlf on Apr 01 2007 10:51:11
> FORK ENTRY = 27362 on Apr 01 2007 10:51:11

Page 21 of 32
> INST Macro expansion on Apr 01 2007 10:51:16
> MACROARGV INST 2
> INSTANCE New (global) instance name = `aime22'
instance 2, connect string
(DESCRIPTION=(ADDRESS=(PROTOCOL=beq)(PROGRAM=/ade/aime2_stahi16/oracle/bin/oracle)
(ARGV0=oracleaime22)(ARGS='(DESCRIPTION=(LOCAL=YES)(ADDRESS=(PROTOCOL=beq)))'))
(CONNECT_DATA=(SID=aime22))), sid is aime22
> INST Finished macro on Apr 01 2007 10:51:16
> FORK Forking sesqlf on Apr 01 2007 10:51:16
> FORK ENTRY = 27366 on Apr 01 2007 10:51:16
> FORK Forking sesqlf on Apr 01 2007 10:51:21
> FORK ENTRY = 27372 on Apr 01 2007 10:51:21
> WAIT Waiting on Apr 01 2007 10:51:26
> WAIT Waiting for 4 FORK(s) with WAIT option

It looks like the test is waiting for 4 sqlplus sessions to complete. Therefore most likely some
oracle session is stuck. Proceed to Step 2.b

Checklist 2.b - identify the oracle foreground(s) and investigate them

In the ps output we search for "oracle…(LOCAL=…)"

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/[Link]:
aime2 27263 1 0 10:50 ? 00:00:00 ora_q001_aime23
aime2 27320 1 0 10:50 ? 00:00:08 ora_cjq0_aime23
aime2 27384 1 0 10:51 ? 00:00:07 oracleaime2 (DESCRIPTION=(LOCAL=YES)
(ADDRESS=(PROTOCOL=beq)))
aime2 27386 1 0 10:51 ? 00:00:08 oracleaime22 (DESCRIPTION=(LOCAL=YES)
(ADDRESS=(PROTOCOL=beq)))
aime2 27388 1 0 10:51 ? 00:00:08 oracleaime22 (DESCRIPTION=(LOCAL=YES)
(ADDRESS=(PROTOCOL=beq)))
aime2 27390 1 0 10:51 ? 00:00:08 oracleaime2 (DESCRIPTION=(LOCAL=YES)
(ADDRESS=(PROTOCOL=beq)))

We have found the OSIDS for the 4 foregrounds: 27384, 27386, 27388, 27390. Note that two of
the foregrounds are on the instance with oracle SID "aime2" and the other two are on the
instance with oracle SID "aime22".

Checklist 2.b.i - check to see if the foreground is spinning.

From the ps output we can see that the maximum amount of cpu that each foreground consumed
was 8 seconds. Thus the foregrounds are not spinning.

Checklist [Link] - check to see if the foreground is making slow progress.

The fastest and most accurate way to check this is to go the hang analysis output

First we search for "Hang Analysis in" inside [Link]. We see a few results:

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/[Link]:
SQL> oradebug hanganalyze 5
Hang Analysis in
/ade/aime2_stahi16/oracle/log/diag/rdbms/aime2/aime2/trace/aime2_ora_28341.trc
...
SQL> oradebug hanganalyze 5
SQL> Hang Analysis in
/ade/aime2_stahi16/oracle/log/diag/rdbms/aime2/aime22/trace/aime22_ora_667.trc
...
SQL> oradebug hanganalyze 5
Hang Analysis in
/ade/aime2_stahi16/oracle/log/diag/rdbms/aime2/aime23/trace/aime23_ora_6118.trc
...
SQL> oradebug -G all hanganalyze 1
Hang Analysis in
/ade/aime2_stahi16/oracle/log/diag/rdbms/aime2/aime2/trace/aime2_diag_26797.trc

Page 22 of 32
...
SQL> oradebug -G all hanganalyze 5
Hang Analysis in
/ade/aime2_stahi16/oracle/log/diag/rdbms/aime2/aime2/trace/aime2_diag_26797.trc

Since the cluster-wide hang analysis dump (-G all) is always preferred over the local instance
hang analysis results we go to aime2_diag_26797 and search for "HANG ANALYSIS:".

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/diag/rdbms/aime2/aime2/trace/
aime2_diag_26797.trc:
*** 2007-04-01 13:41:09.688
===============================================================================
HANG ANALYSIS:
instances (db_name.oracle_sid): aime2.aime2, aime2.aime22, aime2.aime23
no oradebug node dumps
analysis initiated by oradebug
===============================================================================

===============================================================================
Non-intersecting chains:

-------------------------------------------------------------------------------
Chain 2:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 1 (aime2.aime2)
os id: 27384
process id: 33, oracle@stahi16 (TNS V1-V3)
session id: 80
session serial #: 14
}
is waiting for 'gc buffer busy acquire' with wait info:
{
p1: 'file#'=0x6
p2: 'block#'=0xcbe
p3: 'class#'=0x6
time in wait: 0.090221 secs
heur. time in wait: 40 mins
timeout after: 0.909779 secs
wait id: 14184
blocking: 0 sessions
current sql: table_e_a_eac6_3_0_0
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-
kcbzwb()+2960<-kcbgtcr()+17594<-ktsla_fsg_ctime()+477<-ktsl_get_retrange()+409<-
ktsla_init_cmap()+92<-ktsla_set_retcrit()+52<-ktsla_update_rlimit()+89<-
ktsla_fsb_best_fit_gsp()+266<-ktsla_fsb_gsp()+1173<-ktsla_fsg_gsp()+148<-ktsla_hbb_gsp()
+655<-ktsla_gsp_exact()+510<-ktsla_cfs_gsp()+261<-ktsla_cfsgsp_main()+147<-ktslagsp.()
+1974<-ktslagsp_main()+1634<-kdliAllocCache()+
wait history:
1. event: 'gc buffer busy acquire'
wait id: 14183 p1: 'file#'=0x6
time waited: 1.000669 secs p2: 'block#'=0xcbe
p3: 'class#'=0x6
2. event: 'gc buffer busy acquire'
wait id: 14182 p1: 'file#'=0x6
time waited: 1.001358 secs p2: 'block#'=0xcbe
p3: 'class#'=0x6
3. event: 'gc buffer busy acquire'
wait id: 14181 p1: 'file#'=0x6
time waited: 1.001297 secs p2: 'block#'=0xcbe
p3: 'class#'=0x6
}
and is blocked by
=> Oracle session identified by:
{
instance: 1 (aime2.aime2)
os id: 27390
process id: 34, oracle@stahi16 (TNS V1-V3)

Page 23 of 32
 session id: 77
session serial #: 4
}
which is waiting for 'gc current request' with wait info:
{
p1: 'file#'=0x6
p2: 'block#'=0xcbe
p3: 'id#'=0x2000006
time in wait: 0.328436 secs
heur. time in wait: 169 mins
timeout after: 0.921564 secs
wait id: 12358
blocking: 2 sessions
current sql: table_e_a_eac6_3_0_0
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
__poll()+61<-sskgxp_select()+189<-skgxpiwait()+1412<-skgxpwait()+563<-ksxpwait()+2108<-
ksliwat()+5380<-kslwaitctx()+97<-kslwait()+703<-ksxprcvimd()+6262<-kcllkopb()+18420<-
kclgrlk()+766<-kcbzib()+23161<-kcbgcur()+11837<-ktslgfs.()+272<-ktsla_fsg_gsp()+122<-
ktsla_hbb_gsp()+655<-ktsla_gsp_exact()+510<-ktsla_cfs_gsp()+261<-ktsla_cfsgsp_main()+147<-
ktslagsp.()+1974<-ktslagsp_main()+1634<-kdliAllocCache()+3192<-kdliAllocBlocks()+4053<-
kdliAllocChunks()+96<-k
wait history:
1. event: 'gc current request'
wait id: 12357 p1: 'file#'=0x6
time waited: 1.250798 secs p2: 'block#'=0xcbe
p3: 'id#'=0x2000006
2. event: 'gc current request'
wait id: 12356 p1: 'file#'=0x6
time waited: 1.251052 secs p2: 'block#'=0xcbe
p3: 'id#'=0x2000006
3. event: 'gc current request'
wait id: 12355 p1: 'file#'=0x6
time waited: 1.251005 secs p2: 'block#'=0xcbe
p3: 'id#'=0x2000006
}

Chain 2 Signature: 'gc current request'<='gc buffer busy acquire'

Chain 2 Signature Hash: 0x8823aa2a
-------------------------------------------------------------------------------

-------------------------------------------------------------------------------
Chain 3:
-------------------------------------------------------------------------------
Oracle session identified by:
{
instance: 2 (aime2.aime22)
os id: 27386
process id: 34, oracle@stahi16 (TNS V1-V3)
session id: 81
session serial #: 7
}
is waiting for 'gc buffer busy acquire' with wait info:
{
p1: 'file#'=0x6
p2: 'block#'=0xcbf
p3: 'class#'=0x6
time in wait: 0.249224 secs
heur. time in wait: 621.945928 secs
timeout after: 0.750776 secs
wait id: 15029
blocking: 0 sessions
current sql: table_e_a_eac6_3_0_0
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
semtimedop()+36<-sskgpwwait()+286<-skgpwwait()+142<-ksliwat()+1587<-kslwaitctx()+97<-
kcbzwb()+2960<-kcbgtcr()+17594<-ktsla_fsg_ctime()+477<-ktsl_get_retrange()+393<-
ktsla_init_cmap()+92<-ktsla_set_retcrit()+52<-ktsla_update_rlimit()+89<-
ktsla_fsb_best_fit_gsp()+266<-ktsla_fsb_gsp()+1173<-ktsla_fsg_gsp()+148<-ktsla_hbb_gsp()
+655<-ktsla_gsp_exact()+510<-ktsla_cfs_gsp()+261<-ktsla_cfsgsp_main()+147<-ktslagsp.()
+1974<-ktslagsp_main()+1634<-kdliAllocCache()+
wait history:
1. event: 'gc buffer busy acquire'

Page 24 of 32
 wait id: 15028 p1: 'file#'=0x6
time waited: 1.000971 secs p2: 'block#'=0xcbf
p3: 'class#'=0x6
2. event: 'gc buffer busy acquire'
wait id: 15027 p1: 'file#'=0x6
time waited: 1.001345 secs p2: 'block#'=0xcbf
p3: 'class#'=0x6
3. event: 'gc buffer busy acquire'
wait id: 15026 p1: 'file#'=0x6
time waited: 1.001359 secs p2: 'block#'=0xcbf
p3: 'class#'=0x6
}
and is blocked by
=> Oracle session identified by:
{
instance: 2 (aime2.aime22)
os id: 27388
process id: 33, oracle@stahi16 (TNS V1-V3)
session id: 84
session serial #: 13
}
which is waiting for 'gc current request' with wait info:
{
p1: 'file#'=0x6
p2: 'block#'=0xcbf
p3: 'id#'=0x2000006
time in wait: 0.522135 secs
heur. time in wait: 169 mins
timeout after: 0.727865 secs
wait id: 11798
blocking: 2 sessions
current sql: table_e_a_eac6_3_0_0
short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-
__poll()+61<-sskgxp_select()+189<-skgxpiwait()+1412<-skgxpwait()+563<-ksxpwait()+2108<-
ksliwat()+5380<-kslwaitctx()+97<-kslwait()+703<-ksxprcvimd()+6262<-kcllkopb()+18420<-
kclgrlk()+766<-kcbzib()+23161<-kcbgcur()+11837<-ktslgfs.()+272<-ktsla_fsg_gsp()+122<-
ktsla_hbb_gsp()+655<-ktsla_gsp_exact()+510<-ktsla_cfs_gsp()+261<-ktsla_cfsgsp_main()+147<-
ktslagsp.()+1974<-ktslagsp_main()+1634<-kdliAllocCache()+3192<-kdliAllocBlocks()+4053<-
kdliAllocChunks()+96<-k
wait history:
1. event: 'gc current request'
wait id: 11797 p1: 'file#'=0x6
time waited: 1.251261 secs p2: 'block#'=0xcbf
p3: 'id#'=0x2000006
2. event: 'gc current request'
wait id: 11796 p1: 'file#'=0x6
time waited: 1.251454 secs p2: 'block#'=0xcbf
p3: 'id#'=0x2000006
3. event: 'gc current request'
wait id: 11795 p1: 'file#'=0x6
time waited: 1.250861 secs p2: 'block#'=0xcbf
p3: 'id#'=0x2000006
}

Chain 3 Signature: 'gc current request'<='gc buffer busy acquire'

Chain 3 Signature Hash: 0x8823aa2a
-------------------------------------------------------------------------------

We investigate the chains for our foregrounds (osids 27384, 27386, 27388, 27390).

We see that process 27384 is blocked by process 27390 and that process 27386 is blocked by
process 27388. The heuristic time in wait for the blocking sessions is 169 minutes. This is a good
indicator that no progress is being made - the foreground(s) are stuck.

Checklist [Link].1 - check to see if a prior test issue could have cause the hang

/net/aimerepos/results/RDBMS_MAIN_LINUX_070330/lrg9h4b/[Link]:
TS [Link] 070401 10:47:37 OK

Page 25 of 32
U [Link] 070401 10:48:40 OK
U [Link] 070401 10:49:06 OK
U [Link] 070401 10:49:45 OK
HNG [Link] 070401 12:53:25 FAIL -- oradump called
SAT tkmain_9h4b.tlg 070401 13:47:15 OK tksgnllr1r
U [Link] 070401 13:47:26 OK

From [Link] we can see that there were no failures prior to the oradump. Therefore it is
unlikely that the hang was a downstream effect of a prior issue.

Checklist [Link].2 - check to see if the foreground is blocked or incorrectly waiting

From the hang analysis output it is clear that all four foregrounds are blocked. However no
blocking sessions were returned by the 'gc current requests' hang analysis callback.

$ grep 'gc current request' *.h

kcl2.h:KSLEVTDX3(kclevcur_, "gc current request",

kcl2.h:
/* GLOBAL CACHE WAIT EVENTS */
#define kclevcur KSLEVTDN(kclevcur_) /* current request */
KSLEVTDX3(kclevcur_, "gc current request",
"file#", "block#", "id#",
KSLEV_PLACEHOLDER, &kclevccbks, kslclsrac)

Therefore the best person to triage this would be the owner of the hang analysis callback -
kclevccbks.

/* wait event callbacks */

externdef const kgslevcbks kclevccbks = { kclhngcbk1 };

kclhngcbk1() is the hang analysis callback and it is declared in kcl.c.

Another way we could have triaged this was by contacting the owner of the user of the wait event.
In the short stack we see the following:

short stack: <-ksedsts()+286<-ksdxfstk()+22<-ksdxcb()+1560<-sspuser()+102<-__poll()+61<-

sskgxp_select()+189<-skgxpiwait()+1412<-skgxpwait()+563<-ksxpwait()+2108<-ksliwat()+5380<-
kslwaitctx()+97<-kslwait()+703<-ksxprcvimd()+6262<-kcllkopb()+18420<-kclgrlk()+766<-
kcbzib()+23161<-kcbgcur()+11837<-ktslgfs.()+272

In this case kcllkopb() is passing the wait event as a parameter to ksxprcvimd(). Therefore we
would contact the owner of kcllkopb() - kcl.c - and ask why a session could be stuck in the 'gc
current request' wait with no blockers.

What about Windows?

Windows currently has its own separate infrastructure / scripts for detecting and diagnosing lrg
hangs. The first noticeable difference is that in lrg console and [Link] the symptom that a
hang was detected is "-- process killed" (instead of "-- oradump called" on unix ports). The
windows hang detection and resolution infrastructure is driven by [Link]
(%ADE_VIEW_ROOT%\rdbms\utl\[Link]). The output of [Link] is in [Link]. [Link]
invokes [Link] to capture diagnostic information (on a hosted box: c:\ade\
packages\utl\[Link]). The output of this script is in [Link]. Note that
this means that files like "[Link]" do not exist in windows lrg results, and other files though
they have similar names have different content because different scripts are generating them.

When a hang is detected [Link] invokes various dumps. These dumps include the
local hang analysis and system state dump. Furthermore we also try to invoke the global hang
analysis dump on instances 1 and 11. To see if the Oracle instance dumps were successfully

Page 26 of 32
invoked and the trace file names for the location of the dumps look at
oradump<instance_number>.log. The Oracle instance dumps are generated by c:\ade\packages\
utl\[Link] and c:\ade\packages\utl\oradump_rac.sql.

In the example below the local hang analysis dump and system state dump for instance 2 are
located in the "aime12_diag_612.trc" trace file:

-- [Link] --
[05/26/07 05:23:58] timedStart launching process "sqlplus" "-prelim" "/nolog" "@C:\ADE\
packages\utl\[Link]" "inst2_local"

SQL> connect /@&1 as sysdba

Prelim connection established
SQL>
SQL> -- execute commands in 11gr1 in diag
SQL> oradebug setorapname diag
Oracle pid: 4, Windows thread id: 612, image: [Link] (DIAG)
SQL>
SQL> -- execute local hang analysis and dump the system state dump
SQL> oradebug tracefile_name
c:\ade\aime1_vw\oracle\work\diag\rdbms\aime1b\aime12\trace\aime12_diag_612.trc
SQL> oradebug dump hanganalyze 1
Statement processed.
SQL> oradebug dump systemstate 11;
Statement processed.
SQL>
SQL> exit

A useful utility on windows that doesn't exist on linux currently is ostack. Ostack periodically
captures stack dumps and cpu usage information of all threads in all oracle instances. There are
different versions of the ostack output. The most commonly used output format is in
ostack.<oracle_sid>.log. Within a single ostack.<oracle_sid>.log file are multiple snapshots of the
Oracle instance over time. Later snapshots are always appended so the snapshots appear in
time order within the file. To see when a given snapshot was collected look for 'timedStart
launching process'. Its usually best to look at the ostack snapshots right before the '-- process
killed' symptom generation time in [Link].

In the example below there are two ostack captures at times 8:48 and 9:10 for the instance with
oracle_sid aime1.

-- [Link] --
[05/14/07 08:48:34] timedStart launching process "C:/ADE/aime1_vw/rdbms/utl/[Link]"
"-s" "aime1"
**** Thread CPU usage statistics ****
tid user time kernel time elapsed time
------- ----------- ----------- ------------
1840 [C:\A] 0:00:00.000 0:00:00.093 0:06:11.421
3296 [Orac] 0:00:00.015 0:00:00.015 0:06:11.312
4532 0:00:00.000 0:00:00.000 0:06:11.312
4964 [PMON] 0:00:00.031 0:00:00.000 0:04:09.421
3468 [VKTM] 0:00:00.000 0:00:00.015 0:04:09.390
...
**** Thread stack dump ****
tid[5100] [PMON]
-----------------
- KiFastSystemCallRet+0 00000002 096EC378 00000000 00000BB8
sntevaque+36 096EC214 00000BB8 096CDC68 00000008
ntevque+239 096EC214 00000BB8 096CDC68 00000000
nsevwait+11dd 096EB388 001FE7B8 001FE7BC 00000000
ksnwait+68 00000BB8 00000030 00000000 2F456B10
ksliwat+576 2FC1E110 2FC1E110 0000012C 001EF550
kslwaitctx+6c 096CDF44 0000012C 096D7A59 000000EF
kslwait+244 0000012C 00000001 00000000 0000012C
ksuclnwt+8e 0000012C 00000002 00000077 00079E5A
ksucln+51f 05B39910 30303135 00000000 00000000
...

Page 27 of 32
[05/14/07 09:10:00] timedStart launching process "C:/ADE/aime1_vw/rdbms/utl/[Link]"
"-s" "aime1"
**** Thread CPU usage statistics ****
tid user time kernel time elapsed time
------- ----------- ----------- ------------
2180 [C:\A] 0:00:00.015 0:00:00.046 0:11:43.905
3880 [Orac] 0:00:00.015 0:00:00.015 0:11:43.796
4600 0:00:00.000 0:00:00.000 0:11:43.780
5100 [PMON] 0:00:00.031 0:00:00.031 0:11:17.233
3624 [VKTM] 0:00:00.000 0:00:00.000 0:11:17.202

Note that due to some complexities with NT critical sections, short stack captures in the system
state dump and hang analysis dump are disabled by default in our tests (i.e. event 10998 is not
set in the [Link]'s of our tests). Until we fix these issues you can use ostack's periodic stack
captures to get the stacks of hung processes.

In the future the plan is to unify the windows and unix hang diagnostic infrastructure (see the
enhancements requests section). Until then you have to map the techniques described in this
document to windows as best as you can.

Still Can't Debug the Hang?

You've read this document and still cannot triage your hang? In this case the right person to
contact is the owner and backup of the lrg suite that is failing (i.e. "$ owner tkmain_9o2.tsc"). One
of these people is usually a member of the testing organization and they have a lot of expertise
with debugging hangs in areas that they own.

In certain rare circumstances some groups do not have people in the testing team that own their
lrg suites. In this case the individual test that is failing should itself have an owner that you can
contact.

Debugging Hangs Outside of the Lrgs

This section assumes that you have read all the previous sections in this document. We detail
how you can map and apply the lrg-specific hang triaging techniques to debug hangs outside of
the lrgs.

Section Contents:
 Collecting Diagnostic Information
o Collecting Required Hang Diagnostic Dumps
 Dump Levels and Events that Influence the Dumps
 Collecting Dumps from Systems with Normal Sqlplus Connections
 Collecting Dumps from Systems you are UNABLE to Connect Normally
o Collecting Hang Diagnostics via V$ Views
 Applying the Step-by-step Method

Collecting Diagnostic Information:

One way to collect diagnostic information if you are in an ADE view is to invoke "oradump". This
should automatically collect most of the critical information to debug a hang.

$ADE_VIEW_ROOT/utl/oradump:
# oradump [testname] [kill]
#
# if testname is specified, the tail of .tlg file is dumped
# if kill option is specified the server processes are killed

You can also explicitly collect the required diagnostic information. The rest of this section will
detail how to accomplish this. Note that some of the commands below are not safe because

Page 28 of 32
remote Oradebug commands can cause process death or instance hangs. Whenever that is the
case we will explicitly warn you with "WARNING: REMOTE ORADEBUG COMMANDS ARE
UNSAFE".

 Collecting Required Hang Diagnostic Dumps:

To effectively triage a hang you need at least the following info

1. on all machines running Oracle execute
$ ps -elf > hang_ps_<machine>.txt
$ top -b -n 1 > hang_top_<machine>.txt
2. alert logs for all instances
3. hang analysis and system state dumps

Since there are various options you can chose when collecting the hang analysis and
system state output we will walk you through the commonly used options:

o Dump Levels and Events that Influence the Dumps:

For the hang analysis dump, the level parameter controls whether or not to issue
remote oradebug commands to capture additional per-process diagnostic
information (detailed error stack, pga state, etc.). In this case the output of the
dump is contained in the per-process trace file. The per-instance "HANG
ANALYSIS DUMPS:" section will indicate which processes were dumped and
their trace file names.

Commonly used hang analysis dump levels:

* level 1 : no oradebug per-process dumps. The examples below all use level 1.
* level 5 : perform a process diagnostic dump in all possibly interesting process.
WARNING: REMOTE ORADEBUG COMMANDS ARE UNSAFE.
* Note: We are in the process of exposing a level that forces short-stack dumps.
Please check the next version of this document for details.

For the system state dump we usually want to maximize the information collected
so that developers can determine the root cause.

Commonly used system state dump levels:

* level 11 : dump all psos and their children along with other useful dumps
* level + 256 (i.e. 11 + 256 = 267) : adding 256 to the level forces Oradebug short
stack collection so that you see the short-stack in the system state dump per
process. WARNING: REMOTE ORADEBUG COMMANDS ARE UNSAFE.

For both the hang analysis dump and the system state dump you can set an
event, 10998, so that any hang analysis or system state dump issued (manually
or automatically) contains the short stack per-process. We recommend that if you
are conducting non-lrg internal tests that you always set this event. Of-course to
collect the short-stack remote oradebug commands are issued. WARNING:
REMOTE ORADEBUG COMMANDS ARE UNSAFE.

set this event in the [Link] for each instance:

event="10998 trace name context forever, level 1" # dump short stacks

or dynamically via SQL in each instance:

SQL> alter system set events '10998 trace name context forever, level 1';

o Collecting Dumps from Systems with Normal Sqlplus Connections:

If you have no problems connecting to the instance then use the following steps

Page 29 of 32
 to collect the hang analysis and system state dumps.

 For each non-RAC instance:

$ sqplus "/ as sysdba"

SQL> alter system set events '10998 trace name context forever,
level 1';
SQL> oradebug hanganalyze 1
[ outputs foreground trace file name ]
SQL> oradebug setmypid
SQL> oradebug dump systemstate 267

Both dumps will be located in the foreground trace file.

 For each RAC cluster do the following commands on one instance in

each cluster:

$ sqplus "/ as sysdba"

SQL> alter system set events '10998 trace name context forever,
level 1';
SQL> oradebug -g all hanganalyze 1
[ outputs local diag trace file name ]
SQL> oradebug -g all dump systemstate 267

The cluster-wide hang analysis dump will be in the local diag trace file.
The per-instance system state dump will be in the diag trace file for each
instance.

o Collecting Dumps from Systems you are UNABLE to Connect Normally:

Sometimes even connecting to the instance can hang. In this case there is a
slightly unsafe (uses remote Oradebug commands) but useful mechanism to
collect diagnostic dumps. WARNING: REMOTE ORADEBUG COMMANDS ARE
UNSAFE. This mechanism leverages prelim connections. Prelim connections
create an authenticated foreground that just attaches to the SGA. This is enough
to execute Oradebug commands. At the same time, since no process state
object, session state object, etc. are created, you are guaranteed to be able to
connect to the hung instance.

 For each non-RAC instance:

$ sqlplus /nolog
SQL> set _prelim on
SQL> connect / as sysdba
SQL> oradebug setorapname diag
SQL> oradebug dump hanganalyze 1
SQL> oradebug dump systemstate 267
SQL> oradebug tracefile_name

The dumps will be located in the local diag trace file.

 For each RAC cluster do the following commands on one instance in

each cluster:

$ sqlplus /nolog
SQL> set _prelim on
SQL> connect / as sysdba
NOTE: we specify the reco process next, not diag, since we will use reco
to message diag to do the global hang analysis and system state dumps
SQL> oradebug setorapname reco
SQL> oradebug dump hanganalyze_global 1

Page 30 of 32
 SQL> oradebug dump systemstate_global 267
SQL> oradebug setorapname diag
SQL> oradebug tracefile_name

The cluster-wide hang analysis dump will be in the local diag trace file.
The per-instance system state dump will be in the diag trace file for each
instance.

 Collecting Hang Diagnostics via V$ Views:

Check the next version of this document for details on v$wait_chains and the internal
view gv$process_short_stack.

Applying the Step-by-step Method:

You should be able to use the lrg-hang triaging checklist starting at checklist item 2.b to help you
triage hangs outside of the lrgs. The mapping should be straightforward. Please send me an
email if it isn't and I can add more to this section.

Enhancement Requests:

This section will be used to track all pending enhancement requests. If the contact info for an
enhancement request is known please jot it down.

1. unify windows and unix hang detection and diagnostic scripts

contact(s): [Link]
2. have a summary of all the important dumps collected and the trace file containing them at
the start of [Link]
3. distinguish oradumps invoked because the test time limit was reached from oradumps
invoked because a hang was detected by annotating the watson symptom abstract.
contact(s): [Link]
4. if there is more than one oradump prior to the test time limit being exceeded, do not
bother doing an oradump for the test time limit exceeded condition - just terminate the
test.
contact(s): [Link]
5. generate a separate [Link] for each hang encountered
contact(s): [Link] - will be done as part of the next item
6. make farm showdiffs and the train hang aware
contact(s): [Link], [Link]
7. output the most interesting hang analysis chain signatures in [Link] and upload them
to the lrg db so that we can easily identify similar hangs. The chain signatures are
currently available in the hang analysis output but not visible in watson or the lrg console.
contact(s): [Link], [Link], [Link]
8. automatically resolve deadlocks - Some components have their own deadlock resolution
mechanism. For those that don't and also for inter-component deadlock resolution a new
project went into 11gr1 to resolve deadlocks for selected validated components.
Validation of a component involves using the new 11gr1 wait API and having a correctly
implemented hang analysis callback. If you are encountering frequent deadlocks that are
not being automatically resolved please contact me with the hang analysis output, system
state dump, and a clear description of the deadlock. We can work with the component
owners to get these deadlocks automatically resolved. Note that even if an unexpected
deadlock is automatically resolved, the operations that deadlock still need to be fixed to
avoid the deadlock. This is because we do not want to get into a situation where no
operations complete because they continuously deadlock with other operations. The goal
of this project is maximize customer uptime and it has the side benefit of improving the

Page 31 of 32
 utilization of farm machines.
contact(s): [Link]
9. automatically resolve hangs - We sometimes encounter situations where a process is
hung and therefore preventing the test or the instance from making progress. We have
many plans for handling this in 11gr2. A somewhat old brain-dump is located here
[Link] The key challenge is
distinguishing between long running operations and hung operations.
primary contact(s): [Link], [Link], [Link]
10. oradebug -g all hanganalyze 10;
oradebug dump systemstate 267;

Page 32 of 32