Tracking the bind value with errorstack dump

It is technically impossible to find out the bind value of the past query without proactive trace like 10046(level >= 4) or auditing enabled. But enabling 10046 event trace or auditing is too harsh requirement for that purpose.

One of the interesting solutions is errorstack(level >=2). Errorstack dump shows the bind value of the current process(not past!) along with the callstack and other important informations.

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
...
 Bind bytecodes
  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy 
  oacdef = 2bdb5bf0   Offsi = 36, Offsi = 0
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=080aa6e0  bln=22  avl=02  flg=05
  value=1

But the problem is that even the errorstack dump is NOT proactive solution, which means you should stay there at the right time and the right place. Night shift, huh?

Here you can make some ideas on automating the errorstack dump, like following.

1. ORA-00001 event trace
If your requirement is to get the bind value when the process got unique key violation, you can just turn on the trace for the diagnostic event 1, like this.

alter system set events '1 trace name errorstack level 2, forever';
or
alter session events '1 trace name errorstack level 2, forever';

, which means that whenever(forever) you hit the ORA-00001 exception(1), dump errorstack at level 2(errorstack level 2).

2. Proactively monitor the situation and dump errorstack using oradebug
For instance, let me assume that you want to find out the bind value which causes the serious TX lock contention. In this case, simple trick with PL/SQL and SQL*Plus would meet your requirement.

For instance, following simple script

connect /as sysdba

var sid number;

begin
	for idx in 1 .. 1000000 loop
		dbms_lock.sleep(1);
		select min(sid) into :sid from v$lock
			where type = 'TX' and request > 0 and block = 0 and ctime > 30;
			
		if :sid > 0 then
			exit;
		end if;
	end loop;
end;
/

print :sid

col spid new_value v_spid

select spid from v$process 
where addr in (select paddr from v$session where sid = :sid);

oradebug setospid &v_spid

oradebug dump errorstack 2

would dump errorstack for the process who has been waiting for the TX lock over 30 secs.

The result is

----------------------------------------
Cursor#2(08040C64) state=BOUND curiob=080479E8
 curflg=44 fl2=0 par=00000000 ses=2EB3F224
 sqltxt(2E5F0058)=insert into t1 values(:b1, 1)
  hash=bbc06f38e42d1542e8fdfe7363d9ab40
  parent=2945F7D0 maxchild=02 plk=2C75C638 ppn=n
cursor instantiation=080479E8
 child#1(27DB82B0) pcs=295262B8
  clk=2B138D44 ci=2AD04520 pn=2C7CEA94 ctx=2B7508A8
 kgsccflg=0 llk[080479EC,080479EC] idx=0
 xscflg=c0110676 fl2=d100008 fl3=42222008 fl4=0
 Bind bytecodes
  Opcode = 2   Bind Twotask Scalar Sql In (may be out) Copy 
  oacdef = 2bdb5bf0   Offsi = 36, Offsi = 0
kkscoacd
 Bind#0
  oacdty=02 mxl=22(22) mxlc=00 mal=00 scl=00 pre=00
  oacflg=03 fl2=1000000 frm=00 csi=00 siz=24 off=0
  kxsbbbfp=080aa6e0  bln=22  avl=02  flg=05
  value=1

There would other tricks to get the bind value using errorstack at this way of emulating proactive trace. Even this is not a perfect solution, the merit of negligible overhead is not negligible.

Advertisements

Tracking the bind value

One of the most frequent questions I’m always asked of.

Can I trace the bind values of the SQL statement executed last night?

The answer is (sadly) NO.

As far as I know, we have only 2 ways

• With session-wide or system-wide 10046 event(level >=4) enabled
• With auditing enabled

But I bet that 99.99% of the system does not enable aboves.

Okay, then what else do we have? What comes into my mind is 1) Log Miner and/or 2) Bind Capture History.

1. Log Miner
In case of DML statements, you can retrieve the modified row information(NOT bind value!) from redo log fiie using log miner. This is extremely helpful for analyzing unique key violation problem, but not that meaningful for general bind value identification.

Simple demonstration:

UKJA@ukja102> create table t1(c1 int, c2 int, c3 char(100));

Table created.

UKJA@ukja102> insert into t1 select level, level, 'x'
  2  from dual connect by level <= 10000;

10000 rows created.

UKJA@ukja102> select log_mode from v$database;

LOG_MODE                                                                        
------------                                                                    
ARCHIVELOG                                                                      

UKJA@ukja102> alter system switch logfile;

System altered.

UKJA@ukja102> var b1 number;
UKJA@ukja102> var b2 number;
UKJA@ukja102> var b3 varchar2(1);
UKJA@ukja102> begin
  2    :b1 := 1;
  3    :b2 := 1000;
  4    :b3 := 'x';
  5  end;
  6  /

PL/SQL procedure successfully completed.

UKJA@ukja102> update t1 set c3 = :b3 where c1 between :b1 and :b2;

1000 rows updated.

UKJA@ukja102> commit;

Commit complete.

UKJA@ukja102> alter system switch logfile;

System altered.

UKJA@ukja102> col name new_value archive_file
UKJA@ukja102> select name from v$archived_log
  2  where sequence# = (select max(sequence#)rp from v$archived_log);

NAME                                                                            
------------------------------                                                  
C:\ORACLE\FLASH_RECOVERY_AREA\                                                  
UKJA10\ARCHIVELOG\2009_05_06\O                                                  
1_MF_1_4485_501WCW5V_.ARC                                                       
                                                                                

UKJA@ukja102> exec sys.dbms_logmnr.add_logfile('&archive_file');

PL/SQL procedure successfully completed.

UKJA@ukja102> exec sys.dbms_logmnr.start_logmnr;

PL/SQL procedure successfully completed.

UKJA@ukja102> col data_object_id new_value obj_id
UKJA@ukja102> select object_id, data_object_id from user_objects where object_name = 
'T1';

 OBJECT_ID DATA_OBJECT_ID                                                       
---------- --------------                                                       
     85083          85083                                                       

UKJA@ukja102> select count(*) from v$logmnr_contents
  2  where data_obj# = &obj_id;
old   2: where data_obj# = &obj_id
new   2: where data_obj# =      85083

  COUNT(*)                                                                      
----------                                                                      
     10033                                                                      

