Simple formatting on index tree dump

I often need to do index block dump while troubleshooting index problem.

For instance, let’s assume that I want to take a dump for 3rd index leaf block. It’s a very tedious job and error-prone. So I made a simple but cute tool to make a life simple.

UKJA@ukja116> select * from v$version;

BANNER                                                                          
--------------------------------------------------------------------------------
Oracle Database 11g Enterprise Edition Release 11.1.0.6.0 - Production          
PL/SQL Release 11.1.0.6.0 - Production                                          
CORE	11.1.0.6.0	Production                                                      
TNS for 32-bit Windows: Version 11.1.0.6.0 - Production                         
NLSRTL Version 11.1.0.6.0 - Production                                          

Elapsed: 00:00:00.03
UKJA@ukja116> 
UKJA@ukja116> create table t1(c1 int, c2 char(100));

Table created.

Elapsed: 00:00:00.01
UKJA@ukja116> 
UKJA@ukja116> insert into t1
  2  select level, 'dummy' from dual
  3  connect by level  <= 1000
  4  ;

1000 rows created.

Elapsed: 00:00:00.01
UKJA@ukja116> 
UKJA@ukja116> create index t1_n1 on t1(c1, c2);

Index created.

Elapsed: 00:00:00.01
UKJA@ukja116> -- do index tree dump
UKJA@ukja116> exec tree_dump('t1_n1');

PL/SQL procedure successfully completed.

Elapsed: 00:00:00.01

The result of index tree dump is as following.

----- begin tree dump
branch: 0x1c00af4 29362932 (0: nrow: 17, level: 1)
   leaf: 0x1c00af5 29362933 (-1: nrow: 62 rrow: 62)
   leaf: 0x1c00af6 29362934 (0: nrow: 62 rrow: 62)
   leaf: 0x1c00af7 29362935 (1: nrow: 61 rrow: 61)
   leaf: 0x1c00af8 29362936 (2: nrow: 61 rrow: 61)
   leaf: 0x2802ad9 41954009 (3: nrow: 61 rrow: 61)
   leaf: 0x2802ada 41954010 (4: nrow: 61 rrow: 61)
   leaf: 0x2802adb 41954011 (5: nrow: 61 rrow: 61)
   leaf: 0x2802adc 41954012 (6: nrow: 61 rrow: 61)
   leaf: 0x2802add 41954013 (7: nrow: 61 rrow: 61)
   leaf: 0x2802ade 41954014 (8: nrow: 61 rrow: 61)
   leaf: 0x2802adf 41954015 (9: nrow: 61 rrow: 61)
   leaf: 0x2802ae0 41954016 (10: nrow: 61 rrow: 61)
   leaf: 0x2c0268a 46147210 (11: nrow: 61 rrow: 61)
   leaf: 0x2c0268b 46147211 (12: nrow: 61 rrow: 61)
   leaf: 0x2c0268c 46147212 (13: nrow: 61 rrow: 61)
   leaf: 0x2c0268d 46147213 (14: nrow: 61 rrow: 61)
   leaf: 0x2c0268e 46147214 (15: nrow: 22 rrow: 22)
----- end tree dump

To take a dump for specific index block, you need to 1) copy & paste the DBA, 2) convert the block address to file# and block#, 3) type the “alter system dump …” command. I really hate these kinds of boring procedures.

This is how I make my life simpler and easier with litte automized script.

UKJA@ukja116> 
UKJA@ukja116> select
  2  	prefix||
  3  	type ||
  4  	' max_rows=' || nrow ||', '||
  5  	'cur_rows=' || rrow ||', '||
  6  	'dump=alter system dump datafile ' ||
  7  			dbms_utility.data_block_address_file(to_dec(dba)) || ' block ' ||
  8  			dbms_utility.data_block_address_block(to_dec(dba))
  9  from (
 10  	select
 11  		regexp_substr(column_value, '^[[:space:]]+') as prefix,
 12  		regexp_substr(column_value, '(branch|leaf)') as type,
 13  		regexp_replace(regexp_substr(column_value, '(branch:|leaf:) [^ ]+'),
 14  							'(branch:|leaf:) 0x', '') as dba,
 15  		substr(regexp_substr(column_value, 'nrow: [[:digit:]]+'), 7) as nrow,
 16  		substr(regexp_substr(column_value, 'rrow: [[:digit:]]+'), 7) as rrow
 17  	from table(get_trace_file1)
 18  	where regexp_like(column_value, '(branch:|leaf:)')
 19  )
 20  ;

PREFIX||TYPE||'MAX_ROWS='||NROW||','||'CUR_ROWS='||RROW||','||'DUMP=ALTERSYSTEMD
--------------------------------------------------------------------------------
branch max_rows=17, cur_rows=, dump=alter system dump datafile 7 block 2804     
   leaf max_rows=62, cur_rows=62, dump=alter system dump datafile 7 block 2805  
   leaf max_rows=62, cur_rows=62, dump=alter system dump datafile 7 block 2806  
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 7 block 2807  
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 7 block 2808  
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10969
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10970
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10971
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10972
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10973
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10974
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10975
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 10 block 10976
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9866 
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9867 
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9868 
   leaf max_rows=61, cur_rows=61, dump=alter system dump datafile 11 block 9869 
   leaf max_rows=22, cur_rows=22, dump=alter system dump datafile 11 block 9870 

18 rows selected.

Elapsed: 00:00:00.06

Now I can just copy & paste the dump command to my SQL*Plus window and it’s done!

What I’ve done is making my life simple and beautiful. :)

Pure SQL version of ostakprof(from Tanel Poder)

Have you noticed following post from Tanel Poder? This is a very interesting and practical story even with the depth within it.

Here he introduces how you can do a simple but powerful function call profiling on the process without any serious 3rd party tool. ORADEBUG SHORT_STACK command is the core of the technique. His approach is to use VBscript(on the client-side) to parse the result of ORADEBUG SHORT_STACK.

I tried to implement the same functionality with 100% pure SQL which seems more portable and customizable to me. Following is the dirty example of it.

--------------------------------------------------------------------------------
-- @name: prof_callstack
-- @author: dion cho
-- @note: troubleshoot using oradebug callstack dump
-- @usage: @prof_callstack   
--------------------------------------------------------------------------------
define __SID = &1
define __SLEEP = &2
define __SAMPLE = &3

col spid new_value v_spid

select spid 
from v$process
where addr = (select paddr from v$session where sid = &__SID);

oradebug setospid &v_spid

@make_callstack &__SLEEP &__SAMPLE

@oradebug_callstack

/* -- execute following command before doing profiling.
drop table callstack_temp purge;

create global temporary table 
callstack_temp(seq number, idx number, fname varchar2(20));
*/

declare
	b_start		boolean := false;
	b_first		boolean := false;
	fname			varchar2(20);
	ftype			varchar2(10);
	seq				number := 1;
	idx				number := 1;
begin
	for r in (select * from table(ukja.get_trace_file1(&__SID))) loop
		if instr(r.column_value, 'Call Stack Trace') > 0 then
			b_start := true;
			b_first := true;
		end if;
		
		if instr(r.column_value, 'End of Call Stack Trace') >0 then
			seq := seq+1;
			idx := 1;
			b_start := false;
		end if;
		
		if b_start = true and b_first = false then
			fname := rtrim(substr(r.column_value, 1, 20));
			ftype := rtrim(substr(r.column_value, 22, 8));
			if ftype like 'CALL%' or ftype = 'VIRTUAL' then
				dbms_output.put_line(fname);
				insert into callstack_temp values(seq, idx, fname);
				idx := idx + 1;
			end if;
		end if;
		
		if b_start = true then 
			b_first := false;
		end if;
		
	end loop;
end;
/

spool callstack_result.txt
-- do some reporting
col sample# new_value sample_count
select 
	count(distinct seq) as sample#,
	count(*) as call#,
	max(idx) as max_depth
from callstack_temp
;

-- unique callstack and hit count
select 
	count(*) as hit#,
	100*(count(*)/&sample_count) as ratio,
	stack
from 
(
	select 
		seq,
		ltrim(sys_connect_by_path(fname,'->'),',') stack
	from (
		select 
			seq,
			fname,
			row_number() over (partition by seq order by idx desc) rn,
			count(*) over (partition by seq) cnt
		from callstack_temp
	)
	where level = cnt
	start with rn = 1
	connect by prior seq = seq and prior rn = rn-1
)
group by stack
order by 1 desc
;

spool off
@ed callstack_result.txt
delete from callstack_temp;

Here I use ORADEBUG DUMP CALLSTACK 1 command to store the callstacks to the server-side tracefile.

Following is how to make Oracle automatically invokes ORADEBUG DUMP CALLSTACK 1 command multiple times.

set heading off
set timing off
set feedback off
set verify off
set serveroutput on size 100000

spool oradebug_callstack.sql

begin
	for idx in 1 .. &2 loop
		dbms_output.put_line('oradebug dump callstack 1');
		dbms_output.put_line('exec dbms_lock.sleep(&1);');
	end loop;
end;
/

spool off
set heading on
set timing on
set feedback on
set verify on
set serveroutput off

For simple test case, I make a query which consumes good minutes to be hard-parsed.

set heading off
set timing off
set feedback off
set serveroutput on size 100000

var v_sql clob;

begin
  :v_sql := 'select count(*) from ';
  
  for r in (select t1.table_name
        from user_tables t1, user_tables t2 where rownum <= 500 and
            t1.table_name not like '%$%') loop
    :v_sql := :v_sql || r.table_name || ', ';
    
  end loop;
  
  :v_sql := :v_sql || ' dual where 1 = 0;';
  
end;
/

spool long_parse.sql
exec dbms_output.put_line(:v_sql);
spool off
set heading on
set timing on
set feedback on
set serveroutput off

While getting the session#1 invoke the long-parsing query, let me invoke the prof_callstack.sql as following.

-- session #1
UKJA@ukja102> @long_parse

  COUNT(*)
----------
         0

Elapsed: 00:03:06.53
-- session#2
connect /as sysdba
SYS@ukja10> @prof_callstack 140 0.01 100

Now I get the internal meaning of the long hard-parsing query like following.

   SAMPLE#      CALL#  MAX_DEPTH                                                
---------- ---------- ----------                                                
       100       4198         44                                                

1 row selected.

Elapsed: 00:00:00.06

FNAME                  COUNT(*)                                                 
-------------------- ----------                                                 
_opiodr+1099                200                                                 
7C80B680                    200                                                 
_apadrv+459                 100                                                 
_kksLoadChild+5883          100                                                 
_kglpim+264                 100                                                 
_kksParseCursor+143         100                                                 
_kkorrio+195                100                                                 
_ksdxfdmp+847               100                                                 
_ssthreadsrgruncall         100                                                 
_opimai_real+112            100                                                 
_apafdr+402                 100                                                 
_kpooprx+232                100                                                 
_kksfbc+7232                100                                                 
_apakkoqb+151               100                                                 
_opidrv+819                 100                                                 
_kglpin+1078                100                                                 
_kglobpn+1224               100                                                 
_kglobld+837                100                                                 
_rpiswu2+426                100                                                 
_kkoqbc+1689                100                                                 
_kkspsc0+2094               100                                                 
_kkslod+98                  100                                                
_sou2o+45                   100                                                 
_opitca+1445                100                                                 
_ksdxcb+1481                100                                                 
_opiino+1087                100                                                 
_kpoal8+775                 100                                                 
_opiosq0+1965               100                                                 
_apaqbd+383                 100                                                 
00000000                    100                                                 
_OracleOradebugThre         100                                                 
_ksedst_tracecb+55          100                                                 
_ttcpip+1273                100                                                 
_kkooqb+8292                100                                                 
_kxsGetRuntimeLock+         100                                                 
__PGOSF359__kksFull         100                                                 
_opimai+92                  100                                                 
_opitsk+1017                100                                                 
_OracleThreadStart@         100                                                 
_apafjo+161                  85                                                 
_apafjo+265                   5                                                 
_apafjo+358                   2                                                 
_apacjp+162                   1                                                 
_apafbp+491                   1                                                 
_apafjo+295                   1                                                 
_apafbr+168                   1                                                 
_apafbp+262                   1                                                 
_apafbp+156                   1                                                 

48 rows selected.

Elapsed: 00:00:00.14

       SEQ        IDX FNAME                                                     
---------- ---------- --------------------                                      
         1         42 7C80B680                                                  
         1         41 _OracleThreadStart@                                       
         1         40 _opimai+92                                                
         1         39 _opimai_real+112                                          
         1         38 _sou2o+45                                                 
         1         37 _opidrv+819                                               
         1         36 _opiodr+1099                                              
         1         35 _opiino+1087                                              
         1         34 _opitsk+1017                                              
         1         33 _ttcpip+1273                                              
         1         32 _opiodr+1099                                              
         1         31 _kpoal8+775                                               
         1         30 _kpooprx+232                                              
         1         29 _opiosq0+1965                                             
         1         28 _kksParseCursor+143                                       
         1         27 _kkspsc0+2094                                             
         1         26 _kksfbc+7232                                              
         1         25 _kxsGetRuntimeLock+                                       
         1         24 _kglpin+1078                                              
         1         23 _kglpim+264                                               
         1         22 _kglobpn+1224                                             
         1         21 _kglobld+837                                              
         1         20 _kkslod+98                                                
         1         19 _kksLoadChild+5883                                        
         1         18 _rpiswu2+426                                              
         1         17 __PGOSF359__kksFull                                       
         1         16 _opitca+1445                                              
         1         15 _apadrv+459                                               
         1         14 _apaqbd+383                                               
         1         13 _apakkoqb+151                                             
         1         12 _kkoqbc+1689                                              
         1         11 _kkooqb+8292                                              
         1         10 _kkorrio+195                                              
         1          9 _apafdr+402                                               
         1          8 _apafjo+161                                               
         1          7 00000000                                                  
         1          6 7C80B680                                                  
         1          5 _OracleOradebugThre                                       
         1          4 _ssthreadsrgruncall                                       
         1          3 _ksdxcb+1481                                              
         1          2 _ksdxfdmp+847                                             
         1          1 _ksedst_tracecb+55                                        

42 rows selected.

Elapsed: 00:00:00.14
old   3: 	100*(count(*)/&sample_count) as ratio,
new   3: 	100*(count(*)/       100) as ratio,

      HIT#      RATIO                                                           
---------- ----------                                                           
STACK                                                                           
--------------------------------------------------------------------------------
        85         85                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+161->00000000->7C80B680->_OracleOradebugThre->_ss
threadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55               
                                                                                
         7          7                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->00000000->7C80B680->_OracleOradebugThre->_ssthreadsrgrunc
all->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55                            
                                                                                
         2          2                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+358->00000000->7C80B680->_OracleOradebugThre->_ss
threadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55               
                                                                                
         2          2                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+265->00000000->7C80B680->_OracleOradebugThre->_ss
threadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55               
                                                                                
         1          1                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+265->_apafbp+262->00000000->7C80B680->_OracleOrad
ebugThre->_ssthreadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55  
                                                                                
         1          1                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+265->_apafbp+491->_apacjp+162->00000000->7C80B680
->_OracleOradebugThre->_ssthreadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst
_tracecb+55                                                                     
                                                                                
         1          1                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+265->_apafbp+156->_apafbr+168->00000000->7C80B680
->_OracleOradebugThre->_ssthreadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst
_tracecb+55                                                                     
                                                                                
         1          1                                                           
->7C80B680->_OracleThreadStart@->_opimai+92->_opimai_real+112->_sou2o+45->_opidr
v+819->_opiodr+1099->_opiino+1087->_opitsk+1017->_ttcpip+1273->_opiodr+1099->_kp
oal8+775->_kpooprx+232->_opiosq0+1965->_kksParseCursor+143->_kkspsc0+2094->_kksf
bc+7232->_kxsGetRuntimeLock+->_kglpin+1078->_kglpim+264->_kglobpn+1224->_kglobld
+837->_kkslod+98->_kksLoadChild+5883->_rpiswu2+426->__PGOSF359__kksFull->_opitca
+1445->_apadrv+459->_apaqbd+383->_apakkoqb+151->_kkoqbc+1689->_kkooqb+8292->_kko
rrio+195->_apafdr+402->_apafjo+295->00000000->7C80B680->_OracleOradebugThre->_ss
threadsrgruncall->_ksdxcb+1481->_ksdxfdmp+847->_ksedst_tracecb+55               
                                                                                

8 rows selected.

Elapsed: 00:00:06.95

Here you see that the most frequent functions to be called are “kko”, “kks”(compile) and “kgl”(library cache) related ones which strongly hints the possibility of the hard parse with many LCO being related.

Anyway, the insights given by Tanel Poder are always amazing and technically challenging.

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.

Simple and stupid example on troubleshooting using callstack

Look at this – the simplest query imagineable.

UKJA@ukja102> select * from dual;
...  <-- Hanged!!!

But it’s hanged!

Okay, it’s abnormal hang situation, so I look into the session.

SYS@ukja10> @session_list

  SID SERIAL# PROGRAM    EVENT                SQL_TEXT
----- ------- ---------- -------------------- ------------------------------
  146    6578 sqlplus.ex SQL*Net message from
              e           client
...

SYS@ukja10> exec print_table('select * from v$session where sid = 146');
SADDR                         : 2EB2FDFC
SID                           : 146
SERIAL#                       : 6578
AUDSID                        : 19288
PADDR                         : 2EA4F58C
USER#                         : 61
USERNAME                      : UKJA
COMMAND                       : 0
OWNERID                       : 2147483644
TADDR                         :
LOCKWAIT                      :
STATUS                        : INACTIVE
SERVER                        : DEDICATED
SCHEMA#                       : 61
SCHEMANAME                    : UKJA
OSUSER                        : UKJA\exem
PROCESS                       : 12172:10844
MACHINE                       : EX-EM.COM\UKJA
TERMINAL                      : UKJA
PROGRAM                       : sqlplus.exe
TYPE                          : USER
SQL_ADDRESS                   : 00
SQL_HASH_VALUE                : 0
SQL_ID                        :
SQL_CHILD_NUMBER              :
PREV_SQL_ADDR                 : 27DAB918
PREV_HASH_VALUE               : 96831227
PREV_SQL_ID                   : 7us1frh2wb1rv
PREV_CHILD_NUMBER             : 0
MODULE                        : SQL*Plus
MODULE_HASH                   : 3669949024
ACTION                        :
ACTION_HASH                   : 0
CLIENT_INFO                   :
FIXED_TABLE_SEQUENCE          : 114132657
ROW_WAIT_OBJ#                 : -1
ROW_WAIT_FILE#                : 0
ROW_WAIT_BLOCK#               : 0
ROW_WAIT_ROW#                 : 0
LOGON_TIME                    : 2009/06/11 13:16:42
LAST_CALL_ET                  : 79
PDML_ENABLED                  : NO
FAILOVER_TYPE                 : NONE
FAILOVER_METHOD               : NONE
FAILED_OVER                   : NO
RESOURCE_CONSUMER_GROUP       :
PDML_STATUS                   : DISABLED
PDDL_STATUS                   : ENABLED
PQ_STATUS                     : ENABLED
CURRENT_QUEUE_DURATION        : 0
CLIENT_IDENTIFIER             :
BLOCKING_SESSION_STATUS       : NO HOLDER
BLOCKING_INSTANCE             :
BLOCKING_SESSION              :
SEQ#                          : 29
EVENT#                        : 256
EVENT                         : SQL*Net message from client
P1TEXT                        : driver id
P1                            : 1413697536
P1RAW                         : 54435000
P2TEXT                        : #bytes
P2                            : 1
P2RAW                         : 00000001
P3TEXT                        :
P3                            : 0
P3RAW                         : 00
WAIT_CLASS_ID                 : 2723168908
WAIT_CLASS#                   : 6
WAIT_CLASS                    : Idle
WAIT_TIME                     : 0
SECONDS_IN_WAIT               : 79
STATE                         : WAITING
SERVICE_NAME                  : UKJA10
SQL_TRACE                     : DISABLED
SQL_TRACE_WAITS               : FALSE
SQL_TRACE_BINDS               : FALSE
-----------------

