Re: Unable to detect blocking session

  • From: Sandra Becker <sbecker6925@xxxxxxxxx>
  • To: Andy Sayer <andysayer@xxxxxxxxx>
  • Date: Thu, 22 Feb 2018 08:04:22 -0700

Andrew,

Thank you for the code and examples.  It's very close to what I came up
with yesterday, but adds some detail I was missing.  At any given time, we
can have over 400 sessions, so I've done filters as  you suggested.  We had
the diagnostics pack at one time, but not sure they renewed the license
this last time.  I'll have to check.

On Wed, Feb 21, 2018 at 3:42 PM, Andy Sayer <andysayer@xxxxxxxxx> wrote:

Have you purchased the diagnostics pack licence, if so you can do queries
against AWR views to see what was going on at the time.

Other than that, going forward, a query like the following will show you
all sessions as they are NOW:
select s.inst_id, s.sid||','||s.serial# sess,s.username, s.osuser
      ,s.sql_id, s.state, s.wait_class, s.event, s.wait_time_micro
      
,s.blocking_Session||nvl2(s.blocking_instance,'@'||s.blocking_instance,null)
blocked_By, s.final_blocking_session||nvl2(s.final_blocking_
instance,'@'||s.final_blocking_instance,null) final_blocked_by
from gv$session s
/

It's important to not get distracted by what you see, you're only looking
at an instantaneous snapshot. However, if there are some sessions that have
long wait_time_micro and a non-idle wait class and a non null blocked by
you might want to look into them.

If you have lots of sessions connected at any one time you'd probably want
to filter out only sessions that are on a non idle wait, or that have a
transaction:
where  s.wait_class <> 'Idle'
or     s.taddr is not null
Would do the trick.

As an example, on my home system (not RAC):

   INST_ID SESS       USERNAME             OSUSER
 SQL_ID        STATE               WAIT_CLASS           EVENT
            WAIT_TIME_MICRO BLOCKED_BY FINAL_BLOCKED_BY
---------- ---------- -------------------- ------------------------------
------------- ------------------- --------------------
------------------------------ --------------- ----------
--------------------
         1 62,63959   ANDY                 Andrew\Andy
4kfg0ccdj4vsv WAITING             Application          enq: TX - row lock
contention         13601869 79@1       79@1
         1 79,35243   ANDY                 Andrew\Andy
              WAITING             Idle                 SQL*Net message from
client           30337675

And I have all the necessary information to see who's blocking who, and
how long it's been going on for. (The sql is just a plain old update
statement, nothing fun).

I took a guess at other possible blocking scenarios. This is a stab in the
dark and is one of many possibilities (although this particular one doesn't
completely match your scenario): a session trying to recompile a procedure
that is being run by another session.

ANDY@pdb1>create or replace procedure do_waits
  2  is
  3  begin
  4  dbms_lock.sleep(1000);
  5  end;
  6  /

Procedure created.

ANDY@pdb1>exec do_waits

*New session:*
ANDY@pdb1>ed
Wrote file afiedt.buf

  1  create or replace procedure do_waits
  2  is
  3  begin
  4  dbms_lock.sleep(1000);
  5* end;
ANDY@pdb1>/

<hangs>

My query results:
   INST_ID SESS       USERNAME             OSUSER
 SQL_ID        STATE               WAIT_CLASS           EVENT
            WAIT_TIME_MICRO BLOCKED_BY FINAL_BLOCKED_BY
---------- ---------- -------------------- ------------------------------
------------- ------------------- --------------------
------------------------------ --------------- ----------
--------------------
         1 62,63959   ANDY                 Andrew\Andy
6d1an556t3g16 WAITING             Concurrency          library cache pin
                215770653 79@1       79@1

(although I can't see the blocking session here because it doesn't have a
transaction, I have the identifier for it so I can easily run a follow up
query like)
  1  select s.inst_id, s.sid||','||s.serial# sess,s.username, s.osuser
  2        ,s.sql_id, s.state, s.wait_class, s.event, s.wait_time_micro
  3        
,s.blocking_Session||nvl2(s.blocking_instance,'@'||s.blocking_instance,null)
blocked_By, s.final_blocking_session||nvl2(s.final_blocking_
instance,'@'||s.final_blocking_instance,null) final_blocked_by
  4  from gv$session s
  5  where  s.wait_class <> 'Idle'
  6  or     s.taddr is not null
  7* or     s.sid = 79
ANDY@pdb1>/

   INST_ID SESS       USERNAME             OSUSER
 SQL_ID        STATE               WAIT_CLASS           EVENT
            WAIT_TIME_MICRO BLOCKED_BY FINAL_BLOCKED_BY
