Dion Cho – Oracle Performance Storyteller

We are natural born scientists

Pure SQL version of ostakprof(from Tanel Poder)

with 8 comments

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.





About these ads

Written by Dion Cho

June 18, 2009 at 3:10 am

Posted in Troubleshooting

Tagged with , ,

8 Responses

Subscribe to comments with RSS.

  1. Hi Dion,

    Very interesting way and also we are only depends on oracle.

    Taral Desai

    June 18, 2009 at 2:56 pm

  2. [...] Dion Cho – Pure SQL version of ostakprof(from Tanel Poder) [...]

  3. Hi Dion,

    What is ukja.get_trace_file1 ?

    Taral Desai

    June 23, 2009 at 3:35 pm

  4. Hi Dion,

    Can you please put the get_trace_file1 function definition. Do you just get the tracefile name with that function ?

    coskan

    June 23, 2009 at 4:45 pm

  5. @Coskan.

    It’s pipelined table function to retrieve trace file line by line.

    http://dioncho.wordpress.com/2009/03/19/another-way-to-use-trace-file/

    Dion Cho

    June 23, 2009 at 11:25 pm

  6. Hi Dion,

    I think this query is not working
    select * from (
    select fname, count(*)
    from callstack_temp
    group by fname
    order by 2 desc
    ) where rownum ‘),’,’) 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
    ;

    Taral Desai

    June 24, 2009 at 3:52 am

  7. @Tarel.

    It’s fixed. It was(and is always) the problem of < and > character.

    Dion Cho

    June 24, 2009 at 3:57 am


Leave a Reply

Fill in your details below or click an icon to log in:

WordPress.com Logo

You are commenting using your WordPress.com account. Log Out / Change )

Twitter picture

You are commenting using your Twitter account. Log Out / Change )

Facebook photo

You are commenting using your Facebook account. Log Out / Change )

Google+ photo

You are commenting using your Google+ account. Log Out / Change )

Connecting to %s

Follow

Get every new post delivered to your Inbox.

Join 59 other followers

%d bloggers like this: