Posts Tagged ‘trace fiile’
Another way to use trace file
I believe that many of you sometimes have strong need for customized trace analysis.
For instance, see following wait records of 10046 trace file.
... WAIT #11: nam='buffer busy waits' ela= 4 file#=17 block#=2313 class#=8 obj#=81140 tim=520863116874 WAIT #11: nam='buffer busy waits' ela= 5456 file#=17 block#=2624 class#=1 obj#=81140 tim=520864249735 WAIT #11: nam='buffer busy waits' ela= 6 file#=17 block#=2569 class#=8 obj#=81140 tim=520864249933 ...
What I want is to sort the buffer busy waits events by the class# like this:
CLASS# CNT ELAPSED ---------- ---------- ------- 8 1456 3.01 1 420 1.54 4 5 .00 35 2 .00 77 1 .00
But traditional tkprof has no such things. So what can I do? Hire developer? Do some excelling?
Nope. My approach is totally 100% SQL based, which is quite natural and easy for me. :) Most of all, it’s totally free. :)
Let’s see how I do it.
1. Create directory and array
-- create directory and varchar2 array col value new_value user_dump_directory; select value from v$parameter where name = 'user_dump_dest'; create or replace directory user_dump_dir as '&user_dump_directory'; create or replace type varchar2_array as table of varchar2(4000); /
2. Create pipelined table function with utl_file package. If you’re not familiar with pipelined table function, visit here.
-- create get_trace_file1 function
create or replace function get_trace_file1(s_id number default userenv('sid'))
return varchar2_array
pipelined
as
v_handle utl_file.file_type;
v_filename varchar2(2000);
v_line varchar2(4000);
begin
-- get exact file_name
select i.value||'_ora_'||p.spid||'.trc' into v_filename
from v$process p, v$session s,
(select value from v$parameter where name = 'instance_name') i
where p.addr = s.paddr
and s.sid = s_id
;
v_handle := utl_file.fopen('USER_DUMP_DIR', v_filename, 'R', 32767);
loop
begin
utl_file.get_line(v_handle, v_line);
exception when no_data_found then
exit;
end;
pipe row(v_line);
end loop;
return;
end;
/
-- create get_trace_file2 function
create or replace function get_trace_file2(file_name in varchar2)
return varchar2_array
pipelined
as
v_handle utl_file.file_type;
v_line varchar2(20000);
begin
v_handle := utl_file.fopen('USER_DUMP_DIR', file_name, 'R', 32767);
loop
begin
utl_file.get_line(v_handle, v_line);
exception when no_data_found then
exit;
end;
pipe row(v_line);
end loop;
return;
end;
/
3. Good. Let’s play with it
alter session set events '10046 trace name context forever, level 8'; select count(*) from t1; alter session set events '10046 trace name context off'; select * from table(get_trace_file1); Dump file c:\oracle\admin\ukja10\udump\ukja10_ora_2820.trc Thu Mar 19 15:10:10 2009 ORACLE V10.2.0.1.0 - Production vsnsta=0 vsnsql=14 vsnxtr=3 Oracle Database 10g Enterprise Edition Release 10.2.0.1.0 - Production With the Partitioning, OLAP and Data Mining options Windows XP Version V5.1 Service Pack 2 CPU : 2 - type 586 Process Affinity : 0x00000000 Memory (Avail/Total): Ph:1481M/3070M, Ph+PgF:3140M/4960M, VA:1359M/2047M Instance name: ukja10 Redo thread mounted by this instance: 1 Oracle process number: 16 Windows thread id: 2820, image: ORACLE.EXE (SHAD) *** ACTION NAME:() 2009-03-19 15:10:10.109 *** MODULE NAME:(SQL*Plus) 2009-03-19 15:10:10.109 *** SERVICE NAME:(UKJA10) 2009-03-19 15:10:10.109 *** SESSION ID:(157.1205) 2009-03-19 15:10:10.109 ===================== PARSING IN CURSOR #1 len=68 dep=0 uid=61 oct=42 lid=61 tim=172367882897 hv=740818757 ad='27e12b14' alter session set events '10046 trace name context forever, level 8' END OF STMT ...
4. Very cool. Now I sort the buffer busy waits event by class# like this.(Actually, not that elegant query)
col class# format a10
col elapsed format 99.99
with t as (
select /*+ materialize */
column_value as line,
instr(column_value, 'ela=') ei,
instr(column_value, 'file#=') fi,
instr(column_value, 'block#=') bi,
instr(column_value, 'class#=') ci,
instr(column_value, 'obj#=') oi,
instr(column_value, 'tim=') ti
from table(get_trace_file2('trc_1.trc'))
--from table(get_trace_file2('trc_2.trc'))
where
instr(column_value, 'WAIT #2: nam=''buffer busy waits''') > 0
--instr(column_value, 'WAIT #11: nam=''buffer busy waits''') > 0
)
select
class#
, count(1) as cnt
, sum(elapsed)/1000000 as elapsed
from
(
select
substr(line, ei+4, fi-ei-4) as elapsed,
substr(line, fi+6, bi-fi-6) as file#,
substr(line, bi+7, ci-bi-7) as block#,
substr(line, ci+7, oi-ci-7) as class#,
substr(line, oi+5, ti-oi-5) as obj#,
substr(line, ti+4) as tim
from
t
) x
group by
class#
order by
2 desc, 3 desc
;
What I’m actually doing is:
- trc_1.trc file contains the 10046 trace result with 40K extent size in ASSM.
- trc_2.trc file contains the 10046 trace result with 10M extent size in ASSM.
- 10 concurrent sessions insert into the table with 10046 trace enabled.
- I’d like to analyze how extent size affects the pattern of buffer contention.
Here is the result.
-- when extent size is 40K CLASS# CNT ELAPSED ---------- ---------- ------- 8 285 1.40 1 215 4.64 4 42 .01 9 2 .00 19 1 .00 33 1 .00 -- when extent size is 10M CLASS# CNT ELAPSED ---------- ---------- ------- 8 1456 3.01 1 420 1.54 4 5 .00 35 2 .00 77 1 .00
See the diffference. With big extent size, we have major buffer contention on 1st level bitmap block(8). With (too) smaller extent size, the major contention is on data block(1).
Hm… What does this mean? Well, it’s not the topic. :)
My point here is that Oracle has more funtionality than you imagine. Simple tricks with pipelined table function and utl_file package made it possible for me to analyze the whole new pattern of wait events.
PS) Instead of pipelined table function, the external table is also feasible. But I believe that the pipeline table function version is far more elegant.
