Archive for the ‘Troubleshooting’ Category
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.
