Oradebug dump errorstack and bind values

Tanel Poder's reply to a question in the Oracle-L mailing list inspired me to test the idea of using errostack dump to obtain the bind values in the 9i database. Previously I also took notes about different methods for obtaining bind values: here with sql_trace and more recently here with FGA.

Test steps:

1. create tables
script: cr_tab.sql

create two tables: p and c, which has parent-child relationship

2. In Session 1, insert into the parent table without commit:
SQL> variable n number
SQL> exec :n := 201
PL/SQL procedure successfully completed.
SQL> insert into p values(:n, 35);
1 row created.

3. In Session 2, insert into the child table:

SQL> variable n number
SQL> exec :n := 201
PL/SQL procedure successfully completed.
SQL> insert into c values(2, :n);

4. In another session, we can see the blocker and waiter sessions:

SQL> @bw
'WAITER'                      : WAITER
SID                           : 87
SERIAL#                       : 24
SPID                          : 27274
USERNAME                      : Zxxx294
MACHINE                       : MSHOME\NTBK
SESS_AGE_MIN                  : 17
HASH_VALUE                    : 3262381862
QUERY_TXT                     : insert into c values(:"SYS_B_0", :n)
-----------------

PL/SQL procedure successfully completed.

'BLOCKER'                     : BLOCKER
SID                           : 126
SERIAL#                       : 512
SPID                          : 57
USERNAME                      : Zxxx294
MACHINE                       : MSHOME\NTBK
SESS_AGE_MIN                  : 2
HASH_VALUE                    : 716205104
QUERY_TXT                     : insert into p values(:n, :"SYS_B_0")
-----------------

5. Logon to the server, issue the following command:

$> estk_dump.sh 27274
$> estk_dump.sh 512

Where 27274 and 512 are the OS pid (SPID) of the blocker and waiter session respectively

6. Analyze the trace files:

In the udump dir, trace files were generated, for the waiter session, we can see the bind value
(by search value=), for example:

In the trace file from pid=512

----------------------------------------
Cursor 1 (ffffffff7ca60458): CURBOUND  curiob: ffffffff7ca69828
curflg: 4c curpar: 0 curusr: b7 curses 3b433bb88
cursor name: insert into c values(:"SYS_B_0", :n)
child pin: 3b7b98c88, child lock: 3b7b947f8, parent lock: 3b7b94bb0
xscflg: 110664, parent handle: 3bcaae0a0, xscfl2: f900008
Dumping Literal Information
Bind Pos: 0, Bind Len: 2, Bind Val:
nxt: 3.0x00000420  nxt: 2.0x000001d0  nxt: 1.0x00000208
Cursor frame allocation dump:
frm: -------- Comment --------  Size  Seg Off
bhp size: 216/600
bind 0: dty=2 mxl=22(02) mal=00 scl=00 pre=00 oacflg=10 oacfl2=100 size=24 offset=0
bfp=ffffffff7ca694f0 bln=22 avl=02 flg=09
value=2
bind 1: dty=2 mxl=22(22) mal=00 scl=00 pre=00 oacflg=03 oacfl2=0 size=24 offset=0
bfp=ffffffff7ca5e040 bln=22 avl=03 flg=05
value=201
End of cursor dump

In addtion,we can find DML LOCK information as can be seen:

DML LOCK: tab=508254 flg=11 chi=0
his[0]: mod=3 spn=302
(enqueue) TM-0007C15E-00000000  DID: 0001-000D-0000005A
lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
res: 3b4a42960, mode: SX, prv: 3b4a42970, sess: 3b433bb88, proc: 3b41ac6d8
----------------------------------------
SO: 3b60e47b0, type: 34, owner: 3b63c7540, flag: INIT/-/-/0x00
DML LOCK: tab=508252 flg=11 chi=0
his[0]: mod=2 spn=302
(enqueue) TM-0007C15C-00000000  DID: 0001-000D-0000005A
lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
res: 3b4a45758, mode: SS, prv: 3b4a45768, sess: 3b433bb88, proc: 3b41ac6d8

However, from the blocker session trace file, we can not find any bind values. Notice that waiter session was shown as 'ACTIVE' and blocker session shown as 'INACTIVE' in the v$session view. Nevertheless, we can still find DML lock info:

----------------------------------------
SO: 3b60e4540, type: 34, owner: 3b643fbe0, flag: INIT/-/-/0x00
DML LOCK: tab=508254 flg=11 chi=0
his[0]: mod=2 spn=11931
(enqueue) TM-0007C15E-00000000  DID: 0001-000A-00000E56
lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
res: 3b4a42960, mode: SS, prv: 3b60e4b28, sess: 3b4355778, proc: 3b41ab6b8
----------------------------------------
SO: 3b60e4060, type: 34, owner: 3b643fbe0, flag: INIT/-/-/0x00
DML LOCK: tab=508252 flg=11 chi=0
his[0]: mod=3 spn=11931
(enqueue) TM-0007C15C-00000000  DID: 0001-000A-00000E56
lv: 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00 00
res: 3b4a45758, mode: SX, prv: 3b60e47e8, sess: 3b4355778, proc: 3b41ab6b8

If we feed the DML lock information from the trace file (i.e. tab=508252) into the following query, we canget:

SQL> select object_name from dba_objects where object_id=508252;

OBJECT_NAME
------------------------------
P

SQL> select object_name from dba_objects where object_id=508254;

OBJECT_NAME
------------------------------
C

So it is interesting to know the blocker session holds SX mode DML lock on P, and SS mode DML lock on C; whereas the waiter session holds SS mode DML lock on P, and SX mode DML lock on C. If we see such kind of info, we can check the relationship between P and C, and may speculate the block/waiter is caused by FK constriant.


Appendix:

--- script: estk_dump.sh -----
#!/bin/ksh
ospid=$1
sqlplus -s "/ as sysdba" <<EOF
oradebug setospid $ospid
oradebug unlimit
oradebug dump errorstack 2 
EOF



--- script: bw.sql ------------
exec print_table(' select distinct ''WAITER'', vs.sid, vs.serial#, vp.SPID, vs.username, vs.machine, round((sysdate - vs.logo
n_time) * (24*60)) sess_age_min, va.hash_value, substr(va.sql_text,1,800) Query_Txt from v$sqlarea va, dba_waiters wait, v$se
ssion vs, v$process vp where vs.sid=wait.waiting_session and  vs.PADDR = vp.ADDR (+) and vs.sql_address=va.address (+) and vs
.sql_hash_value=va.hash_value (+) ');

exec print_table(' select distinct ''BLOCKER'' ,vs.sid, vs.serial#, vp.SPID, vs.username, vs.machine, round((sysdate - vs.log
on_time) * (24*60)) sess_age_min,va.hash_value, substr(va.sql_text,1,800) Query_Txt from v$sqlarea va, dba_blockers block, v$
session vs, v$process vp where vs.sid=block.holding_session and  vs.PADDR = vp.ADDR (+) and vs.sql_address=va.address (+) and
vs.sql_hash_value=va.hash_value (+) ');



---- script: cr_tab.sql ----------
set echo on
drop table c;
drop table p;

create table p
as
select  rownum id,
trunc(rownum/20) d
from all_objects
where rownum <=200;  

alter table p add constraint p_pk primary key (id);  

create table c 
as 
select   
rownum id,   
mod(rownum+1000, 200) + 1 fk1 
from all_objects where rownum <=200; 
alter table c add constraint c_fk foreign key(fk1) references p(id);

exec dbms_stats.gather_table_stats(user, 'p', cascade=> true);
exec dbms_stats.gather_table_stats(user, 'c', cascade=> true);

Update: Feb 2012
Reference: How to read ERRORSTACK output