UKJA@ukja102> set serveroutput on
UKJA@ukja102> exec print_table('select * from v$logmnr_contents where -
>   operation = ''UPDATE'' and data_obj# = &obj_id and rownum = 1');
SCN                           : 8654960105647
CSCN                          :
TIMESTAMP                     : 2009/05/06 11:10:04
COMMIT_TIMESTAMP              :
THREAD#                       : 1
LOG_ID                        : 4486
XIDUSN                        : 1
XIDSLT                        : 29
XIDSQN                        : 18038
PXIDUSN                       : 1
PXIDSLT                       : 29
PXIDSQN                       : 18038
RBASQN                        : 4486
RBABLK                        : 2
RBABYTE                       : 192
UBAFIL                        : 2
UBABLK                        : 8388867
UBAREC                        : 24
UBASQN                        : 5559
ABS_FILE#                     : 2
REL_FILE#                     : 6
DATA_BLK#                     : 836
DATA_OBJ#                     : 85083
DATA_OBJD#                    : 85083
SEG_OWNER                     : UNKNOWN
SEG_NAME                      : OBJ# 85083
TABLE_NAME                    : OBJ# 85083
SEG_TYPE                      : 0
SEG_TYPE_NAME                 : UNKNOWN
TABLE_SPACE                   : UNKNOWN
ROW_ID                        : AAAUxbAAGAAAANEAAA
SESSION#                      : 0
SERIAL#                       : 0
USERNAME                      :
SESSION_INFO                  :
TX_NAME                       :
ROLLBACK                      : 0
OPERATION                     : UPDATE
OPERATION_CODE                : 3
SQL_REDO                      : update "UNKNOWN"."OBJ# 85083" set "COL 3" =
HEXTORAW('7820202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020') where "COL 3" =
HEXTORAW('7820202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020') and ROWID =
'AAAUxbAAGAAAANEAAA';
SQL_UNDO                      : update "UNKNOWN"."OBJ# 85083" set "COL 3" =
HEXTORAW('7820202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020') where "COL 3" =
HEXTORAW('7820202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020202020202020202020202020202020
20202020202020202020202020202020202020202020202020') and ROWID =
'AAAUxbAAGAAAANEAAA';
RS_ID                         :  0x001186.00000002.00c0
SEQUENCE#                     : 1
SSN                           : 0
CSF                           : 0
INFO                          : Dictionary Mismatch
STATUS                        : 2
REDO_VALUE                    : 2162
UNDO_VALUE                    : 2163
SQL_COLUMN_TYPE               :
SQL_COLUMN_NAME               :
REDO_LENGTH                   : 0
REDO_OFFSET                   : 0
UNDO_LENGTH                   : 0
UNDO_OFFSET                   : 0
DATA_OBJV#                    : 0
SAFE_RESUME_SCN               :
XID                           : 01001D0076460000
PXID                          : 01001D0076460000
AUDIT_SESSIONID               : 0
-----------------

PL/SQL procedure successfully completed.               

UKJA@ukja102> exec sys.dbms_logmnr.end_logmnr;

PL/SQL procedure successfully completed.

2. Bind Capture History
As of 10g, Oracle captures the bind value and stores it into the repository(AWR), but with following restrictions.

• Captured periodically(_cursor_bind_capture_interval), not at real time.
• Captured under maximum size(_cursor_bind_capture_area_size)
• Only bind variables in WHERE clause are captured

Ouch! Too many restrictions, aren’t they?

Simple demonstration:

UKJA@ukja102> var bid1 number;
UKJA@ukja102> var eid1 number;
UKJA@ukja102> 
UKJA@ukja102> exec :bid1 := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

UKJA@ukja102> 
UKJA@ukja102> var b1 number;
UKJA@ukja102> var b2 number;
UKJA@ukja102> var b3 varchar2(1);
UKJA@ukja102> begin
  2    :b1 := 1;
  3    :b2 := 2000;
  4    :b3 := 'y';
  5  end;
  6  /

PL/SQL procedure successfully completed.

UKJA@ukja102> 
UKJA@ukja102> update t1 set c3 = :b3 where c1 between :b1 and :b2;

2000 rows updated.

UKJA@ukja102> commit;

Commit complete.

UKJA@ukja102> 
UKJA@ukja102> exec :eid1 := dbms_workload_repository.create_snapshot;

PL/SQL procedure successfully completed.

UKJA@ukja102> 
UKJA@ukja102> var sql_id varchar2(100);
UKJA@ukja102> begin
  2    select sql_id into :sql_id
  3    from dba_hist_sqltext
  4    where sql_text like 'update t1 set c3 = :b3 where c1 between :b1 and :b2';
  5  end;
  6  /

PL/SQL procedure successfully completed.

UKJA@ukja102> 
UKJA@ukja102> print sql_id

SQL_ID                                                                          
--------------------------------------------------------------------------------
bvy5d4xupjkku                                                                   

UKJA@ukja102> 
UKJA@ukja102> col name format a10
UKJA@ukja102> col position format 99
UKJA@ukja102> col value_string format a20
UKJA@ukja102> select snap_id, name, position, value_string, last_captured -
> from dba_hist_sqlbind
  2  where sql_id = :sql_id
  3  order by snap_id desc;

   SNAP_ID NAME       POSITION VALUE_STRING         LAST_CAPTURED               
---------- ---------- -------- -------------------- -------------------         
      6701 :B1               2 1                    2009/05/06 11:10:13         
      6701 :B2               3 2000                 2009/05/06 11:10:13         
      6701 :B3               1                                                  
      6700 :B2               3 1000                 2009/05/06 11:10:03         
      6700 :B3               1                                                  
      6700 :B1               2 1                    2009/05/06 11:10:03         
      6699 :B1               2 1                    2009/05/06 11:05:50         
      6699 :B3               1                                                  
      6699 :B2               3 2000                 2009/05/06 11:05:50         
      6697 :B2               3 2000                 2009/05/06 10:47:51         
      6697 :B3               1                                                  
      6697 :B1               2 1                    2009/05/06 10:47:51         

12 rows selected.

As I already pointed it out, these are just naive tries, not solution to the original question. Basically speaking, we have no ways to identify the bind values of the past SQL without 10046 event nor auditing enabled.