---------- ---------- -------------------- ------------------------------
------------- ------------------- --------------------
------------------------------ --------------- ----------
--------------------
         1 62,63959   ANDY                 Andrew\Andy
6d1an556t3g16 WAITING             Concurrency          library cache pin
                273724936 79@1       79@1
         1 79,35243   ANDY                 Andrew\Andy
4bm91698ssbw8 WAITING             Idle                 PL/SQL lock timer
                284643372

When I ran your query, I got no results. I then reran the query to find
that I now have results, so I did a check. It takes some time for the
blocking to get registered by the gv$session_blockers view

ANDY@pdb1>get blockers
  1  select s.inst_id, s.sid||','||s.serial# sess,s.username, s.osuser
  2        ,s.sql_id, s.state, s.wait_class, s.event, s.wait_time_micro
  3        
,s.blocking_Session||nvl2(s.blocking_instance,'@'||s.blocking_instance,null)
blocked_By, s.final_blocking_session||nvl2(s.final_blocking_
instance,'@'||s.final_blocking_instance,null) final_blocked_by
  4  from gv$session s
  5  where  s.wait_class <> 'Idle'
  6  or     s.taddr is not null
  7  or     s.sid = 79;
  8* select * from gv$session_blockers;
  9  .
ANDY@pdb1>
ANDY@pdb1>@blockers

   INST_ID SESS       USERNAME             OSUSER
 SQL_ID        STATE               WAIT_CLASS           EVENT
            WAIT_TIME_MICRO BLOCKED_BY FINAL_BLOCKED_BY
---------- ---------- -------------------- ------------------------------
------------- ------------------- --------------------
------------------------------ --------------- ----------
--------------------
         1 25,14247   ANDY                 Andrew\Andy
6d1an556t3g16 WAITING             Concurrency          library cache pin
                  1506705 79@1
         1 79,35243   ANDY                 Andrew\Andy
4bm91698ssbw8 WAITING             Idle                 PL/SQL lock timer
                605400087


no rows selected

ANDY@pdb1>@blockers

   INST_ID SESS       USERNAME             OSUSER
 SQL_ID        STATE               WAIT_CLASS           EVENT
            WAIT_TIME_MICRO BLOCKED_BY FINAL_BLOCKED_BY
---------- ---------- -------------------- ------------------------------
------------- ------------------- --------------------
------------------------------ --------------- ----------
--------------------
         1 25,14247   ANDY                 Andrew\Andy
6d1an556t3g16 WAITING             Concurrency          library cache pin
                  4486987 79@1       79@1
         1 79,35243   ANDY                 Andrew\Andy
4bm91698ssbw8 WAITING             Idle                 PL/SQL lock timer
                608380369


   INST_ID        SID SESS_SERIAL#    WAIT_ID WAIT_EVENT WAIT_EVENT_TEXT
                                                BLOCKER_INSTANCE_ID
BLOCKER_SID BLOCKER_SESS_SERIAL#     CON_ID
---------- ---------- ------------ ---------- ----------
----------------------------------------------------------------
------------------- ----------- -------------------- ----------
         1         25        14247         47        342 library cache
pin                                                                  1
    79                35243          0

It's probably populated internally at the same time the final blocking
session info is calculated.
Of course, that doesn't quite explain why your issue wasn't seen by that
query a long time after the blocking was reported to have started - but it
should cast some doubt about the accuracy of the query you were using.

And just to confirm, because my wait was against library cache pin,
there's nothing in gv$lock so any query relying on that is not going to
find it. There are other situations that could cause similar issues, but
nothing will get past gv$session (unless the blocking is outside of the
database!)

Hope that helps,
Andrew


On Wed, 21 Feb 2018 at 21:11, Sandra Becker <sbecker6925@xxxxxxxxx> wrote:

Andrew,

Unfortunately, the query they ran didn't show the blocking session and
instance.  What is being asked for is to show the root blocker and all
sessions it is currently blocking.  Still trying to work that one out.  All
good suggestions, though, that should get us going in the right direction.

Our applications are not properly instrumented and that isn't likely to
happen given that the current direction and directives for development.



On Wed, Feb 21, 2018 at 1:46 PM, Andy Sayer <andysayer@xxxxxxxxx> wrote:

Hi Sandra,

You say you only found the sql*plus session because it was listed as
idle in gv$session, that sounds like a stab in the dark.

Do you still have the results and the query you did against gv$session,
the only things interesting would be inst_id, sid, event,blocking_session,
blocking_instance, status. From just those few columns you can see what is
waiting, on what and who they are waiting for.

Not only will this help when the waits are due to a session blocking
you, it will show you if there is some other event being waited on which
isn’t necessarily another session holding an enqueue. Once you do this you
will find that you don’t need to make guesses or work through a list of
typical situations - it tells you exactly what is going on, you might need
to google the event name but you will be in a 100x better position to fix
the problem.

