I’m getting myself tied in knots trying to debug a sporadic, yet bothersome
issue. The system slows/hangs with lots of ‘DFS lock handle’ waits. My
understanding (lots of which comes from Riyaj’s article
https://orainternals.wordpress.com/2011/11/08/troubleshooting-dfs-lock-handle-waits/)
is that this wait event waits for the lock handle of a *global* lock
request. There are a number of different global resources it might be
trying to obtain (determined from p1 parameter). In our case we are waiting
for a CI enqueue (id1=10, id2=5), trying to obtain it in Exclusive mode. A
CI enqueue, a Cross Instance call, is “used to invoke specific actions in
background processes”. So, if our waiting process needs a background
process (local or remote) to do work for it, it uses a CI enqueue (the
background process holds the enqueue until the work is done. Our process
knows the work is done when its DFS wait no longer waits for the CI
resource).
We can also find out more about the CI resource from id1 and id2. This data
is fairly limited and this is where I start to lose it. In our case id1=10,
which the docs show is ‘Create Remote parallel query Server’, and id2 = 5
which is ‘Used to queue up interested clients’. The meaning of id2=5 makes
it sound like I am queued up trying to do some real work with another
enqueue with another id2 value. (I’ll post other id2 values in a second so
you can see what I mean.) What is odd, is its behavior is very different
from other enqueue waits with which I am familiar. Typically, three double
linked lists (owners, waiters, converters queue) hang off from the
requested resource. For the CI enqueue it looks like we hop from resource
to resource, from id2 to id2. So the process holding the CI enqueue
(id1=10, id2=5) is not the final blocker. We might actually want the CI enq
in id2=1, which is held by another process.
[Some values for id2
1 used to pass in parameters
2 used to invoke the function in backgroud process
3 used to indicate the foreground has not returned
4 mounted excl, use to allocate mechanism
5 used to queue up interested clients]
To summarize:
· A local process, waiting on ‘DFS lock handle’, needs a background
process to do work on local and/or remote nodes (e.g. a Query Coordinator
needs slave parallel processes)
· The background process is pinged (more on this to follow) telling
it to grab the CI enqueue with id1=10 (Create Remote parallel query Server),
id2=5 (Used to queue up interested clients). This tells a specific
background process what work needs to be done. Additional information
(including *lock pointer, resource pointer, and resource name)* can also be
sent via the message (ping) to the resource’s value block.
· While the background process works, it holds the CI enqueue for
which the (QC) process waits on the ‘DFS lock handle’ wait. It waits until
the background process completes its work and releases the lock. This is
how our process (QC in this case) knows the necessary work is complete and
it can continue.
My understanding is if a server process wants a lock on a CI resource, it
will contact a local GES process (e.g. LMD0) which will then message the
same process (LMD0) on the resource’s master node. The master will then
contact the owner and requester.
Messaging between the GES processes is done using Asynchronous System Traps
(AST), which act like an interrupt to the process. These can be either
asynchronous (AAST Acquisition AST) or blocking (BAST Blocking AST).
*Some more detail*. Oracle automatically produced some ProcessState Dumps
(I’m not sure what triggered it or what processes were dumped). Looking at
some of these, we see that the ‘ges process’ is a child of the process, not
of the session. Also, the ‘ges process’ has two ‘ges enqueues’ children.
Excerpts from the queues shown for the ‘ges process’ and the two ‘ges
enqueue’s are as follows:
ges process:
AST_Q:
PENDING_Q:
lp 0x1644b35440 gl KJUSERNL rl KJUSEREX rp 0x17bb7a82e0
[0xa][0x1],[CI][ext 0x0,0x0]
*master 3 pid 29614* bast 0 rseq 1 mseq 0
history FREE > REF_RES > LOC_AST > FREE > REF_RES > GR2CVT
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
GRANTED_Q:
lp 0x1644b39f08 gl KJUSEREX rp 0x17b7ab6490 [0xa][0x5],[CI][ext 0x0,0x0]
*master 1 pid 29614* bast 0 rseq 19 mseq 0
history LOC_AST_FG > CLOSE > FREE > REF_RES > GR2CVT > LOC_AST_FG
open opt KJUSERPROCESS_OWNED
ges enqueues:
GRANTED_Q :
lp 0x1663ca0418 gl KJUSERPR rp 0x17bb7a82e0 [0xa][0x1],[CI][ext
0x0,0x0]
master 3 pid 3889 bast 0 rseq 1 mseq 0
history LOC_AST > LOC_AST > LOC_AST > LOC_AST > LOC_AST > LOC_AST
open opt KJUSERPROCESS_OWNED
CONVERT_Q:
lp 0x1644b35440 gl KJUSERNL rl KJUSEREX rp 0x17bb7a82e0
[0xa][0x1],[CI][ext 0x0,0x0]
master 3 pid 29614 bast 0 rseq 1 mseq 0
history FREE > REF_RES > LOC_AST > FREE > REF_RES > GR2CVT
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
----------------------------------------
ges enqueues:
GRANTED_Q :
lp 0x1644b39f08 gl KJUSEREX rp 0x17b7ab6490 [0xa][0x5],[CI][ext
0x0,0x0]
master 1 pid 29614 bast 0 rseq 19 mseq 0
history LOC_AST_FG > CLOSE > FREE > REF_RES > GR2CVT > LOC_AST_FG
open opt KJUSERPROCESS_OWNED
CONVERT_Q:
lp 0x1644b3c900 gl KJUSERNL rl KJUSEREX rp 0x17b7ab6490
[0xa][0x5],[CI][ext 0x0,0x0]
master 1 pid 38233 bast 0 rseq 19 mseq 0
history REF_RES > LOC_AST > CLOSE > FREE > REF_RES > GR2CVT
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
lp 0x1644efbb60 gl KJUSERNL rl KJUSEREX rp 0x17b7ab6490
[0xa][0x5],[CI][ext 0x0,0x0]
master 1 pid 2898 bast 0 rseq 19 mseq 0
history REF_RES > LOC_AST > CLOSE > FREE > REF_RES > GR2CVT
convert opt KJUSERNODEADLOCKWAIT KJUSERNODEADLOCKBLOCK
So it looks like there is an additional queue (pending_q) and we are trying
to switch from one resource (id2=5) to another (id2=1). We are also going
from a pid on node 1 to the same pid number on node 3. But if pid is ospid
(as it seems to be from the State Dump header), how does that work? OS pids
are fairly arbitrary. Also, is there any way to get more data about the
apparent blocker (node 3; pid 3889) without a System State Dump?
One other question. Some of the ges enqueues convert_q entries have a
slightly different format. Instead of pid, it is owner, and bast 1. This
looks like it is BAST (message) related, but I’m not sure.
lp 0x12542ff100 gl KJUSERNL rl KJUSEREX rp 0x17b7ab6490
[0xa][0x5],[CI][ext 0x0,0x0]
master 1 *owner 3 bast 1* rseq 76 mseq 0x30004
history MSGSENT > GR2CVT > REM_AST > REM_BAST > MSGSENT > GR2CVT
convert opt KJUSERGETVALUE
Finally, the number of ‘DFS lock handle’ waits is growing faster than I can
explain. We go from 10’s to hundreds of thousands within an hour. No sql
statements execute at anywhere near that rate.
So now I have a few problems. It seems like the issue is most likely either
the background process at the head of the queues, or an issue with the
inter-process messaging (AST, BAST).
The major places I am getting stuck are:
1. What is at the head of the queue? From the ProcessStateDump it
looks like node 3; pid 3889.
a. Is there a way to confirm this?
b. Since this is an ospid how can I track it? (do I need a
SystemStateDump?)
c. I assume it is a background process at the front of the line. How
can I tell why it is stuck? What it is doing?
2. Could the issue be messaging (AST, BAST) and not process related?
How do I check?
3. How do I get any of this information? (using a SystemState Dump?
Is there another way?)
Any suggestions as to what is going on and how to best continue to
investigate this?
Thanks.
Henry
