Hi,
Did you check wait chain signatures from v$wait_chains or hanganalyze
dumps? These include background processes being signalled.
On Thu, 5 Nov 2020 at 23:32, Henry Poras <henry.poras@xxxxxxxxx> wrote:
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