Additionally, if your application is properly instrumented via
dbms_application_info, you can easily filter down to just the sessions you
know are important to find out what they’re doing.

I certainly wouldn’t bother with the script you shared previously,
especially as it didn’t help you in the exact circumstance it was designed
for.

Hope that helps,
Andrew

On Wed, 21 Feb 2018 at 20:07, Sandra Becker <sbecker6925@xxxxxxxxx>
wrote:

New information:  we didn't actually find the blocker using v$lock (or
gv$lock).  Someone finally looked at gv$session and saw that a sqlplus
session had been idle for over an hour during the timeframe the application
was experiencing issues.  We had a script, below, that we were using to
locate the root blocker since we have an application issue we're also
trying to resolve.  That script did NOT show the sqlplus session that
appeared to be the blocker.  We think that session was the blocker because
as soon as the user exited the session, everything cleared almost
immediately.  We're trying to figure out a script that will find the root
block, including sessions like this user's that ran an update statement,
but didn't actually update any rows and he didn't do a commit.  If someone
has any suggestions, we would definitely like to hear them.

*ROOT BLOCKER SCRIPT*

SELECT
        DISTINCT
        b.username||' - '||b.blocker_sid||','||b.block
er_sess_serial#||',@'||b.inst_id||' : '||b.sql_id blocker,
b.seconds_in_wait b_secs,
        w.username||' - '||w.sid||','||w.sess_serial#||',@'||w.inst_id||'
: '||w.sql_id waiter, w.seconds_in_wait w_secs
FROM (SELECT
        bb.blocker_sid,
        bb.blocker_sess_serial#,
        sb.inst_id,
        sb.username,
        sb.sql_id,
        sb.seconds_in_wait
      FROM gv$session_blockers bb
           JOIN gv$session sb
                ON bb.blocker_sid = sb.sid
                AND bb.blocker_sess_serial# = sb.serial#
     ) b
JOIN (SELECT
        bw.blocker_sid,
        bw.sid,
        bw.sess_serial#,
        sw.inst_id,
        sw.username,
        sw. sql_id,
        sw.seconds_in_wait
      FROM gv$session_blockers bw
           JOIN gv$session sw
                ON  bw.sid = sw.sid
                AND bw.inst_id = sw.inst_id
                AND bw.sess_serial# = sw.serial#
     ) w
        ON b.blocker_sid = w.blocker_sid
ORDER BY w.seconds_in_wait DESC
/

On Wed, Feb 21, 2018 at 12:14 PM, Powell, Mark <mark.powell2@xxxxxxx>
wrote:

Sandy, to add to what Rick's reply, the "SQL*Net message from client"
indicates to me the user made an update and failed to commit it.  I think
Rick provided valid possibilities for EM but for why you could not 
directly
query the information I think we would need to see what queries you used 
to
try to find the blocker though from your final remarks you did use GV$LOCK
and GV$SESSION plus sys.dbms_lock_allocated to find the blocker.  Could 
the
earlier attempt have been using the V$ version and so missed the blocker
since it was on another instance?  The sys.dbms_lock_allocated table would
not be necessary to find the blocking session though it would identify
which User Lock (UL) was involved if a UL was involved.



Mark Powell
Database Administration
(313) 592-5148


------------------------------
*From:* oracle-l-bounce@xxxxxxxxxxxxx <oracle-l-bounce@xxxxxxxxxxxxx>
on behalf of Sandra Becker <sbecker6925@xxxxxxxxx>
*Sent:* Wednesday, February 21, 2018 10:32:14 AM
*To:* oracle-l
*Subject:* Unable to detect blocking session


Oracle EE 12.1.0.2 on RHEL 5.11

We had a situation in our production environment yesterday where a
user had a sqlplus session had an uncommitted "zero row" update on a
table.  This kept the actual application from processing orders using that
same table.  The sqlplus session was initiated from SQL*Plus Release
11.1.0.6.0.  The wait event on the application session was holding a user
lock, which was apparently blocked, with a wait event of "SQL*Net message
from client".  Once the  user's sqlplus session was exited, all 
application
sessions resumed normal functions without any intervention.  The user who
issues the update is a tier1 support person, so we can't lock out their
access for such activites to prevent future occurrences.

What we are trying to understand is why we were unable to see that the
user's sqlplus session was blocking either through EM or through queries
looking at gv$session and gv$session_blockers.  We found the application
locks by joining  gv$lock, gv$session and sys.dbms_lock_allocated.  Any
ideas why we could see the blocking or suggestions on what we can look at
so we don't miss it again?


--
Sandy B.




--
Sandy B.




--
Sandy B.




-- 
Sandy B.

Other related posts: