Posts Tagged ‘callstack’
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.
Dion Cho - Oracle Performance Storyteller 