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:

1. trc_1.trc file contains the 10046 trace result with 40K extent size in ASSM.
2. trc_2.trc file contains the 10046 trace result with 10M extent size in ASSM.
3. 10 concurrent sessions insert into the table with 10046 trace enabled.
4. 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.