I really see nothing special. It is just in the idle status doing nothing. Now what else can I do?

Oracle provides pretty little feature called short_stack, which prints the minimal callstack information.

SYS@ukja10> oradebug setospid 11744
Oracle pid: 23, Windows thread id: 11744, image: ORACLE.EXE (SHAD)              

SYS@ukja10> oradebug short_stack
_ksdxfstk+14<-_ksdxcb+1481<-_ksdxsus+1037<-_ksdxffrz+50<-_ksdxcb+1481
<-_ssthreadsrgruncallback+428<-_OracleOradebugThreadStart@4+795<-7C80B680
<-00000000<-719857C4<-719E4376<-62985408<-62983266<-60A08BD8<-609CCBB8
<-609AF9CD<-609ACF09<-6097E2C7<-__PGOSF126__opikndf2+781<-_opitsk+540
<-_opiino+1087<-_opiodr+1099<-_opidrv+819<-_sou2o+45<-_opimai_real+112
<-_opimai+92<-_OracleThreadStart@4+708<-7C80B680

Do you see any meaningful information? What makes me curios is following part.

... <-_ksdxsus+1037<-_ksdxffrz+50<- ... 

My interpretation. Flash freeze(ffrz) was invoked and the session was suspended(sus). Resuming the instance from flash freeze would prove my suspicion.

SYS@ukja10> oradebug ffresumeinst
Statement processed.

...
UKJA@ukja102> select * from dual;

D
-
X

Elapsed: 00:09:30.14

If you don’t like the simplicity of short_stack, errorstack would show more information.

SYS@ukja10> oradebug dump errorstack 2
Statement processed.
SYS@ukja10> oradebug tracefile_name
c:\oracle\admin\ukja10\udump\ukja10_ora_11744.trc

----- Call Stack Trace -----
calling              call     entry                argument values in hex      
location             type     point                (? means dubious value)     
-------------------- -------- -------------------- ----------------------------
_ksedst+38           CALLrel  _ksedst1+0           1 1
_ksedmp+898          CALLrel  _ksedst+0            1
_ksdxfdmp+847        CALLreg  00000000             2
_ksdxcb+1481         CALLreg  00000000             D68F43C 11 3 D68F39C D68F3EC
_ksdxsus+1037        CALLrel  _ksdxcb+0            1
_ksdxffrz+50         CALLrel  _ksdxsus+0           1
_ksdxcb+1481         CALLreg  00000000             D68FB20 7 1 D68FA80 D68FAD0
_ssthreadsrgruncall  CALLrel  _ksdxcb+0            1
back+428                                           
_OracleOradebugThre  CALLrel  _ssthreadsrgruncall  D68FF84
adStart@4+795                 back+0               
7C80B680             CALLreg  00000000             
00000000             VIRTUAL  7C93EB94             
719857C4             CALLrel  71983C6B             
719E4376             CALLreg  00000000             
62985408             CALL???  00000000             
62983266             CALLrel  6298530C             F90 AAD779A 810 0
60A08BD8             CALLreg  00000000             AAAF98C AAD779A AAAFB20 0 0
609CCBB8             CALLrel  60A07EF0             AA7FAF0 B83E01C A5FED30
609AF9CD             CALLrel  609CCAF0             AA7FAF0 A5FED30
609ACF09             CALLrel  609ACF48             A5FEC14 55 A5FED30 0 B83E2AC
                                                   0 3
6097E2C7             CALLrel  609ACEF4             A5FEC14 A5FED30 B83E2AC 0
__PGOSF126__opikndf  CALLreg  00000000             
2+781                                              
_opitsk+540          CALLreg  00000000             
_opiino+1087         CALLrel  _opitsk+0            0 0
_opiodr+1099         CALLreg  00000000             3C 4 B83FC8C
_opidrv+819          CALLrel  _opiodr+0            3C 4 B83FC8C 0
_sou2o+45            CALLrel  _opidrv+0            3C 4 B83FC8C
_opimai_real+112     CALLrel  _sou2o+0             B83FC80 3C 4 B83FC8C
_opimai+92           CALLrel  _opimai_real+0       2 B83FCB8
_OracleThreadStart@  CALLrel  _opimai+0            
4+708                                              
7C80B680             CALLreg  00000000             

Very stupid demo, isn’t it? But is a streotypical case which shows the usefullness and uniqueness of callstack analysis.

Tanel Poder shows his uniquesses and real-life approach on callstack analysis (short_stack) here, and you might like to see see following metalink notes which accidentally contain good information on callstack analysis.

• 175982.1: ORA-600 Lookup Error Categories
• 453521.1: ORA-04031 “KSFQ Buffers” ksmlgpalloc
• 558671.1: Getting ORA-01461 while INSERT INTO WWV_THINGS

Troubleshooting PGA leak with PGA heap dump

Jonathan Lewis shared interesting and practical experience on PGA memory leak here. Here he mentions on the memory leaks by forall batch insert bug.

This is actually a very interesting case where troubleshooting using PGA heap dump seems to be one of the feasible ways to analyze the problem(as Tanel responded to Jonathan’s request). I would just like to show and discuss how I would investigate this problem and find the solution using PGA heap dump.

This is the simple simulation made by Jonathan Lewis which makes memory leak on PGA.

define m_string_length = 20

drop table t1 purge;
create table t1(v1 varchar2( &m_string_length ));

create or replace procedure proc1 (
	i_rowcount	in number	default 1000000,
	i_bulk_pause	in number	default 0,
	i_forall_pause	in number	default 0,
	i_free_pause	in number	default 0
)
as
	type w_type is table of varchar2( &m_string_length );
	w_list 		w_type := w_type();
	w_free		w_type := w_type();
begin
	for i in 1..i_rowcount loop
		w_list.extend;
		w_list(i) := rpad('x', &m_string_length );
	end loop;

	dbms_lock.sleep(i_bulk_pause);

	forall i in 1..w_list.count
	  insert into t1 values(w_list(i));

	dbms_lock.sleep(i_forall_pause);
	commit;
	w_list := w_free;
	dbms_session.free_unused_user_memory;

	dbms_lock.sleep(i_free_pause);
end;
/

Let me monitor the session memory usage while making multiple calls on this procedure.

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

SYS@ukja10> select
  2     name, value
  3  from
  4     v$sesstat ss,
  5     v$statname sn
  6  where
  7     sn.name like '%ga memory%'
  8  and        ss.statistic# = sn.statistic#
  9  and        ss.sid = 149
 10  ;

NAME                                      VALUE
------------------------------ ----------------
session uga memory                  498,942,840
session uga memory max              500,053,908
session pga memory                  599,907,924
session pga memory max              675,602,004

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME                                      VALUE
------------------------------ ----------------
session uga memory                  695,429,288
session uga memory max              695,429,288
session pga memory                  904,191,572
session pga memory max              904,257,108

UKJA@ukja102> exec proc1;

PL/SQL procedure successfully completed.

NAME                                      VALUE
------------------------------ ----------------
session uga memory                  840,565,088
session uga memory max              840,565,088
session pga memory                1,077,861,972
session pga memory max            1,077,861,972

Very serious memory leak! Isn’t it? 1) Oracle does not release memory even after the call has completed and 2) Oracle does not 100% reuse the memory.

The problem is that it’s almost impossible to identify on which objects we’re losing memory. As far as I know, Oracle does not expose the PGA memory structure by v$ views nor x$views. (Jonathan Lewis pointed me to the X$KSMPP view)

So what else can we do? PGA heap dump is the only thing left to us.

oradebug setospid 6760
oradebug dump heapdump 1

The heap dump file is quite easy to interpret, but it is sometimes too long to interpret with our eyes. So I built heap_analyze.sql to retrieve summarized report from raw dump file. Here is the result for the PGA heap dump.

UKJA@ukja102> @heap_analyze heap_dump_1.trc
UKJA@ukja102> set echo off

     TSIZE
----------
 598488868

Elapsed: 00:00:00.57

ATYPE                         CSIZE  HEAP_SIZE  RATIO
------------------------ ---------- ---------- ------
freeable                  498650144  598488868  83.32
perm                         181928  598488868    .03
recreate                      87180  598488868    .01
free                       99569616  598488868  16.64

Elapsed: 00:00:00.75

CTYPE                               CSIZE  HEAP_SIZE  RATIO
------------------------------ ---------- ---------- ------
Alloc environm                       4144  598488868    .00
Fixed Uga                           20572  598488868    .00
KFIO PGA struct                        72  598488868    .00
KFK PGA                               260  598488868    .00
KJZT context                           60  598488868    .00
KSFQ heap                            3928  598488868    .00
KSFQ heap descr                        92  598488868    .00
PLS cca hp desc                       212  598488868    .00
PLS non-lib hp                      18560  598488868    .00
callheap                             2144  598488868    .00
external name                          24  598488868    .00
joxp heap                            2000  598488868    .00
kews sqlstat st                      1292  598488868    .00
kgh stack                           17012  598488868    .00
kjztprq struct                       2068  598488868    .00
koh-kghu call h                      1328  598488868    .00
kopolal dvoid                        2524  598488868    .00
kpuinit env han                      1584  598488868    .00
kzsna:login nam                        24  598488868    .00
ldm context                         12712  598488868    .00
perm                               181928  598488868    .03
qmtmInit                            13980  598488868    .00
session heap                    498632732  598488868  83.32
free                             99569616  598488868  16.64

24 rows selected.

Elapsed: 00:00:00.65

DS                        CSIZE  HEAP_SIZE  RATIO
-------------------- ---------- ---------- ------
083BD9CC                  10320  598488868    .00
08563470                  12436  598488868    .00
085A7600              498567256  598488868  83.30
free                   99898856  598488868  16.69

Elapsed: 00:00:00.68

Hm… nothing special except the fact that the subheap(085A7600) occupies 83.3% of the PGA heap. So I do subheap dump for that heap address.

oradebug dump heapdump_addr 1 0xa067600

UKJA@ukja102> @heap_analyze heap_subdump_1.trc
UKJA@ukja102> set echo off

     TSIZE
----------
 498561776

Elapsed: 00:00:00.40

ATYPE                         CSIZE  HEAP_SIZE  RATIO
------------------------ ---------- ---------- ------
freeable                  488817960  498561776  98.05
perm                          54896  498561776    .01
recreate                      14852  498561776    .00
free                        9674068  498561776   1.94

Elapsed: 00:00:00.56

CTYPE                               CSIZE  HEAP_SIZE  RATIO
------------------------------ ---------- ---------- ------
PLS cca hp desc                       400  498561776    .00
PLS non-lib hp                  488740608  498561776  98.03
Session NCHAR l                       552  498561776    .00
kgict                                  40  498561776    .00
kgicttab                               44  498561776    .00
kgicu                                  92  498561776    .00
kgiob                                1928  498561776    .00
kgiobdtb                              192  498561776    .00
kgsc ht segs                         5720  498561776    .00
koddcal dvoid                          24  498561776    .00
kodmcon kodmc                          64  498561776    .00
kodpai image                         1036  498561776    .00
koh-kghu sessi                      15888  498561776    .00
koh-kghu sessio                     14252  498561776    .00
kokahin kgglk                         140  498561776    .00
kokl lob id has                      1036  498561776    .00
kokl transactio                       268  498561776    .00
koklug hlctx in                        24  498561776    .00
koklug hxctx in                        24  498561776    .00
kpuinit env han                      1584  498561776    .00
kqlpWrntoStr:st                       112  498561776    .00
ksulu : ksulueo                        40  498561776    .00
kwqaalag                               92  498561776    .00
kwqb context me                        92  498561776    .00
kwqica hash tab                        92  498561776    .00
kwqidwh memory                         92  498561776    .00
kwqmahal                               92  498561776    .00
kxs-heap-d                           1036  498561776    .00
kxs-heap-p                           4148  498561776    .00
kxs-krole                             780  498561776    .00
kxsFrame4kPage                      28840  498561776    .01
kxsc: kkspbd0                         968  498561776    .00
kxsc: kkspsc0                        7756  498561776    .00
kzctxhugi1                           4108  498561776    .00
kzsrcrdi                               60  498561776    .00
perm                                54896  498561776    .01
session languag                       552  498561776    .00
system trigger                         36  498561776    .00
free                              9674068  498561776   1.94

39 rows selected.

Elapsed: 00:00:00.51

DS                        CSIZE  HEAP_SIZE  RATIO
-------------------- ---------- ---------- ------
08B3608C                   2076  498561776    .00
08B3EAAC              488738512  498561776  98.03
08B578F4                   2080  498561776    .00
08B5A114                   2080  498561776    .00
0FD400B0                   2080  498561776    .00
free                    9814948  498561776   1.97

6 rows selected.

Elapsed: 00:00:00.54

Well, again, another subheap(08B3EAAC) does occupy 98% of the space.

oradebug dump heapdump_addr 1 0x0A08EAAC

UKJA@ukja102> @heap_analyze heap_subdump_2.trc
UKJA@ukja102> set echo off

     TSIZE
----------
 488662552

Elapsed: 00:00:02.50

ATYPE                         CSIZE  HEAP_SIZE  RATIO
------------------------ ---------- ---------- ------
freeable                    4750540  488662552    .97
perm                            144  488662552    .00
free                      483911868  488662552  99.03

