Quick notes about troubleshooting a blocker issue involving an insert

Called to help troubleshooting a production issue: an insert statemnt blocked many others. However, when I checked the database on 7:30 PM, the symptoms have gone.

In retrospective, the problem is most  likely due to a configuration issue in context of DMT. This database was upgraded to 10g a year ago from 8i. A few tablespaces is still dictionary-managed.


Here is the AWR "Top 5 Timed Events" during the problem period:

Top 5 Timed Events (18:30 -19:00)

Event Waits Time(s) Avg Wait(ms) % Total Call Time Wait Class

enq: TX - contention 44,494 130,783 2,939 59.7 Other
enq: ST - contention 27,122 79,719 2,939 36.4 Configuration
CPU time 3,700 1.7
read by other session 839,265 2,843 3 1.3 User I/O
db file scattered read 405,142 2,121 5 1.0 User I/O


From: http://www.saptechies.com/faq-oracle-enqueues/,  we can read some info about Oracle enqueue.


System enqueues:

ST (space transaction enqueue): This enqueue is held in dictionary-managed tablespaces within extent allocations and releases.

TYPE = ST

Very large numbers of extents are allocated or deallocated.


You can solve the problem permanently by using LMTS instead of DMTS (refer to Notes 214995 and 659946). If you use DMTS, you must ensure that the extents of temporary segments, tables and indexes are sufficiently big so that you can avoid large quantities of extents being allocated and deallocated.




I wan able to find the blocker from the DBA_HIST_ACTIVE_SESS_HISTORY view. Drunig 18:30 - 19:00 Session 651 is blocking many other sessions, which either wait for enq: TX or enq:ST  for examples:

SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION

---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.59.56.243 PM 242 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 345 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 414 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 469 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 591 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 593 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 594 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 595 6wyrqa50whrjg enq: TX - contention 651
08-FEB-11 06.59.56.243 PM 596 6wyrqa50whrjg enq: TX - contention 651

...


SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION
---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.59.56.243 PM 1976 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 49 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1841 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1763 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1693 dpc1k1djg5gh0 enq: ST - contention 651
08-FEB-11 06.59.56.243 PM 1660 dpc1k1djg5gh0 enq: ST - contention 651

....

Session 651 that was doing the same insert lasted about 1hour, from about 6:17 to 7:15

SAMPLE_TIME SESSION_ID SQL_ID EVENT BLOCKING_SESSION
---------------------------------------- ---------- ------------- ------------------------------ ----------------
08-FEB-11 06.17.23.778 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.33.998 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.44.198 PM 651 6wyrqa50whrjg
08-FEB-11 06.17.54.508 PM 651 6wyrqa50whrjg
...

08-FEB-11 07.14.45.919 PM 651 6wyrqa50whrjg
08-FEB-11 07.14.56.049 PM 651 6wyrqa50whrjg
08-FEB-11 07.15.06.159 PM 651 6wyrqa50whrjg
-- end --



After this sql ( 6wyrqa50whrjg  is an  simple insert into a table) was done, things become normal.  I am still not sure why this insert took so long. I was unable to know what wait event it was experiencing. Apparantly, Oracle was allocating a new extent to the table segment, but why took about an hour? The table referred in the SQL has two extents now, first one has 64000 blocks, the second has 16000 blocks.

So the scenario appeared to be that a session wants to insert a row into a table that resides in a DMT tablespace, but  the table segment is run out of space, Oracle firstly has to allocate a new extent to the table segment; the session is waiting for this allocation to complete; it blocks all other sessions doing the same insert into the same table with the latter waiting for enq:TX. It also blocks other sessions with enq:ST events,  which  are doing DML on  different tables  that resides in the same tablespace.

Anyway we really need to migrate DMT to LMT asap.

Identify and kill a blocking session - enq: TX - row lock contention

This post documented steps I have taken to identify and kill a blocking session:

1. Recived alert:

DBNAME:critical-Higher wait events:enq: TX - row lock contention-63(threshold 50)

2. Checking the wait events, find that the count for 'enq: TX - row lock contention' is high

  COUNT(*) EVENT                                         MAX(SECONDS_IN_WAIT)
---------- --------------------------------------------- --------------------
5753 SQL*Net message from client                                6048278
188 SQL*Net break/reset to client                                33425
149 enq: TX - row lock contention                                12274
20 rdbms ipc message                                            41691
1 Streams AQ: qmn slave idle wait                             556815
1 Streams AQ: waiting for messages in the queue                    5
1 Streams AQ: waiting for time management or cl                33106
eanup tasks
1 db file parallel write                                           0
1 direct path write                                                2
1 Streams AQ: qmn coordinator idle wait                      6184833
1 jobq slave wait                                                 18
1 os thread startup                                                0
1 pmon timer                                                   18795
1 smon timer                                                    5504
1 SQL*Net message to client                                        0

3. Checking locks:

Looks everyone is waiting for sid=7752

system@DBNAME> @qlocks

Lock                Time Held
SID Lock Type Requested Lock Held (minutes) Block
------ --------- --------- --------- --------- -----
7752 Trans     None      Exclusive       325 Yes
3994 Trans     Share     None            324 No
8305 Trans     Share     None            323 No
4922 Trans     Share     None            292 No
3977 Trans     Share     None            285 No
7668 Trans     Share     None            282 No
4379 Trans     Share     None            124 No
5423 Trans     Share     None              1 No
7611 Trans     Share     None              1 No
6080 Trans     Share     None              1 No
3843 Trans     Share     None              0 No
4731 Trans     Share     None              0 No

( truncated ...  total 116 rows )



system@DBNAME> @blocker

ADDR             KADDR               SID TY        ID1        ID2      LMODE    REQUEST      CTIME   Block
---------------- ---------------- ------ -- ---------- ---------- ---------- ---------- ---------- ----------
0000000516758030 00000005167581B8   7752 TX    3080222     128785          6          0      19544 ##########

4. Check the session sid=7752

system@DBNAME> @sess_by_sid
Enter value for sid: 7752

Shadow       Remote       Remote
SID-SERIAL   OS User  Username         Module         Process      Process      Machine              Logon Time      Status
------------ -------- ---------------- -------------- ------------ ------------ -------------------- --------------- --------
'7752,55822' doammw27 OLAMLOG                         8786         1234         dspcef07             10/26 13:42:04  INACTIVE

5. The following query shows that session sid=7752 is 19367 sec old, and the last call made by it is 19366 sec ago.

system@DBNAME> @trans_long_running.sql

ADDR             Status       UBAREC           START_SCN SYSDATE             START_DATE                SECS     RSSIZE   SID LAST_CALL_ET Status   Username         OS User  SHARABLE_MEM
---------------- -------- ---------- ------------------- ------------------- ------------------- ---------- ---------- ----- ------------ -------- ---------------- -------- ------------
0000000516758030 ACTIVE           13      10172725882034 2008-10-26 19:05:54 2008-10-26 13:43:07      19367    1171456  7752        19366 INACTIVE OLAMLOG          doammw27

6. After killing the session sid=7752, wait event showed as follows:

  COUNT(*) EVENT                                         MAX(SECONDS_IN_WAIT)
---------- --------------------------------------------- --------------------
5943 SQL*Net message from client                                6049401
188 SQL*Net break/reset to client                                34548
22 rdbms ipc message                                            42814
1 smon timer                                                     276
1 Streams AQ: waiting for time management or cl                34229
eanup tasks

1 jobq slave wait                                                 47
1 pmon timer                                                     283
1 Streams AQ: qmn slave idle wait                             557938
1 Streams AQ: qmn coordinator idle wait                      6185956
1 SQL*Net message to client                                        0
1 Streams AQ: waiting for messages in the queue                    5

####---------------------------------------------------------------------------
Appendix - scripts used:

$ cat event.sql
rem file: event.sql
rem
rem  Lists the Current Waits in the database.
rem  First Script to run in the database to debug performance issues.
rem  This query lists the Count of Sessions group by Wait Event, and
rem  sorted in Ascending Order.
rem  Look for Top 5 Wait events from this query.
rem  Also listed is the maximum time ( seconds) sessions
rem  have waited against a particular wait event. Count Information is
rem  more valuable than the Max time information.
rem
column event format a45
select count(*), event, max(seconds_in_wait) from v$session_wait
group by event
order by 1 desc
/

####---------------------------------------------------------------------------

$ cat qlocks.sql
clear columns
clear computes
clear breaks

set linesize 240
set pagesize 40

column sid      format 99999    heading "SID"
column locktype format A9       heading "Lock Type"
column lockreq  format A9       heading "Lock     Requested"
column lockheld format A9       heading "Lock Held"
column timeheld format 9999999  heading "Time Held(minutes)"
column block    format a5       heading "Block"


select /* RULE */ l.sid sid,
decode(l.type,'TM','DML','TX','Trans','UL','User',l.type) locktype,
decode(l.request,0,'None',1,'Null',2,'Row-S',3,'Row-X',4,'Share',5,'S/Row-X',6,'Exclusive') lockreq,
decode(l.lmode,0,'None',1,'Null',2,'Row-S',3,'Row-X',4,'Share',5,'S/Row-X',6,'Exclusive') lockheld,
l.ctime/60 timeheld,
decode(l.block,0,'No',1,'Yes') block
from v$lock l
where l.request != 0 or l.block != 0
order by l.id1, l.lmode desc, l.ctime desc
/

####---------------------------------------------------------------------------
$ cat blocker.sql
select * from v$lock where block > 0
/

####---------------------------------------------------------------------------
$ cat sess_by_sid.sql
set linesize 250
set pagesize 1000
set verify off

column SidSerial        format a12      heading "SID-SERIAL"
column sid      format 9999     heading "SID"
column serial   format 99999    heading "Serial "
column osuser   format a8       heading "OS User"
column username format a16      heading "Username"
column module   format a14      heading "Module"
column spid     format 999999   heading "ShadowProcess"
column process  format 999999   heading "RemoteProcess"
column machine  format a20      heading "RemoteMachine"
column time     format a15      heading "Logon Time"
column status   format a8       heading "Status"


select ''''||s.sid||','||s.serial# ||'''' SidSerial,
--select s.sid sid ,
--s.serial# serial,
s.osuser                 osuser,
s.username               username,
s.module                 module,
p.spid                   spid,
s.process                process,
s.machine                machine,
to_char(s.logon_time, 'mm/dd hh24:mi:ss') time,
s.status                 status
from v$session s, v$process p
where s.paddr = p.addr (+)
and s.sid = &sid
/

####---------------------------------------------------------------------------

$ cat trans_long_running.sql
column start_scn format 999999999999999999
select
t.addr,
t.status,
t.UBAREC,
t.start_scn,
SYSDATE,
t.start_date,
(
(SYSDATE - t.start_date) * 86400
) secs,
r.rssize,
s.sid,
s.last_call_et,
s.status,
s.username,
s.osuser,
sa.sharable_mem
from
v$transaction t
join v$rollstat r on t.xidusn = r.usn
join v$session s on s.saddr = t.ses_addr
left outer join v$sqlarea sa on s.sql_address = sa.address
where s.sid = 7752
/

Why waiting for 'db file sequential read' whereas plan shows FTS?

Application team reported that a query usually run less than 1 hour now took almost 3 hour and still not finish. This query is only a select statement against one table. I checked the execution plan of this query it is a very simple FTS. But when check the wait event, it is waiting for 'db file sequential read', which usually means index scan.

The application team killed the session and re-run the query some time later, and this time it was finished much faster.

Later performance team provided a nice explaination, first of all they provided the following query result:

select x.* , (select file_name from dba_data_files where file_id=p1) name from (
  select p1, count(*) cnt
    from v$active_session_history where sql_id='8xnhck4a6d400' and event='db file sequential read'
   group by p1 order by 2 desc
  )x


                  P1                     CNT                                             NAME                                      
----------------------- ---------------------- --------------------------------------------------------
                    114                    188 /ora_36a_04/ORACLE/DBNAME/dbf/undoDBNAME_6.dbf
                      2                    188 /ora_36a_01/ORACLE/DBNAME/dbf/undoDBNAME_1.dbf                                
                    162                    176 /ora_36a_05/ORACLE/DBNAME/dbf/undoDBNAME_13.dbf                               
                     33                    173 /ora_36a_02/ORACLE/DBNAME/dbf/undoDBNAME_2.dbf                                
                    113                    172 /ora_36a_05/ORACLE/DBNAME/dbf/undoDBNAME_5.dbf                                
                     95                    170 /ora_36a_03/ORACLE/DBNAME/dbf/undoDBNAME_9.dbf                                
                    112                    169 /ora_36a_04/ORACLE/DBNAME/dbf/undoDBNAME_5.dbf                                
                    105                    168 /ora_36a_04/ORACLE/DBNAME/dbf/undoDBNAME_3.dbf                                
                     96                    167 /ora_36a_05/ORACLE/DBNAME/dbf/undoDBNAME_10.dbf                               
                     97                    166 /ora_36a_05/ORACLE/DBNAME/dbf/undoDBNAME_11.dbf                               
                     94                    165 /ora_36a_05/ORACLE/DBNAME/dbf/undoDBNAME_8.dbf                                
                     93                    161 /ora_36a_04/ORACLE/DBNAME/dbf/undoDBNAME_7.dbf                                
                    111                    161 /ora_36a_04/ORACLE/DBNAME/dbf/undoDBNAME_4.dbf                                

This query undoubtly demonstrate that the wait for 'db file sequntial read' is due to read from undo tablespace blocks.

They further expained:

The difference between the first and second run is that on the first (slow) run when query started , it appears there was a lot of DML activity was going on against CH_OBJECTS table - possibly involving longer than normal running non-committed transactions. This made Oracle perform a lot of extra I/O against the UNDO segments in order to maintain a read consistent image of the data true to the moment the query was kicked off.

When the query was kicked off the second time, the abnormal DML activity had already completed and there were no reads from UNDO segments, just the normal serial full scan occurred.

It is a great learning experience for me. Particularly what insterested to me is the way they query the v$active_session_history view. I did the following
exercise in another database:

system@DB2NAME> select distinct(event)  from v$active_session_history where sql_id='axuuxsm4p8hct';

EVENT
----------------------------------------------------------------

reliable message
os thread startup
direct path read
PX Deq: Signal ACK


system@DB2NAME> select p1, p1text, count(*) from v$active_session_history 
where sql_id='axuuxsm4p8hct' and  event='direct path read' group by p1, p1text;

        P1 P1TEXT                             COUNT(*)
---------- -------------------------------- ----------
       540 file number                               1
       407 file number                               2
       193 file number                               1

system@DB2NAME> select file_name from dba_data_files where file_id=540;

FILE_NAME
------------------------------------------------------------------------------------------------------------------------
/ora_44a_04/ORACLE/DB2NAME/dbf/tlgp11mDB2NAME_06.dbf

system@DB2NAME> select file_name from dba_data_files where file_id=407;

FILE_NAME
------------------------------------------------------------------------------------------------------------------------
/ora_44a_07/ORACLE/DB2NAME/dbf/tlgp11mDB2NAME_05.dbf



  1  select x.*, (select file_name from dba_data_files where file_id=p1) from
  2  (
  3  select p1, count(*) from v$active_session_history where sql_id='axuuxsm4p8hct' and  event='direct path read' group by p1
  4* ) x
system@DB2NAME> /

        P1   COUNT(*)
---------- ----------
(SELECTFILE_NAMEFROMDBA_DATA_FILESWHEREFILE_ID=P1)
------------------------------------------------------------------------------------------------------------------------
       407          2
/ora_44a_07/ORACLE/DB2NAME/dbf/tlgp11mDB2NAME_05.dbf

       193          1
/ora_44a_02/ORACLE/DB2NAME/dbf/tlgp11mDB2NAME_01.dbf

       540          1
/ora_44a_04/ORACLE/DB2NAME/dbf/tlgp11mDB2NAME_06.dbf

Library Cache Pin for over 600 seconds

During my on-call shift today, I recieved the alerts for a database: Library Cache Pin for over 600 seconds

Checked the database, found the following:

===> check session wait: sid=852 wait for library cache pin


SID USERNAME EVENT P1 P2 WAIT_TIME STATE
------ --------------- -------------------- ---------- ---------- ---------- -------------------

852 MTZUSG12CON library cache pin 1.3835E+19 1.3835E+19 0 WAITING


===> current running sql:

SQL_TEXT SID USER_NAME
---------------------------------------- ------ ------------
update AC_PROCESSING_ACCOUNTING set FIL 852 MTZUSG12CON
E_STATUS='CN' where (((FPFC_NXT_PGM_NAME
=:b0 and FILE_STATUS='RD') and FPFC_NXT_
FILE_ALIAS=:b1) and DATA_GROUP like :b2)


From Google, found Burleson has a tip for this topic. click this.

The following script is published by Mark Bobak for locating the source of library cache pin waits.

select decode(lob.kglobtyp, 0, 'NEXT OBJECT', 1, 'INDEX', 2, 'TABLE', 3, 'CLUSTER',
                      4, 'VIEW', 5, 'SYNONYM', 6, 'SEQUENCE',
                      7, 'PROCEDURE', 8, 'FUNCTION', 9, 'PACKAGE',
                      11, 'PACKAGE BODY', 12, 'TRIGGER',
                      13, 'TYPE', 14, 'TYPE BODY',
                      19, 'TABLE PARTITION', 20, 'INDEX PARTITION', 21, 'LOB',
                      22, 'LIBRARY', 23, 'DIRECTORY', 24, 'QUEUE',
                      28, 'JAVA SOURCE', 29, 'JAVA CLASS', 30, 'JAVA RESOURCE',
                      32, 'INDEXTYPE', 33, 'OPERATOR',
                      34, 'TABLE SUBPARTITION', 35, 'INDEX SUBPARTITION',
                      40, 'LOB PARTITION', 41, 'LOB SUBPARTITION',
                      42, 'MATERIALIZED VIEW',
                      43, 'DIMENSION',
                      44, 'CONTEXT', 46, 'RULE SET', 47, 'RESOURCE PLAN',
                      48, 'CONSUMER GROUP',
                      51, 'SUBSCRIPTION', 52, 'LOCATION',
                      55, 'XML SCHEMA', 56, 'JAVA DATA',
                      57, 'SECURITY PROFILE', 59, 'RULE',
                      62, 'EVALUATION CONTEXT',
                     'UNDEFINED') object_type,
       lob.KGLNAOBJ object_name,
       pn.KGLPNMOD lock_mode_held,
       pn.KGLPNREQ lock_mode_requested,
       ses.sid,
       ses.serial#,
       ses.username
  FROM
       x$kglpn pn,
       v$session ses,
       x$kglob lob,
       v$session_wait vsw
  WHERE
   pn.KGLPNUSE = ses.saddr and
   pn.KGLPNHDL = lob.KGLHDADR
   and lob.kglhdadr = vsw.p1raw
   and vsw.event = 'library cache pin'
order by lock_mode_held desc
/

I run it as sysdba and the output is:

OBJECT_TYPE
------------------
OBJECT_NAME
----------------------------------------------------------------------------------------------------------------------                                       --
LOCK_MODE_HELD LOCK_MODE_REQUESTED    SID    SERIAL# USERNAME
-------------- ------------------- ------ ---------- ---------------
NEXT OBJECT
update AC_PROCESSING_ACCOUNTING  set FILE_STATUS='CN' where (((FPFC_NXT_PGM_NAME=:b0 and FILE_STATUS='RD') and FPFC_NX                                       T_
FILE_ALIAS=:b1) and DATA_GROUP like :b2)
             3                   0    985      28668 MTZUSG08CON

NEXT OBJECT
update AC_PROCESSING_ACCOUNTING  set FILE_STATUS='CN' where (((FPFC_NXT_PGM_NAME=:b0 and FILE_STATUS='RD') and FPFC_NX                                       T_
FILE_ALIAS=:b1) and DATA_GROUP like :b2)
             0                   2    852      14208 MTZUSG12CON

After a while, the wait envet went away by itself.