Elapsed: 00:00:03.37

CTYPE                               CSIZE  HEAP_SIZE  RATIO
------------------------------ ---------- ---------- ------
DPAGE                             4750096  488662552    .97
peihstdep                             260  488662552    .00
perm                                  144  488662552    .00
pl_iot_alloc                           92  488662552    .00
pl_lut_alloc                           92  488662552    .00
free                            483911868  488662552  99.03

6 rows selected.

Elapsed: 00:00:03.20

no rows selected

Elapsed: 00:00:02.42

Okay, now I see the problem. The deepest subheap occupies 466M(488662552) but, the 99% is FREE! Oracle does not release the free space even after the call has completed and even denies to reuse it 100%.

This certainly looks like a bug and I search metalink using these keywords.

And this links me to the bug 5866410 which is described as the free chunks problem with FORALL insertion.

Bulk insert in PLSQL can consume a large amount of PGA memory which can lead to ORA-4030 errors.

A heapdump will show lot of free memory in the free lists which is not used but instead fresh allocations are made.

Well, above process might seem natural and easy for who read this post, but following things make the process somewhat difficult to follow

• The heap dump file is sometimes quite long and hard to analyze without proper analysis tool.
• Heap has hierarchical structure as shown above. It sometimes is composed of multiple subheaps and subheap itself could be composed of multiple subheapds.
• The object names are sometimes hard to decode.

But I believe that above test case proves the usefulness of the PGA heap dump analysis and it would turn out to be very successful under certain circumstances.

Releasing library cache pin

Interesting question from one of my customers.

One of the sessions was killed in the process of debugging a procedure with Toad. But the library cache pin continued to be hold and couldn’t recompile or modify the procedure.

Even “shutdow immediate” got blocked, so the only one I could do was “shutdown abort”.

Why is this happening and how do I force the release of the library cache pin.

The answer is simple and clear.

When the session got termininated unsuccessfully hodling library cache pin, there is a chance that library cache pin is still hold. Killing the corresponding perfectly would release the library cache pin.

What does this mean? I’ve built up very simple test case to prove my viewpoint.

-- Session #1
-- Create procedure PROC1 which sleeps 1000 sec
UKJA@ukja102> create or replace procedure proc1
  2  is
  3  begin
  4     dbms_lock.sleep(1000);
  5
  6  end;
  7  /

Procedure created.


-- Execute procedure proc1. It would be blocked due to the TX lock contention.
-- And kill the session simply with Ctrl+C
-- The problem is that killing session with Ctrl+C(especially on Windows)
-- does not actually kill the corresponding process.
UKJA@ukja102> exec proc1;
^C
C:\Documents and Settings\exem>sqlplus ukja/ukja@ukja102

-- Session #2
-- Okay, now the session #1 got killed. 
-- But how about the procedure itself? Is it terminated or alive?
SYS@ukja10> @lock_internal 144 PROC1

       SID TY handle            mod        req NAME
---------- -- ---------- ---------- ---------- ------------------------------
       142 LK 2A3557A8            1          0 PROC1
       142 LN 2A3557A8            2          0 PROC1  <-- Here!

SYS@ukja10> @lco 2A3557A8 %

KGLHDADR                      : 2A3557A8
KGLNAOBJ                      : PROC1
TYPE                          : Parent
LOCK_HOLDER                   : 142
KGLLKMOD                      : 1
KGLLKREQ                      : 0
PIN_HOLDER                    : 142
KGLPNMOD                      : 2    <-- Here
KGLPNREQ                      : 0
-----------------

PL/SQL procedure successfully completed.

-- The session is alive holding the shared library cache pin on the PROC1.
-- No change on the procedure is allowed. Ouch!
-- It would be alive forever without proper cleanout for the corresponding resources.

-- Session #2
-- Kill the corresponding process(thread) using orakill
-- On unix, kill command
SYS@ukja10> ho orakill UKJA10 5288

Kill of thread id 5288 in instance UKJA10 successfully signalled.

-- After a couple of seconds, PMON would cleanout the resource of the killed process
-- And the library cache pin got released. 
UKJA@ukja102> @lco 2A3557A8 %
KGLHDADR                      : 2A3557A8
KGLNAOBJ                      : PROC1
TYPE                          : Parent
LOCK_HOLDER                   :
KGLLKMOD                      :
KGLLKREQ                      :
PIN_HOLDER                    :
KGLPNMOD                      :
KGLPNREQ                      :
-----------------

PL/SQL procedure successfully completed.

I hope that this simple and stupid test case clearly explains what I’m trying to say.
(lock_internal.sql is here and lco.sql is here)

I’m not sure why Toad did not release the libary cache pin in the above question. Debugging functionality given by Toad(and Oracle!) might have some critical sections that hold library cache pin on the procedure(which would be quite natural with debugging function) and fail to release it without proper termination process.

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.